refactor(logging): add a logging abstraction and move the job logger onto it (#1295)

Add `act/common/logging`: a printf-style `Logger` on a slog-shaped `Handler`, with a logrus-backed handler as the only backend, plus a `logtest` handler for tests. Move the job logger onto it: `common.Logger` returns `*logging.Logger`, the job log formatters and the `Reporter` hook become handlers, and composite step IDs travel in the context. Logging is tightly coupled to logrus types (hooks, formatters, `Entry.Data`). Going through our own interface first lets the remaining call sites move over with unchanged behavior, and lets the backend be swapped for `log/slog` in one place afterwards. The global process logger and its masking formatter stay on logrus for now. Assisted-by: Codet Co-authored-by: bircni <[email protected]> Reviewed-on: https://gitea.com/gitea/runner/pulls/1295 Reviewed-by: bircni <[email protected]>
2026-11-08 00:00:28 +00:00 · 2026-10-11 23:26:00 +00:00
1 parent ad9eeb668a
commit de961b91eb
@@ -0,0 +1,32 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package logging
+
+import "github.com/sirupsen/logrus"
+
+var std = New(NewLogrusHandler(logrus.StandardLogger()))
+
+// Default returns the process-wide Logger.
+func Default() *Logger { return std }
+
+// SetLevel sets the minimum level of the process-wide Logger.
+func SetLevel(level Level) { logrus.SetLevel(toLogrusLevel(level)) }
+
+// GetLevel returns the minimum level of the process-wide Logger.
+func GetLevel() Level { return fromLogrusLevel(logrus.GetLevel()) }
+
+func Enabled(level Level) bool { return std.Enabled(level) }
+
+func With(args ...any) *Logger          { return std.With(args...) }
+func WithError(err error) *Logger       { return std.WithError(err) }
+func Tracef(format string, args ...any) { std.logf(LevelTrace, format, args) }
+func Debugf(format string, args ...any) { std.logf(LevelDebug, format, args) }
+func Infof(format string, args ...any)  { std.logf(LevelInfo, format, args) }
+func Warnf(format string, args ...any)  { std.logf(LevelWarn, format, args) }
+func Errorf(format string, args ...any) { std.logf(LevelError, format, args) }
+func Trace(args ...any)                 { std.log(LevelTrace, args) }
+func Debug(args ...any)                 { std.log(LevelDebug, args) }
+func Info(args ...any)                  { std.log(LevelInfo, args) }
+func Warn(args ...any)                  { std.log(LevelWarn, args) }
+func Error(args ...any)                 { std.log(LevelError, args) }
@@ -0,0 +1,114 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package logging
+
+import (
+	"context"
+	"errors"
+	"slices"
+	"time"
+)
+
+// Attr is a structured key/value pair attached to a log record.
+type Attr struct {
+	Key   string
+	Value any
+}
+
+// Record is one log event. Attrs holds the call-site attributes only, the ones added with
+// Logger.With are accumulated by the Handler.
+type Record struct {
+	Time    time.Time
+	Level   Level
+	Message string
+	PC      uintptr // program counter of the logging call, 0 if unknown
+	Attrs   []Attr
+}
+
+// Attr returns the value of the last attribute named key.
+func (r Record) Attr(key string) (any, bool) {
+	for _, a := range slices.Backward(r.Attrs) {
+		if a.Key == key {
+			return a.Value, true
+		}
+	}
+	return nil, false
+}
+
+// Handler consumes records, and is shaped like slog.Handler so that a slog backend can replace
+// the current one without touching callers. Handle must not modify the Attrs slice it is given.
+type Handler interface {
+	Enabled(ctx context.Context, level Level) bool
+	Handle(ctx context.Context, r Record) error
+	// WithAttrs returns a Handler that adds attrs to every record it handles.
+	WithAttrs(attrs []Attr) Handler
+}
+
+type multiHandler []Handler
+
+// NewMultiHandler fans every record out to all handlers that have its level enabled.
+func NewMultiHandler(handlers ...Handler) Handler {
+	return multiHandler(handlers)
+}
+
+func (m multiHandler) Enabled(ctx context.Context, level Level) bool {
+	for _, h := range m {
+		if h.Enabled(ctx, level) {
+			return true
+		}
+	}
+	return false
+}
+
+func (m multiHandler) Handle(ctx context.Context, r Record) error {
+	var errs []error
+	for _, h := range m {
+		if h.Enabled(ctx, r.Level) {
+			errs = append(errs, h.Handle(ctx, r))
+		}
+	}
+	return errors.Join(errs...)
+}
+
+func (m multiHandler) WithAttrs(attrs []Attr) Handler {
+	out := make(multiHandler, len(m))
+	for i, h := range m {
+		out[i] = h.WithAttrs(attrs)
+	}
+	return out
+}
+
+type discardHandler struct{}
+
+// DiscardHandler drops every record.
+var DiscardHandler Handler = discardHandler{}
+
+func (discardHandler) Enabled(context.Context, Level) bool  { return false }
+func (discardHandler) Handle(context.Context, Record) error { return nil }
+func (d discardHandler) WithAttrs([]Attr) Handler           { return d }
+
+type levelHandler struct {
+	h        Handler
+	minLevel Level
+}
+
+// NewLevelHandler passes only records at or above minLevel on to h.
+func NewLevelHandler(h Handler, minLevel Level) Handler {
+	return levelHandler{h: h, minLevel: minLevel}
+}
+
+func (l levelHandler) Enabled(ctx context.Context, level Level) bool {
+	return level >= l.minLevel && l.h.Enabled(ctx, level)
+}
+
+func (l levelHandler) Handle(ctx context.Context, r Record) error {
+	if r.Level < l.minLevel {
+		return nil
+	}
+	return l.h.Handle(ctx, r)
+}
+
+func (l levelHandler) WithAttrs(attrs []Attr) Handler {
+	return levelHandler{h: l.h.WithAttrs(attrs), minLevel: l.minLevel}
+}
@@ -0,0 +1,53 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package logging
+
+import (
+	"fmt"
+	"strings"
+)
+
+// Level is a log severity. The values match log/slog, with Trace added below Debug.
+type Level int
+
+const (
+	LevelTrace Level = -8
+	LevelDebug Level = -4
+	LevelInfo  Level = 0
+	LevelWarn  Level = 4
+	LevelError Level = 8
+)
+
+func (l Level) String() string {
+	switch {
+	case l <= LevelTrace:
+		return "trace"
+	case l <= LevelDebug:
+		return "debug"
+	case l <= LevelInfo:
+		return "info"
+	case l <= LevelWarn:
+		return "warn"
+	default:
+		return "error"
+	}
+}
+
+// ParseLevel accepts every name logrus does. "fatal" and "panic" map to LevelError because
+// the Logger has no level above it.
+func ParseLevel(s string) (Level, error) {
+	switch strings.ToLower(s) {
+	case "trace":
+		return LevelTrace, nil
+	case "debug":
+		return LevelDebug, nil
+	case "info":
+		return LevelInfo, nil
+	case "warn", "warning":
+		return LevelWarn, nil
+	case "error", "fatal", "panic":
+		return LevelError, nil
+	}
+	return LevelInfo, fmt.Errorf("not a valid log level: %q", s)
+}
@@ -0,0 +1,106 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package logging
+
+import (
+	"context"
+	"fmt"
+	"runtime"
+	"time"
+)
+
+const badKey = "!BADKEY"
+
+// Logger writes printf-style messages with structured attributes to a Handler.
+type Logger struct {
+	h   Handler
+	ctx context.Context
+}
+
+func New(h Handler) *Logger {
+	return &Logger{h: h, ctx: context.Background()}
+}
+
+// With returns a Logger that adds the key/value pairs to every record, like slog.Logger.With.
+func (l *Logger) With(args ...any) *Logger {
+	if len(args) == 0 {
+		return l
+	}
+	return &Logger{h: l.h.WithAttrs(argsToAttrs(args)), ctx: l.ctx}
+}
+
+func (l *Logger) WithError(err error) *Logger {
+	return l.With("error", err)
+}
+
+// WithContext returns a Logger that passes ctx to its Handler.
+func (l *Logger) WithContext(ctx context.Context) *Logger {
+	return &Logger{h: l.h, ctx: ctx}
+}
+
+func (l *Logger) Enabled(level Level) bool {
+	return l.h.Enabled(l.ctx, level)
+}
+
+func (l *Logger) Tracef(format string, args ...any) { l.logf(LevelTrace, format, args) }
+func (l *Logger) Debugf(format string, args ...any) { l.logf(LevelDebug, format, args) }
+func (l *Logger) Infof(format string, args ...any)  { l.logf(LevelInfo, format, args) }
+func (l *Logger) Warnf(format string, args ...any)  { l.logf(LevelWarn, format, args) }
+func (l *Logger) Errorf(format string, args ...any) { l.logf(LevelError, format, args) }
+
+// Trace and the methods below format their arguments like fmt.Sprint.
+func (l *Logger) Trace(args ...any) { l.log(LevelTrace, args) }
+func (l *Logger) Debug(args ...any) { l.log(LevelDebug, args) }
+func (l *Logger) Info(args ...any)  { l.log(LevelInfo, args) }
+func (l *Logger) Warn(args ...any)  { l.log(LevelWarn, args) }
+func (l *Logger) Error(args ...any) { l.log(LevelError, args) }
+
+func (l *Logger) logf(level Level, format string, args []any) {
+	if !l.Enabled(level) {
+		return
+	}
+	l.emit(callerPC(4), level, fmt.Sprintf(format, args...))
+}
+
+func (l *Logger) log(level Level, args []any) {
+	if !l.Enabled(level) {
+		return
+	}
+	l.emit(callerPC(4), level, fmt.Sprint(args...))
+}
+
+// emit drops the Handler error, as a logger has nowhere to report it.
+func (l *Logger) emit(pc uintptr, level Level, msg string) {
+	_ = l.h.Handle(l.ctx, Record{Time: time.Now(), Level: level, Message: msg, PC: pc})
+}
+
+// callerPC returns the program counter skip frames up, 4 being the caller of an exported method.
+func callerPC(skip int) uintptr {
+	var pcs [1]uintptr
+	runtime.Callers(skip, pcs[:])
+	return pcs[0]
+}
+
+func argsToAttrs(args []any) []Attr {
+	attrs := make([]Attr, 0, len(args)/2+1)
+	for len(args) > 0 {
+		switch k := args[0].(type) {
+		case Attr:
+			attrs = append(attrs, k)
+			args = args[1:]
+		case string:
+			if len(args) == 1 {
+				attrs = append(attrs, Attr{Key: badKey, Value: k})
+				args = nil
+			} else {
+				attrs = append(attrs, Attr{Key: k, Value: args[1]})
+				args = args[2:]
+			}
+		default:
+			attrs = append(attrs, Attr{Key: badKey, Value: k})
+			args = args[1:]
+		}
+	}
+	return attrs
+}
@@ -0,0 +1,163 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package logging_test
+
+import (
+	"errors"
+	"io"
+	"runtime"
+	"strings"
+	"testing"
+	"time"
+
+	"gitea.com/gitea/runner/act/common/logging"
+	"gitea.com/gitea/runner/act/common/logging/logtest"
+
+	"github.com/sirupsen/logrus"
+	logrustest "github.com/sirupsen/logrus/hooks/test"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestParseLevel(t *testing.T) {
+	for in, want := range map[string]logging.Level{
+		"trace": logging.LevelTrace, "DEBUG": logging.LevelDebug, "info": logging.LevelInfo,
+		"warn": logging.LevelWarn, "warning": logging.LevelWarn,
+		"error": logging.LevelError, "fatal": logging.LevelError, "panic": logging.LevelError,
+	} {
+		got, err := logging.ParseLevel(in)
+		require.NoError(t, err, in)
+		assert.Equal(t, want, got, in)
+	}
+	_, err := logging.ParseLevel("loud")
+	require.Error(t, err)
+	assert.Equal(t, "warn", logging.LevelWarn.String())
+}
+
+type countingStringer struct{ n *int }
+
+func (c countingStringer) String() string { *c.n++; return "x" }
+
+func TestLogger(t *testing.T) {
+	h := logtest.NewWithLevel(logging.LevelTrace)
+	l := logging.New(h)
+
+	l.With("job", "j1").WithError(errors.New("boom")).Warnf("step %d", 2)
+	l.Info("a", 1, 2, "b")
+	l.With("k").With(7).Debug("x")
+
+	recs := h.AllRecords()
+	require.Len(t, recs, 3)
+	assert.Equal(t, "step 2", recs[0].Message)
+	assert.Equal(t, logging.LevelWarn, recs[0].Level)
+	assert.False(t, recs[0].Time.IsZero())
+	job, _ := recs[0].Attr("job")
+	assert.Equal(t, "j1", job)
+	errv, _ := recs[0].Attr("error")
+	require.EqualError(t, errv.(error), "boom")
+	assert.Equal(t, "a1 2b", recs[1].Message) // fmt.Sprint spacing
+	bad, _ := recs[2].Attr("!BADKEY")
+	assert.Equal(t, 7, bad)
+
+	h.Reset()
+	assert.Nil(t, h.LastRecord())
+}
+
+func TestLoggerSkipsFormattingWhenDisabled(t *testing.T) {
+	n := 0
+	l := logging.New(logging.NewLevelHandler(logtest.NewWithLevel(logging.LevelTrace), logging.LevelWarn))
+	l.Debugf("%v", countingStringer{&n})
+	assert.Zero(t, n)
+	assert.False(t, l.Enabled(logging.LevelInfo))
+}
+
+func TestMultiHandler(t *testing.T) {
+	assert.False(t, logging.DiscardHandler.Enabled(t.Context(), logging.LevelError))
+	all, warnOnly := logtest.New(), logtest.NewWithLevel(logging.LevelTrace)
+	l := logging.New(logging.NewMultiHandler(all, logging.NewLevelHandler(warnOnly, logging.LevelWarn), logging.DiscardHandler)).With("a", 1)
+	l.Info("i")
+	l.Error("e")
+	assert.Len(t, all.AllRecords(), 2)
+	require.Len(t, warnOnly.AllRecords(), 1)
+	v, _ := warnOnly.LastRecord().Attr("a")
+	assert.Equal(t, 1, v)
+}
+
+func frameOf(t *testing.T, pc uintptr) runtime.Frame {
+	t.Helper()
+	require.NotZero(t, pc)
+	f, _ := runtime.CallersFrames([]uintptr{pc}).Next()
+	return f
+}
+
+func TestCallerPC(t *testing.T) {
+	h := logtest.New()
+	l := logging.New(h)
+	l.Infof("method")
+	l.Info("method")
+	for _, r := range h.AllRecords() {
+		assert.True(t, strings.HasSuffix(frameOf(t, r.PC).Function, "TestCallerPC"), r.Message)
+	}
+
+	std := logrus.StandardLogger()
+	prevOut, prevCaller, prevHooks := std.Out, std.ReportCaller, std.ReplaceHooks(logrus.LevelHooks{})
+	t.Cleanup(func() {
+		std.SetOutput(prevOut)
+		std.SetReportCaller(prevCaller)
+		std.ReplaceHooks(prevHooks)
+	})
+	std.SetOutput(io.Discard)
+	std.SetReportCaller(true)
+	hook := logrustest.NewGlobal()
+	logging.Infof("global")
+	logging.Error("global")
+
+	require.Len(t, hook.AllEntries(), 2)
+	for _, e := range hook.AllEntries() {
+		require.NotNil(t, e.Caller, e.Message)
+		assert.True(t, strings.HasSuffix(e.Caller.Function, "TestCallerPC"), e.Caller.Function)
+	}
+}
+
+func TestLogrusHandler(t *testing.T) {
+	logger, hook := logrustest.NewNullLogger()
+	logger.SetLevel(logrus.DebugLevel)
+	logger.SetReportCaller(true)
+	l := logging.New(logging.NewLogrusHandler(logger)).With("job", "j1")
+
+	when := time.Date(2026, 1, 2, 3, 4, 5, 0, time.UTC)
+	h := logging.NewLogrusHandler(logger).WithAttrs([]logging.Attr{{Key: "base", Value: true}})
+	require.NoError(t, h.Handle(t.Context(), logging.Record{Time: when, Level: logging.LevelWarn, Message: "timed"}))
+
+	l.Tracef("dropped")
+	assert.False(t, l.Enabled(logging.LevelTrace))
+	l.WithError(errors.New("boom")).Errorf("fail %s", "x")
+	l.Debugf("dbg")
+
+	entries := hook.AllEntries()
+	require.Len(t, entries, 3)
+	assert.Equal(t, when, entries[0].Time)
+	assert.Equal(t, logrus.WarnLevel, entries[0].Level)
+	assert.Equal(t, true, entries[0].Data["base"])
+
+	assert.Equal(t, logrus.ErrorLevel, entries[1].Level)
+	assert.Equal(t, "fail x", entries[1].Message)
+	assert.Equal(t, "j1", entries[1].Data["job"])
+	require.EqualError(t, entries[1].Data[logrus.ErrorKey].(error), "boom")
+	assert.Equal(t, logrus.DebugLevel, entries[2].Level)
+
+	require.NotNil(t, entries[1].Caller)
+	assert.True(t, strings.HasSuffix(entries[1].Caller.Function, "TestLogrusHandler"), entries[1].Caller.Function)
+	assert.Contains(t, entries[1].Caller.File, "logging_test.go")
+}
+
+func TestDefaultLevel(t *testing.T) {
+	prev := logging.GetLevel()
+	t.Cleanup(func() { logging.SetLevel(prev) })
+
+	logging.SetLevel(logging.LevelWarn)
+	assert.Equal(t, logging.LevelWarn, logging.GetLevel())
+	assert.True(t, logging.Enabled(logging.LevelError))
+	assert.False(t, logging.Enabled(logging.LevelInfo))
+}
@@ -0,0 +1,87 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package logging
+
+import (
+	"context"
+	"runtime"
+
+	"github.com/sirupsen/logrus"
+)
+
+type logrusHandler struct {
+	entry *logrus.Entry
+}
+
+// NewLogrusHandler writes to l, so its level, hooks, formatter and output all apply.
+func NewLogrusHandler(l *logrus.Logger) Handler {
+	return &logrusHandler{entry: logrus.NewEntry(l)}
+}
+
+func (h *logrusHandler) Enabled(_ context.Context, level Level) bool {
+	return h.entry.Logger.IsLevelEnabled(toLogrusLevel(level))
+}
+
+func (h *logrusHandler) Handle(ctx context.Context, r Record) error {
+	if ctx == nil {
+		ctx = context.Background()
+	}
+	e := h.entry.WithContext(ctx) // always a copy, so the fields below never reach h.entry
+	if !r.Time.IsZero() {
+		e = e.WithTime(r.Time)
+	}
+	if len(r.Attrs) > 0 {
+		e = e.WithFields(attrsToFields(r.Attrs))
+	}
+	if r.PC != 0 && e.Logger.ReportCaller {
+		// logrus only skips its own frames, so without this it would report the logging package
+		frame, _ := runtime.CallersFrames([]uintptr{r.PC}).Next()
+		e.Caller = &frame
+	}
+	e.Log(toLogrusLevel(r.Level), r.Message)
+	return nil
+}
+
+func (h *logrusHandler) WithAttrs(attrs []Attr) Handler {
+	return &logrusHandler{entry: h.entry.WithFields(attrsToFields(attrs))}
+}
+
+func attrsToFields(attrs []Attr) logrus.Fields {
+	fields := make(logrus.Fields, len(attrs))
+	for _, a := range attrs {
+		fields[a.Key] = a.Value
+	}
+	return fields
+}
+
+func toLogrusLevel(l Level) logrus.Level {
+	switch {
+	case l <= LevelTrace:
+		return logrus.TraceLevel
+	case l <= LevelDebug:
+		return logrus.DebugLevel
+	case l <= LevelInfo:
+		return logrus.InfoLevel
+	case l <= LevelWarn:
+		return logrus.WarnLevel
+	default:
+		return logrus.ErrorLevel
+	}
+}
+
+// fromLogrusLevel maps logrus's Fatal and Panic to LevelError.
+func fromLogrusLevel(l logrus.Level) Level {
+	switch l {
+	case logrus.TraceLevel:
+		return LevelTrace
+	case logrus.DebugLevel:
+		return LevelDebug
+	case logrus.InfoLevel:
+		return LevelInfo
+	case logrus.WarnLevel:
+		return LevelWarn
+	default:
+		return LevelError
+	}
+}
@@ -0,0 +1,72 @@
+// Copyright 2026 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+// Package logtest provides a Handler that keeps records in memory for assertions.
+package logtest
+
+import (
+	"context"
+	"slices"
+	"sync"
+
+	"gitea.com/gitea/runner/act/common/logging"
+)
+
+type store struct {
+	mu      sync.Mutex
+	records []logging.Record
+}
+
+// Handler records what it receives at or above its level. Loggers derived with WithAttrs share one store.
+type Handler struct {
+	store    *store
+	attrs    []logging.Attr
+	minLevel logging.Level
+}
+
+// New records from LevelInfo up, like the logger of logrus's hooks/test.
+func New() *Handler {
+	return NewWithLevel(logging.LevelInfo)
+}
+
+func NewWithLevel(minLevel logging.Level) *Handler {
+	return &Handler{store: &store{}, minLevel: minLevel}
+}
+
+func (h *Handler) Enabled(_ context.Context, level logging.Level) bool { return level >= h.minLevel }
+
+// Handle stores the record with the attributes accumulated by WithAttrs placed first.
+func (h *Handler) Handle(_ context.Context, r logging.Record) error {
+	r.Attrs = append(slices.Clone(h.attrs), r.Attrs...)
+	h.store.mu.Lock()
+	defer h.store.mu.Unlock()
+	h.store.records = append(h.store.records, r)
+	return nil
+}
+
+func (h *Handler) WithAttrs(attrs []logging.Attr) logging.Handler {
+	return &Handler{store: h.store, attrs: append(slices.Clone(h.attrs), attrs...), minLevel: h.minLevel}
+}
+
+func (h *Handler) AllRecords() []logging.Record {
+	h.store.mu.Lock()
+	defer h.store.mu.Unlock()
+	return slices.Clone(h.store.records)
+}
+
+// LastRecord returns nil when nothing was logged.
+func (h *Handler) LastRecord() *logging.Record {
+	h.store.mu.Lock()
+	defer h.store.mu.Unlock()
+	if len(h.store.records) == 0 {
+		return nil
+	}
+	r := h.store.records[len(h.store.records)-1]
+	return &r
+}
+
+func (h *Handler) Reset() {
+	h.store.mu.Lock()
+	defer h.store.mu.Unlock()
+	h.store.records = nil
+}