From de961b91ebe7c242db5672ab706b37c16d2b0778 Mon Sep 17 00:00:00 2001 From: Lunny Xiao Date: Sun, 11 Oct 2026 23:26:00 +0000 Subject: [PATCH] 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 Reviewed-on: https://gitea.com/gitea/runner/pulls/1295 Reviewed-by: bircni --- act/artifactcache/handler.go | 13 +- act/artifacts/server.go | 3 +- act/common/context_helpers_test.go | 36 ++-- act/common/git/git.go | 5 +- act/common/git/git_test.go | 14 +- act/common/logger.go | 53 +++-- act/common/logging/global.go | 32 +++ act/common/logging/handler.go | 114 ++++++++++ act/common/logging/level.go | 53 +++++ act/common/logging/logger.go | 106 +++++++++ act/common/logging/logging_test.go | 163 ++++++++++++++ act/common/logging/logrus.go | 87 ++++++++ act/common/logging/logtest/logtest.go | 72 +++++++ act/container/docker_logger.go | 6 +- act/container/docker_pull_test.go | 9 +- act/container/docker_run.go | 6 +- act/container/docker_run_test.go | 42 ++-- act/container/host_environment_test.go | 14 +- act/ghcontext/github_context.go | 6 +- act/runner/action.go | 6 +- act/runner/command.go | 4 +- act/runner/command_test.go | 18 +- act/runner/docker_proxy_integration_test.go | 8 +- act/runner/job_executor.go | 6 +- act/runner/job_executor_test.go | 47 ++-- act/runner/job_hooks.go | 2 +- act/runner/job_hooks_test.go | 7 +- act/runner/logger.go | 225 +++++++++++--------- act/runner/logger_json.go | 52 +++++ act/runner/logger_test.go | 79 +++++-- act/runner/reusable_workflow.go | 2 +- act/runner/run_context.go | 10 +- act/runner/run_context_test.go | 32 ++- act/runner/runner.go | 25 +-- act/runner/step.go | 10 +- act/runner/step_action_builtin.go | 2 +- act/runner/step_action_local.go | 2 +- act/runner/step_action_remote.go | 2 +- act/runner/step_run.go | 12 +- act/runner/step_run_print_test.go | 33 ++- act/runner/step_test.go | 23 +- internal/app/cmd/cache-server.go | 3 +- internal/app/cmd/exec.go | 5 +- internal/app/run/logging.go | 16 +- internal/app/run/post_task_script_test.go | 10 +- internal/app/run/runner.go | 5 +- internal/app/run/runner_test.go | 7 +- internal/pkg/report/joblog_test.go | 8 +- internal/pkg/report/reporter.go | 69 ++++-- internal/pkg/report/reporter_test.go | 115 +++++----- 50 files changed, 1241 insertions(+), 438 deletions(-) create mode 100644 act/common/logging/global.go create mode 100644 act/common/logging/handler.go create mode 100644 act/common/logging/level.go create mode 100644 act/common/logging/logger.go create mode 100644 act/common/logging/logging_test.go create mode 100644 act/common/logging/logrus.go create mode 100644 act/common/logging/logtest/logtest.go create mode 100644 act/runner/logger_json.go diff --git a/act/artifactcache/handler.go b/act/artifactcache/handler.go index 7cdeab85..00b22045 100644 --- a/act/artifactcache/handler.go +++ b/act/artifactcache/handler.go @@ -15,7 +15,6 @@ import ( "encoding/json/v2" "errors" "fmt" - "io" "net" "net/http" "net/http/httputil" @@ -30,10 +29,10 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/internal/pkg/disk" "github.com/julienschmidt/httprouter" - "github.com/sirupsen/logrus" "github.com/timshannon/bolthold" "go.etcd.io/bbolt" ) @@ -85,7 +84,7 @@ type Handler struct { listener net.Listener port int server *http.Server - logger logrus.FieldLogger + logger *logging.Logger gcing atomic.Bool gcAt time.Time @@ -133,7 +132,7 @@ type Options struct { InternalSecret string Policy Policy - Logger logrus.FieldLogger + Logger *logging.Logger } // StartHandler starts an embedded cache or forwards cache requests to Upstream. @@ -147,11 +146,9 @@ func StartHandler(opts Options) (*Handler, error) { } if logger == nil { - discard := logrus.New() - discard.Out = io.Discard - logger = discard + logger = logging.New(logging.DiscardHandler) } - logger = logger.WithField("module", "artifactcache") + logger = logger.With("module", "artifactcache") h.logger = logger if opts.OutboundIP != "" { diff --git a/act/artifacts/server.go b/act/artifacts/server.go index 1d85fb3f..cb0f0287 100644 --- a/act/artifacts/server.go +++ b/act/artifacts/server.go @@ -230,7 +230,8 @@ func Serve(ctx context.Context, artifactPath, addr, port string) context.CancelF go func() { logger.Infof("Start server on http://%s", server.Addr) if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed { - logger.Fatal(err) + logger.Error(err) + os.Exit(1) } }() diff --git a/act/common/context_helpers_test.go b/act/common/context_helpers_test.go index ca21134d..c1779b9f 100644 --- a/act/common/context_helpers_test.go +++ b/act/common/context_helpers_test.go @@ -8,7 +8,8 @@ import ( "errors" "testing" - "github.com/sirupsen/logrus" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" ) func TestDryrunContext(t *testing.T) { @@ -40,34 +41,27 @@ func TestJobErrorContainer(t *testing.T) { } } -func TestLoggerAndHookContext(t *testing.T) { +func TestLoggerAndHandlerContext(t *testing.T) { ctx := context.Background() - if Logger(ctx) != logrus.StandardLogger() { - t.Fatal("plain context should use standard logger") + if Logger(ctx) != logging.Default() { + t.Fatal("plain context should use the default logger") } - if LoggerHook(ctx) != nil { - t.Fatal("plain context should not have a logger hook") + if LoggerHandler(ctx) != nil { + t.Fatal("plain context should not have a logger handler") + } + if StepIDs(ctx) != nil { + t.Fatal("plain context should not have step IDs") } - logger := logrus.New() + logger := logging.New(logtest.New()) ctx = WithLogger(ctx, logger) if Logger(ctx) != logger { t.Fatal("WithLogger should set logger") } - hook := testHook{} - ctx = WithLoggerHook(ctx, hook) - if LoggerHook(ctx) != hook { - t.Fatal("WithLoggerHook should set hook") + handler := logtest.New() + ctx = WithLoggerHandler(ctx, handler) + if LoggerHandler(ctx) != handler { + t.Fatal("WithLoggerHandler should set handler") } } - -type testHook struct{} - -func (testHook) Levels() []logrus.Level { - return logrus.AllLevels -} - -func (testHook) Fire(*logrus.Entry) error { - return nil -} diff --git a/act/common/git/git.go b/act/common/git/git.go index b1cdc244..5a321f85 100644 --- a/act/common/git/git.go +++ b/act/common/git/git.go @@ -23,9 +23,8 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/internal/pkg/lock" - - log "github.com/sirupsen/logrus" ) var ( @@ -189,7 +188,7 @@ type NewGitCloneExecutorInput struct { } // CloneIfRequired reports whether an existing local clone was reused. -func CloneIfRequired(ctx context.Context, input NewGitCloneExecutorInput, logger log.FieldLogger) (bool, error) { +func CloneIfRequired(ctx context.Context, input NewGitCloneExecutorInput, logger *logging.Logger) (bool, error) { var origin string _, err := os.Stat(filepath.Join(input.Dir, ".git")) // without it git would discover a repository around Dir if err == nil { diff --git a/act/common/git/git_test.go b/act/common/git/git_test.go index 2c6d4bb4..61a6879e 100644 --- a/act/common/git/git_test.go +++ b/act/common/git/git_test.go @@ -22,10 +22,10 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.com/gitea/runner/internal/pkg/lock" - log "github.com/sirupsen/logrus" - logrustest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -318,7 +318,7 @@ func TestGitCloneExecutorReclonesWhenOriginURLChanges(t *testing.T) { cancelled, cancel := context.WithCancel(t.Context()) cancel() - _, err := CloneIfRequired(cancelled, NewGitCloneExecutorInput{URL: oldRemoteDir, Ref: "main", Dir: cacheDir}, log.New()) + _, err := CloneIfRequired(cancelled, NewGitCloneExecutorInput{URL: oldRemoteDir, Ref: "main", Dir: cacheDir}, logging.New(logtest.New())) require.ErrorIs(t, err, context.Canceled) require.FileExists(t, markerPath) @@ -428,9 +428,9 @@ func TestGitCloneExecutorQuietDemotesCloneLine(t *testing.T) { // Quiet callers report the download themselves, so the clone line must not reach the job log. for name, quiet := range map[string]bool{"quiet": true, "not quiet": false} { t.Run(name, func(t *testing.T) { - logger, hook := logrustest.NewNullLogger() - logger.SetLevel(log.InfoLevel) - ctx := common.WithLogger(context.Background(), logger.WithField("job", "j1")) + hook := logtest.New() + logger := logging.New(logging.NewLevelHandler(hook, logging.LevelInfo)) + ctx := common.WithLogger(context.Background(), logger.With("job", "j1")) require.NoError(t, NewGitCloneExecutor(NewGitCloneExecutorInput{ URL: remoteDir, @@ -440,7 +440,7 @@ func TestGitCloneExecutorQuietDemotesCloneLine(t *testing.T) { })(ctx)) var cloneLines int - for _, entry := range hook.AllEntries() { + for _, entry := range hook.AllRecords() { if strings.HasPrefix(entry.Message, "git clone ") { cloneLines++ } diff --git a/act/common/logger.go b/act/common/logger.go index fb9608cb..14e5ba2b 100644 --- a/act/common/logger.go +++ b/act/common/logger.go @@ -7,46 +7,53 @@ package common import ( "context" - "github.com/sirupsen/logrus" + "gitea.com/gitea/runner/act/common/logging" ) type loggerContextKey string -const loggerContextKeyVal = loggerContextKey("logrus.FieldLogger") +const loggerContextKeyVal = loggerContextKey("logging.Logger") // Logger returns the appropriate logger for current context -func Logger(ctx context.Context) logrus.FieldLogger { - val := ctx.Value(loggerContextKeyVal) - if val != nil { - if logger, ok := val.(logrus.FieldLogger); ok { - return logger - } +func Logger(ctx context.Context) *logging.Logger { + if logger, ok := ctx.Value(loggerContextKeyVal).(*logging.Logger); ok { + return logger } - return logrus.StandardLogger() + return logging.Default() } // WithLogger adds a value to the context for the logger -func WithLogger(ctx context.Context, logger logrus.FieldLogger) context.Context { +func WithLogger(ctx context.Context, logger *logging.Logger) context.Context { return context.WithValue(ctx, loggerContextKeyVal, logger) } -type loggerHookKey string +type loggerHandlerKey string -const loggerHookKeyVal = loggerHookKey("logrus.Hook") +const loggerHandlerKeyVal = loggerHandlerKey("logging.Handler") -// LoggerHook returns the appropriate logger hook for current context -// the hook affects job logger, not global logger -func LoggerHook(ctx context.Context) logrus.Hook { - val := ctx.Value(loggerHookKeyVal) - if val != nil { - if hook, ok := val.(logrus.Hook); ok { - return hook - } +// LoggerHandler returns the extra handler the job logger sends its records to, or nil. +// It affects the job logger, not the global logger. +func LoggerHandler(ctx context.Context) logging.Handler { + if h, ok := ctx.Value(loggerHandlerKeyVal).(logging.Handler); ok { + return h } return nil } -// WithLoggerHook adds a value to the context for the logger hook -func WithLoggerHook(ctx context.Context, hook logrus.Hook) context.Context { - return context.WithValue(ctx, loggerHookKeyVal, hook) +// WithLoggerHandler adds the extra handler for the job logger to the context +func WithLoggerHandler(ctx context.Context, h logging.Handler) context.Context { + return context.WithValue(ctx, loggerHandlerKeyVal, h) +} + +type stepIDsContextKey struct{} + +// StepIDs returns the IDs of the step and the composite steps enclosing the current one, outermost first. +func StepIDs(ctx context.Context) []string { + ids, _ := ctx.Value(stepIDsContextKey{}).([]string) + return ids +} + +// WithStepIDs replaces the step IDs in the context +func WithStepIDs(ctx context.Context, ids []string) context.Context { + return context.WithValue(ctx, stepIDsContextKey{}, ids) } diff --git a/act/common/logging/global.go b/act/common/logging/global.go new file mode 100644 index 00000000..9d547cc2 --- /dev/null +++ b/act/common/logging/global.go @@ -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) } diff --git a/act/common/logging/handler.go b/act/common/logging/handler.go new file mode 100644 index 00000000..b266baae --- /dev/null +++ b/act/common/logging/handler.go @@ -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} +} diff --git a/act/common/logging/level.go b/act/common/logging/level.go new file mode 100644 index 00000000..a0db0438 --- /dev/null +++ b/act/common/logging/level.go @@ -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) +} diff --git a/act/common/logging/logger.go b/act/common/logging/logger.go new file mode 100644 index 00000000..741da8a4 --- /dev/null +++ b/act/common/logging/logger.go @@ -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 +} diff --git a/act/common/logging/logging_test.go b/act/common/logging/logging_test.go new file mode 100644 index 00000000..3dae49d6 --- /dev/null +++ b/act/common/logging/logging_test.go @@ -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)) +} diff --git a/act/common/logging/logrus.go b/act/common/logging/logrus.go new file mode 100644 index 00000000..c7c4116b --- /dev/null +++ b/act/common/logging/logrus.go @@ -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 + } +} diff --git a/act/common/logging/logtest/logtest.go b/act/common/logging/logtest/logtest.go new file mode 100644 index 00000000..9b84abe1 --- /dev/null +++ b/act/common/logging/logtest/logtest.go @@ -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 +} diff --git a/act/container/docker_logger.go b/act/container/docker_logger.go index c76c9d49..e0fda370 100644 --- a/act/container/docker_logger.go +++ b/act/container/docker_logger.go @@ -12,7 +12,7 @@ import ( "errors" "io" - "github.com/sirupsen/logrus" + "gitea.com/gitea/runner/act/common/logging" ) type dockerMessage struct { @@ -26,7 +26,7 @@ type dockerMessage struct { Progress string `json:"progress"` } -func logDockerResponse(logger logrus.FieldLogger, dockerResponse io.ReadCloser, isError bool) error { +func logDockerResponse(logger *logging.Logger, dockerResponse io.ReadCloser, isError bool) error { if dockerResponse == nil { return nil } @@ -77,7 +77,7 @@ func logDockerResponse(logger logrus.FieldLogger, dockerResponse io.ReadCloser, return nil } -func writeLog(logger logrus.FieldLogger, isError bool, format string, args ...any) { +func writeLog(logger *logging.Logger, isError bool, format string, args ...any) { if isError { logger.Errorf(format, args...) } else { diff --git a/act/container/docker_pull_test.go b/act/container/docker_pull_test.go index 8f4a629e..ed17674f 100644 --- a/act/container/docker_pull_test.go +++ b/act/container/docker_pull_test.go @@ -10,15 +10,16 @@ import ( "strings" "testing" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" + "github.com/docker/cli/cli/config" - log "github.com/sirupsen/logrus" - "github.com/sirupsen/logrus/hooks/test" assert "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func init() { - log.SetLevel(log.DebugLevel) + logging.SetLevel(logging.LevelDebug) } func TestCleanImage(t *testing.T) { @@ -79,7 +80,7 @@ func TestIsPinnedImage(t *testing.T) { // The pull path reports a failure the daemon sent mid-stream, so it must carry the reason // whichever of the two shapes the daemon used. func TestLogDockerResponseError(t *testing.T) { - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) streamErr := func(line string) error { return logDockerResponse(logger, io.NopCloser(strings.NewReader(line)), false) } diff --git a/act/container/docker_run.go b/act/container/docker_run.go index cba68c9c..646bd308 100644 --- a/act/container/docker_run.go +++ b/act/container/docker_run.go @@ -25,6 +25,7 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "dario.cat/mergo" "github.com/bmatcuk/doublestar/v4" @@ -40,7 +41,6 @@ import ( "github.com/moby/moby/client" "github.com/moby/moby/client/pkg/versions" specs "github.com/opencontainers/image-spec/specs-go/v1" - "github.com/sirupsen/logrus" ) // drainGracePeriod bounds how long we wait for an output-copy goroutine to @@ -1046,7 +1046,7 @@ func (cr *containerReference) wait() common.Executor { // sanitizeOptionsHostConfig takes back everything a workflow could escape the container with, // setting each field to trusted, which is what the runner's own options parse to on their own. // Only for unprivileged mode, since privileged mode grants host access anyway. -func sanitizeOptionsHostConfig(logger logrus.FieldLogger, hostConfig, trusted *container.HostConfig) { +func sanitizeOptionsHostConfig(logger *logging.Logger, hostConfig, trusted *container.HostConfig) { resetOption(logger, "--pid", &hostConfig.PidMode, trusted.PidMode) resetOption(logger, "--ipc", &hostConfig.IpcMode, trusted.IpcMode) resetOption(logger, "--uts", &hostConfig.UTSMode, trusted.UTSMode) @@ -1085,7 +1085,7 @@ func sanitizeOptionsHostConfig(logger logrus.FieldLogger, hostConfig, trusted *c // resetOption puts a field back to the runner's own value. It compares the values rather than // the flags, so a field that more than one option feeds cannot slip through. -func resetOption[T any](logger logrus.FieldLogger, option string, field *T, trusted T) { +func resetOption[T any](logger *logging.Logger, option string, field *T, trusted T) { if reflect.DeepEqual(*field, trusted) { return } diff --git a/act/container/docker_run_test.go b/act/container/docker_run_test.go index 61a63eeb..62a126af 100644 --- a/act/container/docker_run_test.go +++ b/act/container/docker_run_test.go @@ -19,6 +19,8 @@ import ( "testing" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" cerrdefs "github.com/containerd/errdefs" "github.com/moby/moby/api/pkg/stdcopy" @@ -26,7 +28,6 @@ import ( "github.com/moby/moby/api/types/mount" "github.com/moby/moby/api/types/network" mobyclient "github.com/moby/moby/client" - "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -353,7 +354,8 @@ func TestRemoveIgnoresAutoRemoveRace(t *testing.T) { {name: "real failure", err: removeFailure, wantErr: removeFailure}, } { t.Run(tc.name, func(t *testing.T) { - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) ctx := common.WithLogger(context.Background(), logger) client := &mockDockerClient{} client.On("ContainerKill", ctx, "abc", killOpts).Return(mobyclient.ContainerKillResult{}, nil) @@ -377,7 +379,7 @@ func TestRemoveIgnoresAutoRemoveRace(t *testing.T) { } else { assert.Empty(t, cr.id) } - assert.Empty(t, hook.AllEntries()) + assert.Empty(t, hook.AllRecords()) client.AssertExpectations(t) }) } @@ -614,7 +616,8 @@ func TestCheckVolumes(t *testing.T) { } for _, tc := range testCases { t.Run(tc.desc, func(t *testing.T) { - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) ctx := common.WithLogger(context.Background(), logger) cr := &containerReference{ input: &NewContainerInput{ @@ -624,7 +627,7 @@ func TestCheckVolumes(t *testing.T) { _, hostConf := cr.sanitizeConfig(ctx, &container.Config{}, &container.HostConfig{Binds: tc.binds, Mounts: tc.mounts}) assert.Equal(t, tc.expectedBinds, hostConf.Binds) assert.ElementsMatch(t, tc.expectedMounts, hostConf.Mounts) - assert.Len(t, hook.AllEntries(), len(tc.binds)+len(tc.mounts)-len(tc.expectedBinds)-len(tc.expectedMounts)) // every drop is warned about + assert.Len(t, hook.AllRecords(), len(tc.binds)+len(tc.mounts)-len(tc.expectedBinds)-len(tc.expectedMounts)) // every drop is warned about }) } } @@ -652,7 +655,7 @@ func TestMergeContainerConfigsKeepsTheRunnersFilesAndEnvToItself(t *testing.T) { t.Setenv("RUNNER_SECRET", "s3cr3t") for _, option := range []string{"--env-file " + hostFile, "--label-file " + hostFile} { - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) cr := &containerReference{input: &NewContainerInput{NetworkMode: "bridge", WorkflowOptions: option}} _, _, err := cr.mergeContainerConfigs(common.WithLogger(context.Background(), logger), &container.Config{}, &container.HostConfig{}) @@ -665,7 +668,7 @@ func TestMergeContainerConfigsKeepsTheRunnersFilesAndEnvToItself(t *testing.T) { } // a bare name is no longer resolved from the runner's environment, for either source - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) cr := &containerReference{input: &NewContainerInput{ NetworkMode: "bridge", RunnerOptions: "--env RUNNER_SECRET", @@ -678,7 +681,7 @@ func TestMergeContainerConfigsKeepsTheRunnersFilesAndEnvToItself(t *testing.T) { } func TestSanitizeOptionsHostConfig(t *testing.T) { - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) // every field the sanitizer resets, so a reset dropped in a refactor fails here hostConfig := &container.HostConfig{ @@ -711,9 +714,10 @@ func TestSanitizeOptionsHostConfig(t *testing.T) { } // mergeOptions merges both option sources into a bare container, returning the result and its log. -func mergeOptions(t *testing.T, runnerOptions, workflowOptions string, privileged bool) (*container.HostConfig, *test.Hook) { +func mergeOptions(t *testing.T, runnerOptions, workflowOptions string, privileged bool) (*container.HostConfig, *logtest.Handler) { t.Helper() - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) cr := &containerReference{input: &NewContainerInput{ RunnerOptions: runnerOptions, WorkflowOptions: workflowOptions, @@ -765,7 +769,7 @@ func TestMergeContainerConfigsStripsDangerousOptionsWhenUnprivileged(t *testing. } func TestCheckVolumesRejectsEscapingHostPaths(t *testing.T) { - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) ctx := common.WithLogger(context.Background(), logger) base := t.TempDir() @@ -806,14 +810,15 @@ func TestSanitizeConfigKeepsTmpfsMounts(t *testing.T) { require.Len(t, hostConfig.Mounts, 1) for _, validVolumes := range [][]string{nil, {"data"}, {"**:ro"}} { - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) _, sanitized := (&containerReference{input: &NewContainerInput{ValidVolumes: validVolumes}}).sanitizeConfig(common.WithLogger(context.Background(), logger), &container.Config{}, &container.HostConfig{Mounts: []mount.Mount{ hostConfig.Mounts[0], {Type: mount.TypeVolume, Target: "/anonymous"}, {Type: mount.TypeTmpfs, Source: "/etc", Target: "/etc-copy"}, }}) assert.Equal(t, hostConfig.Mounts, sanitized.Mounts) - assert.Len(t, hook.AllEntries(), 2) + assert.Len(t, hook.AllRecords(), 2) } } @@ -896,7 +901,7 @@ func TestContainerInfoFromInspect(t *testing.T) { } func TestMergeContainerConfigsVolumesReplaceRunnerMounts(t *testing.T) { - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) ctx := common.WithLogger(context.Background(), logger) cr := &containerReference{ input: &NewContainerInput{ @@ -919,7 +924,7 @@ func TestMergeContainerConfigsVolumesReplaceRunnerMounts(t *testing.T) { func TestMergeContainerConfigsWarnsOnlyAboutOptionsThatWereGiven(t *testing.T) { warnings := func(runnerOptions, workflowOptions string) int { _, hook := mergeOptions(t, runnerOptions, workflowOptions, false) - return len(hook.AllEntries()) + return len(hook.AllRecords()) } assert.Zero(t, warnings("--volume /host/tools:/opt/hostedtoolcache", "")) @@ -931,7 +936,8 @@ func TestMergeContainerConfigsWarnsOnlyAboutOptionsThatWereGiven(t *testing.T) { func TestDockerCreateKeepsInputEntrypoint(t *testing.T) { for _, entrypoint := range [][]string{nil, {"sleep", "3600"}} { for _, optionEntrypoint := range []string{"/sbin/dumb-init", ""} { - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) cr := &containerReference{ input: &NewContainerInput{ NetworkMode: "bridge", @@ -952,13 +958,13 @@ func TestDockerCreateKeepsInputEntrypoint(t *testing.T) { } require.NoError(t, cr.create(nil, nil)(common.WithLogger(t.Context(), logger))) assert.Equal(t, "created", cr.id) - assert.Equal(t, len(entrypoint) > 0, len(hook.AllEntries()) == 1) + assert.Equal(t, len(entrypoint) > 0, len(hook.AllRecords()) == 1) } } } func TestMergeContainerConfigsKeepsNetworkAliasesFromOptions(t *testing.T) { - logger, _ := test.NewNullLogger() + logger := logging.New(logtest.New()) cr := &containerReference{input: &NewContainerInput{ NetworkMode: "job-network", NetworkAliases: []string{"redis"}, WorkflowOptions: "--network-alias redis-primary", }} diff --git a/act/container/host_environment_test.go b/act/container/host_environment_test.go index 790e9947..ea8e306b 100644 --- a/act/container/host_environment_test.go +++ b/act/container/host_environment_test.go @@ -18,8 +18,8 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -170,8 +170,7 @@ func TestHostEnvironmentAllocatePTY(t *testing.T) { } func TestHostEnvironmentRemovePreservesWorkdirByDefault(t *testing.T) { - logger := logrus.New() - ctx := common.WithLogger(context.Background(), logrus.NewEntry(logger)) + ctx := common.WithLogger(context.Background(), logging.Default()) base := t.TempDir() miscRoot := filepath.Join(base, "misc") path := filepath.Join(miscRoot, "hostexecutor") @@ -193,8 +192,7 @@ func TestHostEnvironmentRemovePreservesWorkdirByDefault(t *testing.T) { } func TestHostEnvironmentRemoveCleansWorkdirWhenOwned(t *testing.T) { - logger := logrus.New() - ctx := common.WithLogger(context.Background(), logrus.NewEntry(logger)) + ctx := common.WithLogger(context.Background(), logging.Default()) base := t.TempDir() miscRoot := filepath.Join(base, "misc") path := filepath.Join(miscRoot, "hostexecutor") @@ -252,8 +250,7 @@ func TestHostEnvironmentRemoveDoesNotHangOnStuckCleanUp(t *testing.T) { hostCleanupTimeout = 100 * time.Millisecond t.Cleanup(func() { hostCleanupTimeout = orig }) - logger := logrus.New() - ctx := common.WithLogger(context.Background(), logrus.NewEntry(logger)) + ctx := common.WithLogger(context.Background(), logging.Default()) base := t.TempDir() path := filepath.Join(base, "misc", "hostexecutor") require.NoError(t, os.MkdirAll(path, 0o700)) @@ -306,8 +303,7 @@ func TestHostEnvironmentRemoveDoesNotHangOnStuckPathRemoval(t *testing.T) { removeAll = origRemoveAll }) - logger := logrus.New() - ctx := common.WithLogger(context.Background(), logrus.NewEntry(logger)) + ctx := common.WithLogger(context.Background(), logging.Default()) base := t.TempDir() path := filepath.Join(base, "misc", "hostexecutor") require.NoError(t, os.MkdirAll(path, 0o700)) diff --git a/act/ghcontext/github_context.go b/act/ghcontext/github_context.go index d78cf0ed..170138da 100644 --- a/act/ghcontext/github_context.go +++ b/act/ghcontext/github_context.go @@ -74,7 +74,7 @@ func SetRef(ctx context.Context, ghc *model.GithubContext, repoPath string) { if ghc.Ref == "" { ref, err := pinned(ctx, "ref:"+repoPath, func() (string, error) { return findGitRef(ctx, repoPath) }) if err != nil { - logger.Warningf("unable to get git ref: %v", err) + logger.Warnf("unable to get git ref: %v", err) } else { logger.Debugf("using github ref: %s", ref) ghc.Ref = ref @@ -121,7 +121,7 @@ func SetSha(ctx context.Context, ghc *model.GithubContext, repoPath string) { return revision, err }) if err != nil { - logger.Warningf("unable to get git revision: %v", err) + logger.Warnf("unable to get git revision: %v", err) } else { ghc.Sha = sha } @@ -134,7 +134,7 @@ func SetRepositoryAndOwner(ctx context.Context, ghc *model.GithubContext, repoPa if ghc.Repository == "" { repo, err := findGithubRepo(ctx, repoPath) if err != nil { - common.Logger(ctx).Warningf("unable to get git repo (repoPath: %v): %v", repoPath, err) + common.Logger(ctx).Warnf("unable to get git repo (repoPath: %v): %v", repoPath, err) return } ghc.Repository = repo diff --git a/act/runner/action.go b/act/runner/action.go index e4616444..51ae57cb 100644 --- a/act/runner/action.go +++ b/act/runner/action.go @@ -689,17 +689,17 @@ func shouldRunPostStep(step actionStep) common.Conditional { stepResult := stepResults[step.getStepModel().ID] if stepResult == nil { - log.WithField("stepResult", model.StepStatusSkipped).Debugf("skipping post step for '%s'; step was not executed", step.getStepModel()) + log.With("stepResult", model.StepStatusSkipped).Debugf("skipping post step for '%s'; step was not executed", step.getStepModel()) return false } if stepResult.Conclusion == model.StepStatusSkipped { - log.WithField("stepResult", model.StepStatusSkipped).Debugf("skipping post step for '%s'; main step was skipped", step.getStepModel()) + log.With("stepResult", model.StepStatusSkipped).Debugf("skipping post step for '%s'; main step was skipped", step.getStepModel()) return false } if step.getActionModel() == nil { - log.WithField("stepResult", model.StepStatusSkipped).Debugf("skipping post step for '%s': no action model available", step.getStepModel()) + log.With("stepResult", model.StepStatusSkipped).Debugf("skipping post step for '%s': no action model available", step.getStepModel()) return false } diff --git a/act/runner/command.go b/act/runner/command.go index a0f79d74..7c119a08 100644 --- a/act/runner/command.go +++ b/act/runner/command.go @@ -117,7 +117,7 @@ func (rc *RunContext) refuseUnsecureCommand(ctx context.Context, command string) } // The step executor logs the failure itself, so keep this line's wording distinct. - common.Logger(ctx).WithField(rawOutputField, true).Errorf("##[error]%s", EscapeCommandData(fmt.Sprintf( + common.Logger(ctx).With(rawOutputField, true).Errorf("##[error]%s", EscapeCommandData(fmt.Sprintf( "The `%s` command is disabled: it can set the environment of every later step from untrusted output. "+ "Write to $GITHUB_ENV or $GITHUB_PATH instead, or set ACTIONS_ALLOW_UNSECURE_COMMANDS to allow it", command))) @@ -159,7 +159,7 @@ func (rc *RunContext) setEnv(ctx context.Context, kvPairs map[string]string, arg if fromCommand { message = "Can't update NODE_OPTIONS environment variable using ::set-env:: command." } - common.Logger(ctx).WithField(rawOutputField, true).Errorf("##[error]%s", EscapeCommandData(message)) + common.Logger(ctx).With(rawOutputField, true).Errorf("##[error]%s", EscapeCommandData(message)) return } common.Logger(ctx).Infof("::set-env:: %s=%s", name, arg) diff --git a/act/runner/command_test.go b/act/runner/command_test.go index afff6842..55321fa8 100644 --- a/act/runner/command_test.go +++ b/act/runner/command_test.go @@ -12,9 +12,10 @@ import ( "testing" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.dev/actionslib/pkg/model" - "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -26,7 +27,8 @@ func unsecureRC() *RunContext { func TestSetEnv(t *testing.T) { a := assert.New(t) - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) ctx := common.WithLogger(context.Background(), logger) rc := unsecureRC() handler := rc.commandHandler(ctx) @@ -37,7 +39,7 @@ func TestSetEnv(t *testing.T) { rc.setEnvFile(ctx, map[string]string{"name": "node_options"}, "--require env.js") a.NotContains(rc.Env, "NODE_OPTIONS") a.NotContains(rc.Env, "node_options") - entries := hook.AllEntries() + entries := hook.AllRecords() require.Len(t, entries, 3) a.Equal("##[error]Can't update NODE_OPTIONS environment variable using ::set-env:: command.", entries[1].Message) a.Equal("##[error]Can't store NODE_OPTIONS output parameter using '$GITHUB_ENV' command.", entries[2].Message) @@ -120,7 +122,8 @@ func TestAddpath(t *testing.T) { } func TestStopCommands(t *testing.T) { - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) a := assert.New(t) ctx := common.WithLogger(context.Background(), logger) @@ -137,7 +140,7 @@ func TestStopCommands(t *testing.T) { a.Equal("abcd", rc.Env["x"]) messages := make([]string, 0) - for _, entry := range hook.AllEntries() { + for _, entry := range hook.AllRecords() { messages = append(messages, entry.Message) } @@ -174,7 +177,8 @@ func TestAddpathADO(t *testing.T) { } func TestAddmask(t *testing.T) { - logger, hook := test.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) a := assert.New(t) ctx := context.Background() @@ -184,7 +188,7 @@ func TestAddmask(t *testing.T) { handler := rc.commandHandler(loggerCtx) handler("::ADD-MASK::my::secret") - a.Equal("***", hook.LastEntry().Message) + a.Equal("***", hook.LastRecord().Message) a.Equal([]string{"my::secret"}, rc.Masks) } diff --git a/act/runner/docker_proxy_integration_test.go b/act/runner/docker_proxy_integration_test.go index 87970ccf..8b91d6d4 100644 --- a/act/runner/docker_proxy_integration_test.go +++ b/act/runner/docker_proxy_integration_test.go @@ -15,12 +15,12 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.com/gitea/runner/act/container" "gitea.dev/actionslib/pkg/model" cerrdefs "github.com/containerd/errdefs" "github.com/moby/moby/client" - "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -83,10 +83,10 @@ func TestDockerProxyMountedJob(t *testing.T) { } }) - hook := &test.Hook{} - require.NoError(t, runner.NewPlanExecutor(plan)(common.WithLoggerHook(ctx, hook))) + hook := logtest.New() + require.NoError(t, runner.NewPlanExecutor(plan)(common.WithLoggerHandler(ctx, hook))) var messages []string - for _, entry := range hook.AllEntries() { + for _, entry := range hook.AllRecords() { messages = append(messages, strings.TrimSpace(entry.Message)) } require.Contains(t, messages, "docker proxy post verified") diff --git a/act/runner/job_executor.go b/act/runner/job_executor.go index cf83f113..bd281d65 100644 --- a/act/runner/job_executor.go +++ b/act/runner/job_executor.go @@ -92,7 +92,7 @@ func printPrepareActions(rc *RunContext, preparers []actionPreparer) common.Exec return nil } - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) rawLogger.Infof("Prepare all required actions") for _, preparer := range preparers { @@ -126,7 +126,7 @@ func printCompleteJobName(rc *RunContext) common.Executor { if name == "" && rc.Run != nil { name = rc.Run.JobID } - common.Logger(ctx).WithField(rawOutputField, true).Infof("Complete job name: %s", name) + common.Logger(ctx).With(rawOutputField, true).Infof("Complete job name: %s", name) return nil } } @@ -412,7 +412,7 @@ func setJobResult(ctx context.Context, info jobInfo, rc *RunContext, success boo jobResultMessage = "cancelled" } - logger.WithField("jobResult", jobResult).Infof("Job %s", jobResultMessage) + logger.With("jobResult", jobResult).Infof("Job %s", jobResultMessage) } // evaluateJobEnv returns the workflow and job env evaluated, as far as it got on error, leaving rc.Env raw. diff --git a/act/runner/job_executor_test.go b/act/runner/job_executor_test.go index 32ab9d84..172bb866 100644 --- a/act/runner/job_executor_test.go +++ b/act/runner/job_executor_test.go @@ -21,11 +21,11 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.com/gitea/runner/act/container" "gitea.dev/actionslib/pkg/model" - log "github.com/sirupsen/logrus" - logrustest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -136,11 +136,8 @@ func (apm *actionPreparerMock) actionDownloadInfo() (string, string, bool) { func TestPrintPrepareActionsGolden(t *testing.T) { buf := &bytes.Buffer{} - logger := log.New() - logger.SetOutput(buf) - logger.SetLevel(log.InfoLevel) - logger.SetFormatter(&jobLogFormatter{color: cyan}) - ctx := common.WithLogger(context.Background(), logger.WithFields(log.Fields{"job": "j1"})) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(buf, cyan), logging.LevelInfo)) + ctx := common.WithLogger(context.Background(), logger.With("job", "j1")) preparers := []actionPreparer{ &actionPreparerMock{reference: "actions/checkout@v7", sha: "9c091bb21b7c1c1d1991bb908d89e4e9dddfe3e0", ok: true}, @@ -162,10 +159,8 @@ func TestPrintPrepareActionsGolden(t *testing.T) { func TestPrintPrepareActionsSkipsWithoutActions(t *testing.T) { buf := &bytes.Buffer{} - logger := log.New() - logger.SetOutput(buf) - logger.SetFormatter(&jobLogFormatter{color: cyan}) - ctx := common.WithLogger(context.Background(), logger.WithFields(log.Fields{"job": "j1"})) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(buf, cyan), logging.LevelInfo)) + ctx := common.WithLogger(context.Background(), logger.With("job", "j1")) require.NoError(t, printPrepareActions(&RunContext{}, nil)(ctx)) @@ -173,8 +168,8 @@ func TestPrintPrepareActionsSkipsWithoutActions(t *testing.T) { } func TestPrintPrepareActionsFailsJobOnDownloadError(t *testing.T) { - logger, _ := logrustest.NewNullLogger() - ctx := common.WithJobErrorContainer(common.WithLogger(context.Background(), logger.WithField("job", "j1"))) + logger := logging.New(logtest.New()) + ctx := common.WithJobErrorContainer(common.WithLogger(context.Background(), logger.With("job", "j1"))) downloadErr := errors.New("failed to fetch \"actions/checkout\"") rc := &RunContext{} @@ -203,10 +198,8 @@ func TestPrintCompleteJobName(t *testing.T) { } { t.Run(name, func(t *testing.T) { buf := &bytes.Buffer{} - logger := log.New() - logger.SetOutput(buf) - logger.SetFormatter(&jobLogFormatter{color: cyan}) - ctx := common.WithLogger(context.Background(), logger.WithFields(log.Fields{"job": "j1"})) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(buf, cyan), logging.LevelInfo)) + ctx := common.WithLogger(context.Background(), logger.With("job", "j1")) require.NoError(t, printCompleteJobName(tt.rc)(ctx)) @@ -269,14 +262,16 @@ func TestNewJobExecutorDownloadsAllActionsBeforeTheFirstStep(t *testing.T) { defer sm.AssertExpectations(t) } - logger, hook := logrustest.NewNullLogger() - err := newJobExecutor(jim, sfm, rc)(common.WithLogger(ctx, logger.WithField("job", "test"))) + hook := logtest.New() + + logger := logging.New(hook) + err := newJobExecutor(jim, sfm, rc)(common.WithLogger(ctx, logger.With("job", "test"))) require.NoError(t, err) assert.Equal(t, []string{"pre1", "pre2", "step1", "step2"}, executorOrder) setup := make([]string, 0) - for _, entry := range hook.AllEntries() { + for _, entry := range hook.AllRecords() { if strings.HasPrefix(entry.Message, "Prepare all required actions") || strings.HasPrefix(entry.Message, "Download action") || strings.HasPrefix(entry.Message, "Complete job name") { setup = append(setup, entry.Message) @@ -974,7 +969,8 @@ func TestReadSingleFileFromContainerArchiveFindsMatchingRegularFile(t *testing.T } func TestReadSingleFileFromContainerArchiveTruncatesWhenTooLarge(t *testing.T) { - logger, hook := logrustest.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) ctx := common.WithLogger(context.Background(), logger) cm := &containerMock{} content := strings.Repeat("a", 300) @@ -992,14 +988,15 @@ func TestReadSingleFileFromContainerArchiveTruncatesWhenTooLarge(t *testing.T) { assert.LessOrEqual(t, len(body), maxBytes) keep := maxBytes - len(jobSummaryTruncationMarker) assert.Equal(t, []byte(content[:keep]+jobSummaryTruncationMarker), body) - if assert.Len(t, hook.Entries, 1) { - assert.Contains(t, hook.Entries[0].Message, "job summary truncated") + if assert.Len(t, hook.AllRecords(), 1) { + assert.Contains(t, hook.AllRecords()[0].Message, "job summary truncated") } cm.AssertExpectations(t) } func TestReadSingleFileFromContainerArchiveKeepsExactLimitWithoutWarning(t *testing.T) { - logger, hook := logrustest.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) ctx := common.WithLogger(context.Background(), logger) cm := &containerMock{} cm.On("GetContainerArchive", ctx, "/var/run/act/workflow/SUMMARY.md").Return( @@ -1012,7 +1009,7 @@ func TestReadSingleFileFromContainerArchiveKeepsExactLimitWithoutWarning(t *test // A summary that is exactly at the limit is kept whole and not flagged as truncated. assert.True(t, ok) assert.Equal(t, []byte("abc"), body) - assert.Empty(t, hook.Entries) + assert.Empty(t, hook.AllRecords()) cm.AssertExpectations(t) } diff --git a/act/runner/job_hooks.go b/act/runner/job_hooks.go index ab6f6ea6..26f30b1f 100644 --- a/act/runner/job_hooks.go +++ b/act/runner/job_hooks.go @@ -42,7 +42,7 @@ func (rc *RunContext) runJobHook(ctx context.Context, hookPath, name string) err } cmd, shell := hookCommand(hookPath) - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) defer rawLogger.Infof("::endgroup::") rawLogger.Infof("::group::Run '%s'", EscapeCommandData(hookPath)) rawLogger.Infof("A %s hook has been configured by the runner administrator", name) diff --git a/act/runner/job_hooks_test.go b/act/runner/job_hooks_test.go index ec6ca331..046d675a 100644 --- a/act/runner/job_hooks_test.go +++ b/act/runner/job_hooks_test.go @@ -12,9 +12,10 @@ import ( "testing" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.dev/actionslib/pkg/model" - "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -64,8 +65,8 @@ func newHookRunContext(jobContainer *hookContainer, config *Config) (*RunContext Run: &model.Run{JobID: "job", Workflow: &model.Workflow{Jobs: map[string]*model.Job{"job": {}}}}, JobContainer: jobContainer, } - logger, _ := test.NewNullLogger() - ctx := common.WithJobErrorContainer(common.WithLogger(context.Background(), logger.WithField("test", true))) + logger := logging.New(logtest.New()) + ctx := common.WithJobErrorContainer(common.WithLogger(context.Background(), logger.With("test", true))) rc.ExprEval = rc.NewExpressionEvaluator(ctx) return rc, ctx } diff --git a/act/runner/logger.go b/act/runner/logger.go index 401c56ec..9195562a 100644 --- a/act/runner/logger.go +++ b/act/runner/logger.go @@ -19,8 +19,8 @@ import ( "sync" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" - "github.com/sirupsen/logrus" "golang.org/x/term" ) @@ -73,8 +73,9 @@ func WithMasks(ctx context.Context, masks *[]string) context.Context { return context.WithValue(ctx, masksContextKeyVal, masks) } +// JobLoggerFactory supplies the handler a job's own log output goes to, in place of stdout. type JobLoggerFactory interface { - WithJobLogger() *logrus.Logger + WithJobLogger() logging.Handler } type jobLoggerFactoryContextKey string @@ -89,84 +90,70 @@ func WithJobLoggerFactory(ctx context.Context, factory JobLoggerFactory) context func WithJobLogger(ctx context.Context, jobID, jobName string, config *Config, masks *[]string, matrix map[string]any) context.Context { ctx = WithMasks(ctx, masks) - var logger *logrus.Logger + var output logging.Handler if jobLoggerFactory, ok := ctx.Value(jobLoggerFactoryContextKeyVal).(JobLoggerFactory); ok && jobLoggerFactory != nil { - logger = jobLoggerFactory.WithJobLogger() + output = jobLoggerFactory.WithJobLogger() + } else if config.JSONLogger { + output = newJobLogJSONHandler(os.Stdout) } else { - var formatter logrus.Formatter - if config.JSONLogger { - formatter = &logrus.JSONFormatter{} - } else { - mux.Lock() - defer mux.Unlock() - nextColor++ - formatter = &jobLogFormatter{color: colors[nextColor%len(colors)]} - } - - logger = logrus.New() - logger.SetOutput(os.Stdout) - logger.SetLevel(logrus.GetLevel()) - logger.SetFormatter(formatter) + mux.Lock() + nextColor++ + color := colors[nextColor%len(colors)] + mux.Unlock() + output = newJobLogHandler(os.Stdout, color) } - { // Adapt to Gitea - if hook := common.LoggerHook(ctx); hook != nil { - logger.AddHook(hook) - } - if config.JobLoggerLevel != nil { - logger.SetLevel(*config.JobLoggerLevel) - } else { - logger.SetLevel(logrus.TraceLevel) - } + var handlers []logging.Handler + if h := common.LoggerHandler(ctx); h != nil { // Adapt to Gitea + handlers = append(handlers, h) } - - logger.SetFormatter(&maskedFormatter{ - Formatter: logger.Formatter, - masker: valueMasker(config.InsecureSecrets, config.maskers()), + handlers = append(handlers, &maskedHandler{ + Handler: output, + masker: valueMasker(config.InsecureSecrets, config.maskers()), }) - rtn := logger.WithFields(logrus.Fields{ - "job": jobName, - "jobID": jobID, - "dryrun": common.Dryrun(ctx), - "matrix": matrix, - }).WithContext(ctx) + + level := logging.LevelTrace + if config.JobLoggerLevel != nil { + level = *config.JobLoggerLevel + } + + rtn := logging.New(logging.NewLevelHandler(logging.NewMultiHandler(handlers...), level)).With( + "job", jobName, + "jobID", jobID, + "dryrun", common.Dryrun(ctx), + "matrix", matrix, + ).WithContext(ctx) return common.WithLogger(ctx, rtn) } func WithCompositeLogger(ctx context.Context, masks *[]string) context.Context { ctx = WithMasks(ctx, masks) - return common.WithLogger(ctx, common.Logger(ctx).WithFields(logrus.Fields{}).WithContext(ctx)) + return common.WithLogger(ctx, common.Logger(ctx).WithContext(ctx)) } func WithCompositeStepLogger(ctx context.Context, stepID string) context.Context { - val := common.Logger(ctx) - stepIDs := make([]string, 0) + stepIDs := append(slices.Clone(common.StepIDs(ctx)), stepID) + ctx = common.WithStepIDs(ctx, stepIDs) - if logger, ok := val.(*logrus.Entry); ok { - if oldStepIDs, ok := logger.Data["stepID"].([]string); ok { - stepIDs = append(stepIDs, oldStepIDs...) - } - } - - stepIDs = append(stepIDs, stepID) - - return common.WithLogger(ctx, common.Logger(ctx).WithFields(logrus.Fields{ - "stepID": stepIDs, - }).WithContext(ctx)) + return common.WithLogger(ctx, common.Logger(ctx).With("stepID", stepIDs).WithContext(ctx)) } func withStepLogger(ctx context.Context, stepNumber int, stepID, stepName, stageName string) context.Context { - rtn := common.Logger(ctx).WithFields(logrus.Fields{ - "stepNumber": stepNumber, - "step": stepName, - "stepID": []string{stepID}, - "stage": stageName, - }) + stepIDs := []string{stepID} + ctx = common.WithStepIDs(ctx, stepIDs) + + rtn := common.Logger(ctx).With( + "stepNumber", stepNumber, + "step", stepName, + "stepID", stepIDs, + "stage", stageName, + ) return common.WithLogger(ctx, rtn) } -type entryProcessor func(entry *logrus.Entry) *logrus.Entry +// entryProcessor rewrites a record before the output handler sees it. +type entryProcessor func(ctx context.Context, r logging.Record) logging.Record var secretValueEncoders = []func(string) string{ func(v string) string { return base64.StdEncoding.EncodeToString([]byte(v)) }, @@ -321,16 +308,16 @@ func valueMasker(insecureSecrets bool, oldnew []string) entryProcessor { replacer *strings.Replacer ) - return func(entry *logrus.Entry) *logrus.Entry { + return func(ctx context.Context, r logging.Record) logging.Record { if insecureSecrets { - return entry + return r } - masks := Masks(entry.Context) + masks := Masks(ctx) if len(*masks) == 0 { - entry.Message = defReplacer.Replace(entry.Message) - return entry + r.Message = defReplacer.Replace(r.Message) + return r } mu.Lock() @@ -349,89 +336,129 @@ func valueMasker(insecureSecrets bool, oldnew []string) entryProcessor { cmasker := replacer mu.Unlock() - entry.Message = cmasker.Replace(entry.Message) + r.Message = cmasker.Replace(r.Message) - return entry + return r } } -type maskedFormatter struct { - logrus.Formatter +type maskedHandler struct { + logging.Handler masker entryProcessor } -func (f *maskedFormatter) Format(entry *logrus.Entry) ([]byte, error) { - return f.Formatter.Format(f.masker(entry)) +func (m *maskedHandler) Handle(ctx context.Context, r logging.Record) error { + return m.Handler.Handle(ctx, m.masker(ctx, r)) } -type jobLogFormatter struct { +func (m *maskedHandler) WithAttrs(attrs []logging.Attr) logging.Handler { + return &maskedHandler{Handler: m.Handler.WithAttrs(attrs), masker: m.masker} +} + +// jobLogHandler writes a job's log to w, one record per line in the shape format gives it. +type jobLogHandler struct { + w io.Writer + mu *sync.Mutex // shared by every handler derived with WithAttrs, as they share w + attrs []logging.Attr + format func(logging.Record) ([]byte, error) +} + +// newJobLogHandler writes readable text. +func newJobLogHandler(w io.Writer, color int) *jobLogHandler { + return &jobLogHandler{w: w, mu: &sync.Mutex{}, format: textFormatter{w: w, color: color}.format} +} + +func (h *jobLogHandler) Enabled(context.Context, logging.Level) bool { return true } + +func (h *jobLogHandler) WithAttrs(attrs []logging.Attr) logging.Handler { + c := *h + c.attrs = slices.Concat(h.attrs, attrs) + return &c +} + +func (h *jobLogHandler) Handle(_ context.Context, r logging.Record) error { + r.Attrs = slices.Concat(h.attrs, r.Attrs) + line, err := h.format(r) + if err != nil { + return err + } + h.mu.Lock() + defer h.mu.Unlock() + _, err = h.w.Write(line) + return err +} + +type textFormatter struct { + w io.Writer color int } -func (f *jobLogFormatter) Format(entry *logrus.Entry) ([]byte, error) { +func (f textFormatter) format(r logging.Record) ([]byte, error) { b := &bytes.Buffer{} // the web renderer decodes command data, so this local view has to as well - if _, _, _, ok := tryParseRawActionCommand(entry.Message + "\n"); ok { - entry.Message = UnescapeCommandData(entry.Message) + if _, _, _, ok := tryParseRawActionCommand(r.Message + "\n"); ok { + r.Message = UnescapeCommandData(r.Message) } + r.Message = strings.TrimSuffix(r.Message, "\n") - if f.isColored(entry) { - f.printColored(b, entry) + if f.isColored() { + f.printColored(b, r) } else { - f.print(b, entry) + f.print(b, r) } b.WriteByte('\n') return b.Bytes(), nil } -func (f *jobLogFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry) { - entry.Message = strings.TrimSuffix(entry.Message, "\n") +func attrIsTrue(r logging.Record, key string) bool { + v, _ := r.Attr(key) + return v == true +} - job := entry.Data["job"] +func (f textFormatter) printColored(b *bytes.Buffer, r logging.Record) { + job, _ := r.Attr("job") debugFlag := "" - if entry.Level == logrus.DebugLevel { + if r.Level == logging.LevelDebug { debugFlag = "[DEBUG] " } switch { - case entry.Data[rawOutputField] == true: - if entry.Data[scriptLineCyanField] == true { - fmt.Fprintf(b, "\x1b[%dm|\x1b[0m \x1b[36;1m%s\x1b[0m", f.color, entry.Message) + case attrIsTrue(r, rawOutputField): + if attrIsTrue(r, scriptLineCyanField) { + fmt.Fprintf(b, "\x1b[%dm|\x1b[0m \x1b[36;1m%s\x1b[0m", f.color, r.Message) } else { - fmt.Fprintf(b, "\x1b[%dm|\x1b[0m %s", f.color, entry.Message) + fmt.Fprintf(b, "\x1b[%dm|\x1b[0m %s", f.color, r.Message) } - case entry.Data["dryrun"] == true: - fmt.Fprintf(b, "\x1b[1m\x1b[%dm\x1b[7m*DRYRUN*\x1b[0m \x1b[%dm[%s] \x1b[0m%s%s", gray, f.color, job, debugFlag, entry.Message) + case attrIsTrue(r, "dryrun"): + fmt.Fprintf(b, "\x1b[1m\x1b[%dm\x1b[7m*DRYRUN*\x1b[0m \x1b[%dm[%s] \x1b[0m%s%s", gray, f.color, job, debugFlag, r.Message) default: - fmt.Fprintf(b, "\x1b[%dm[%s] \x1b[0m%s%s", f.color, job, debugFlag, entry.Message) + fmt.Fprintf(b, "\x1b[%dm[%s] \x1b[0m%s%s", f.color, job, debugFlag, r.Message) } } -func (f *jobLogFormatter) print(b *bytes.Buffer, entry *logrus.Entry) { - entry.Message = strings.TrimSuffix(entry.Message, "\n") - - job := entry.Data["job"] +func (f textFormatter) print(b *bytes.Buffer, r logging.Record) { + job, _ := r.Attr("job") debugFlag := "" - if entry.Level == logrus.DebugLevel { + if r.Level == logging.LevelDebug { debugFlag = "[DEBUG] " } switch { - case entry.Data[rawOutputField] == true: - fmt.Fprintf(b, "[%s] | %s", job, entry.Message) - case entry.Data["dryrun"] == true: - fmt.Fprintf(b, "*DRYRUN* [%s] %s%s", job, debugFlag, entry.Message) + case attrIsTrue(r, rawOutputField): + fmt.Fprintf(b, "[%s] | %s", job, r.Message) + case attrIsTrue(r, "dryrun"): + fmt.Fprintf(b, "*DRYRUN* [%s] %s%s", job, debugFlag, r.Message) default: - fmt.Fprintf(b, "[%s] %s%s", job, debugFlag, entry.Message) + fmt.Fprintf(b, "[%s] %s%s", job, debugFlag, r.Message) } } -func (f *jobLogFormatter) isColored(entry *logrus.Entry) bool { - isColored := checkIfTerminal(entry.Logger.Out) +func (f textFormatter) isColored() bool { + isColored := checkIfTerminal(f.w) if force, ok := os.LookupEnv("CLICOLOR_FORCE"); ok && force != "0" { isColored = true diff --git a/act/runner/logger_json.go b/act/runner/logger_json.go new file mode 100644 index 00000000..b041e010 --- /dev/null +++ b/act/runner/logger_json.go @@ -0,0 +1,52 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package runner + +import ( + "encoding/json" + "fmt" + "io" + "sync" + "time" + + "gitea.com/gitea/runner/act/common/logging" +) + +// newJobLogJSONHandler writes one JSON object per record, in the shape of logrus's JSONFormatter. +func newJobLogJSONHandler(w io.Writer) *jobLogHandler { + return &jobLogHandler{w: w, mu: &sync.Mutex{}, format: formatJSON} +} + +func formatJSON(r logging.Record) ([]byte, error) { + data := make(map[string]any, len(r.Attrs)+3) + for _, a := range r.Attrs { + switch v := a.Value.(type) { + case error: + data[a.Key] = v.Error() // an error marshals to {} + default: + data[a.Key] = v + } + } + for _, key := range []string{"time", "msg", "level"} { + if v, ok := data[key]; ok { // keep the fixed keys from being overwritten + data["fields."+key] = v + } + } + data["time"] = r.Time.Format(time.RFC3339) + data["msg"] = r.Message + data["level"] = jsonLevel(r.Level) + + line, err := json.Marshal(data) + if err != nil { + return nil, fmt.Errorf("failed to marshal fields to JSON, %w", err) + } + return append(line, '\n'), nil +} + +func jsonLevel(l logging.Level) string { + if l.String() == "warn" { + return "warning" // what logrus calls it + } + return l.String() +} diff --git a/act/runner/logger_test.go b/act/runner/logger_test.go index a0bc5266..d58a504f 100644 --- a/act/runner/logger_test.go +++ b/act/runner/logger_test.go @@ -4,13 +4,19 @@ package runner import ( + "bytes" "encoding/base64" + "encoding/json" + "errors" "io" "net/url" "strings" "testing" - "github.com/sirupsen/logrus" + "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -49,10 +55,7 @@ func TestValueMasker(t *testing.T) { ctx := WithMasks(t.Context(), &entry.masks) masker := valueMasker(false, AppendSecretMaskers(nil, entry.secrets)) for line := range strings.SplitSeq(entry.lines, "\n") { - lentry := masker(&logrus.Entry{ - Context: ctx, - Message: line, - }) + lentry := masker(ctx, logging.Record{Message: line}) for _, line := range entry.disallowed { assert.NotContains(t, lentry.Message, line) } @@ -79,7 +82,7 @@ func TestValueMaskerEncodedSecrets(t *testing.T) { } { t.Run(tc.name, func(t *testing.T) { masker := valueMasker(false, AppendSecretMaskers(nil, map[string]string{"TOKEN": tc.secret})) - entry := masker(&logrus.Entry{Context: t.Context(), Message: strings.Join(tc.encoded, " ")}) + entry := masker(t.Context(), logging.Record{Message: strings.Join(tc.encoded, " ")}) assert.Contains(t, entry.Message, "***") for _, disallowed := range tc.encoded { @@ -105,7 +108,7 @@ func TestValueMaskerJSONEscapesBothWays(t *testing.T) { {"literal (JS JSON.stringify / .NET)", jsonStringEscapeNoHTML(secret)}, } { t.Run(tc.name, func(t *testing.T) { - entry := masker(&logrus.Entry{Context: t.Context(), Message: `{"t":"` + tc.form + `"}`}) + entry := masker(t.Context(), logging.Record{Message: `{"t":"` + tc.form + `"}`}) assert.Contains(t, entry.Message, "***") assert.NotContains(t, entry.Message, tc.form) @@ -118,7 +121,7 @@ func TestValueMaskerJSONEscapesBothWays(t *testing.T) { func TestValueMaskerHidesExtraMasks(t *testing.T) { masker := valueMasker(false, (&Config{ExtraMasks: []string{"pr0xypw"}}).maskers()) - entry := masker(&logrus.Entry{Context: t.Context(), Message: "proxy is http://user:pr0xypw@proxy:3128"}) + entry := masker(t.Context(), logging.Record{Message: "proxy is http://user:pr0xypw@proxy:3128"}) assert.Equal(t, "proxy is http://user:***@proxy:3128", entry.Message) } @@ -137,7 +140,7 @@ func TestValueMaskerEncodedMasks(t *testing.T) { {"encoded: " + base64.StdEncoding.EncodeToString([]byte("s3cr3t")), "encoded: ***"}, {"encoded: " + base64.StdEncoding.EncodeToString([]byte("first")), "encoded: ***"}, } { - entry := masker(&logrus.Entry{Context: WithMasks(t.Context(), &masks), Message: tc.line}) + entry := masker(WithMasks(t.Context(), &masks), logging.Record{Message: tc.line}) assert.Equal(t, tc.want, entry.Message, tc.line) } } @@ -154,7 +157,7 @@ func TestValueMaskerBase64Alignments(t *testing.T) { for _, prefix := range []string{"x-access-token:", "user:", "ab:"} { t.Run(prefix, func(t *testing.T) { encoded := base64.StdEncoding.EncodeToString([]byte(prefix + secret)) - entry := masker(&logrus.Entry{Context: t.Context(), Message: "Authorization: Basic " + encoded}) + entry := masker(t.Context(), logging.Record{Message: "Authorization: Basic " + encoded}) assert.Contains(t, entry.Message, "***") assert.NotEqual(t, "Authorization: Basic "+encoded, entry.Message) @@ -172,7 +175,7 @@ func TestValueMaskerBase64Alignments(t *testing.T) { func TestValueMaskerCachedReplacerSeesNewMasks(t *testing.T) { masker := valueMasker(false, AppendSecretMaskers(nil, map[string]string{"TOKEN": "secret-token"})) mask := func(masks *[]string, message string) string { - return masker(&logrus.Entry{Context: WithMasks(t.Context(), masks), Message: message}).Message + return masker(WithMasks(t.Context(), masks), logging.Record{Message: message}).Message } job := []string{"first mask"} @@ -206,15 +209,61 @@ func TestAppendSecretMaskerSkipsUselessEncodings(t *testing.T) { } func TestJobLogFormatterDecodesCommandData(t *testing.T) { - logger := logrus.New() - logger.Out = io.Discard format := func(message string) string { - out, err := (&jobLogFormatter{}).Format(&logrus.Entry{Logger: logger, Message: message, Data: logrus.Fields{rawOutputField: true}}) + line, err := textFormatter{w: io.Discard}.format(logging.Record{Message: message, Attrs: []logging.Attr{{Key: rawOutputField, Value: true}}}) require.NoError(t, err) - return string(out) + return string(line) } assert.Contains(t, format("##[error]deploy 50%25 traffic"), "##[error]deploy 50% traffic") // a plain line is not command data and keeps its literal escapes assert.Contains(t, format("progress 50%25 done"), "progress 50%25 done") } + +type factoryFunc func() logging.Handler + +func (f factoryFunc) WithJobLogger() logging.Handler { return f() } + +func TestWithJobLoggerFansOutAndMasksOnlyOutput(t *testing.T) { + output, hook := logtest.NewWithLevel(logging.LevelTrace), logtest.NewWithLevel(logging.LevelTrace) + ctx := WithJobLoggerFactory(t.Context(), factoryFunc(func() logging.Handler { return output })) + ctx = common.WithLoggerHandler(ctx, hook) + level := logging.LevelInfo + cfg := &Config{Secrets: map[string]string{"TOKEN": "s3cr3t-value"}, JobLoggerLevel: &level} + + ctx = WithJobLogger(ctx, "j1", "build", cfg, &[]string{}, nil) + ctx = withStepLogger(ctx, 2, "s2", "step two", "Main") + ctx = WithCompositeStepLogger(ctx, "inner") + common.Logger(ctx).Infof("token is %s", "s3cr3t-value") + common.Logger(ctx).Debugf("below the job logger level") + + // the reporter masks for itself, so its record keeps the original + require.Len(t, hook.AllRecords(), 1) + assert.Equal(t, "token is s3cr3t-value", hook.LastRecord().Message) + require.Len(t, output.AllRecords(), 1) + assert.Equal(t, "token is ***", output.LastRecord().Message) + + for _, want := range []struct { + key string + val any + }{{"job", "build"}, {"jobID", "j1"}, {"stepNumber", 2}, {"stage", "Main"}, {"stepID", []string{"s2", "inner"}}} { + got, ok := hook.LastRecord().Attr(want.key) + assert.True(t, ok, want.key) + assert.Equal(t, want.val, got, want.key) + } +} + +func TestJobLogJSONHandler(t *testing.T) { + buf := &bytes.Buffer{} + logger := logging.New(newJobLogJSONHandler(buf)).With("job", "build", "msg", "clash").WithError(errors.New("boom")) + logger.Warnf("careful %d", 1) + + var got map[string]any + require.NoError(t, json.Unmarshal(buf.Bytes(), &got)) + assert.Equal(t, "careful 1", got["msg"]) + assert.Equal(t, "warning", got["level"]) + assert.Equal(t, "build", got["job"]) + assert.Equal(t, "boom", got["error"]) + assert.Equal(t, "clash", got["fields.msg"]) + assert.NotEmpty(t, got["time"]) +} diff --git a/act/runner/reusable_workflow.go b/act/runner/reusable_workflow.go index 591a5b70..bafa247b 100644 --- a/act/runner/reusable_workflow.go +++ b/act/runner/reusable_workflow.go @@ -193,7 +193,7 @@ func setReusedWorkflowCallerResult(rc *RunContext, runner *runnerImpl) common.Ex unlock := lockJob(rc.Run.Job()) rc.result(reusedWorkflowJobResult) unlock() - common.Logger(ctx).WithField("jobResult", reusedWorkflowJobResult).Infof("Job %s", reusedWorkflowJobResultMessage) + common.Logger(ctx).With("jobResult", reusedWorkflowJobResult).Infof("Job %s", reusedWorkflowJobResultMessage) } } diff --git a/act/runner/run_context.go b/act/runner/run_context.go index 40c0ae97..37dd629d 100644 --- a/act/runner/run_context.go +++ b/act/runner/run_context.go @@ -511,7 +511,7 @@ func (rc *RunContext) startKubernetesPod() common.Executor { // printStartJobContainerGroup mirrors actions/runner's "Starting job container" // section: emit the group header and summary, return a closer for ::endgroup::. func printStartJobContainerGroup(ctx context.Context, image, name, network string) func() { - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) rawLogger.Infof("::group::Starting job container") rawLogger.Infof("image: %s", image) rawLogger.Infof("name: %s", name) @@ -706,7 +706,7 @@ func (rc *RunContext) commandLogWriter(ctx context.Context) io.Writer { } func rawLogLine(ctx context.Context) common.LineHandler { - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) return func(line string) bool { rawLogger.Infof("%s", line) return true @@ -957,7 +957,7 @@ func (rc *RunContext) waitForServiceContainers() common.Executor { // waitUntilHealthy waits on the healthcheck alone, so a container that declares none is // ready at once and one that exited is left to the steps that need it. func (svc *serviceContainer) waitUntilHealthy(ctx context.Context, timeout time.Duration) error { - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) loggedStarting := false ctx, cancel := context.WithTimeout(ctx, timeout) @@ -1015,7 +1015,7 @@ const serviceLogsTimeout = 15 * time.Second // cleanup gets one minute in total func (rc *RunContext) printServiceLogs(ctx context.Context) { ctx, cancel := context.WithTimeout(ctx, serviceLogsTimeout) defer cancel() - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) for _, svc := range rc.serviceContainers { if !svc.created || svc.logsDumped { continue @@ -1338,7 +1338,7 @@ func (rc *RunContext) isEnabled(ctx context.Context) (bool, error) { rc.caller.setReusedWorkflowJobResult(rc.Run.JobID, "skipped") return false, nil } - l.WithField("jobResult", "skipped").Debugf("Skipping job '%s' due to '%s'", job.Name, job.If.Value) + l.With("jobResult", "skipped").Debugf("Skipping job '%s' due to '%s'", job.Name, job.If.Value) return false, nil } diff --git a/act/runner/run_context_test.go b/act/runner/run_context_test.go index 506fb687..5c95cbee 100644 --- a/act/runner/run_context_test.go +++ b/act/runner/run_context_test.go @@ -25,14 +25,14 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.com/gitea/runner/act/container" "gitea.dev/actionslib/pkg/exprparser" "gitea.dev/actionslib/pkg/model" "github.com/docker/cli/cli/compose/loader" "github.com/moby/moby/api/types/volume" - log "github.com/sirupsen/logrus" - logrustest "github.com/sirupsen/logrus/hooks/test" assert "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" require "github.com/stretchr/testify/require" @@ -899,7 +899,7 @@ func TestInterpolateOutputsFromExpression(t *testing.T) { } func TestGetGitHubContext(t *testing.T) { - log.SetLevel(log.DebugLevel) + logging.SetLevel(logging.LevelDebug) cwd, err := os.Getwd() assert.NoError(t, err) //nolint:testifylint // pre-existing issue from nektos/act @@ -929,7 +929,7 @@ func TestGetGitHubContext(t *testing.T) { ghc := rc.getGithubContext(context.Background()) - log.Debugf("%v", ghc) + logging.Debugf("%v", ghc) actor := "nektos/act" if a := os.Getenv("ACT_ACTOR"); a != "" { @@ -1060,7 +1060,7 @@ func createJob(t *testing.T, input, result string) *model.Job { } func TestRunContextRunsOnPlatformNames(t *testing.T) { - log.SetLevel(log.DebugLevel) + logging.SetLevel(logging.LevelDebug) assertObject := assert.New(t) rc := createIfTestRunContext(map[string]*model.Job{ @@ -1107,7 +1107,7 @@ func TestRunContextRunsOnPlatformNames(t *testing.T) { } func TestRunContextIsEnabled(t *testing.T) { - log.SetLevel(log.DebugLevel) + logging.SetLevel(logging.LevelDebug) assertObject := assert.New(t) // success() @@ -1306,11 +1306,8 @@ func TestCreateContainerNameBoundedForLongMatrixInput(t *testing.T) { func TestPrintStartJobContainerGroupGolden(t *testing.T) { buf := &bytes.Buffer{} - logger := log.New() - logger.SetOutput(buf) - logger.SetLevel(log.InfoLevel) - logger.SetFormatter(&jobLogFormatter{color: cyan}) - entry := logger.WithFields(log.Fields{"job": "j1"}) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(buf, cyan), logging.LevelInfo)) + entry := logger.With("job", "j1") ctx := common.WithLogger(context.Background(), entry) printStartJobContainerGroup(ctx, "node:20", "GITEA-WORKFLOW-build-JOB-test", "gitea-runner-network")() @@ -1402,7 +1399,8 @@ func TestRunContext_cleanupFailedStart(t *testing.T) { Run: &model.Run{JobID: "job", Workflow: workflow}, platformImage: "node:20", } - logger, hook := logrustest.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) ctx := common.WithLogger(common.WithDryrun(t.Context(), true), logger) rc.ExprEval = rc.NewExpressionEvaluator(ctx) err = rc.startContainer().Then(rc.stopContainer()).Finally(rc.closeContainer())(ctx) @@ -1423,7 +1421,7 @@ func TestRunContext_cleanupFailedStart(t *testing.T) { } assert.Equal(t, strings.Fields(want+" job.Remove service.Remove service.Close job.Close"), operations) assert.Empty(t, rc.Masks) - assert.Equal(t, testcase.pullError == nil && testcase.health != container.HealthUnhealthy, slices.ContainsFunc(hook.AllEntries(), func(entry *log.Entry) bool { + assert.Equal(t, testcase.pullError == nil && testcase.health != container.HealthUnhealthy, slices.ContainsFunc(hook.AllRecords(), func(entry logging.Record) bool { return strings.HasPrefix(entry.Message, "::group::Print service container logs") })) }) @@ -1463,9 +1461,8 @@ func TestWaitForServiceContainers(t *testing.T) { Return(&container.Info{ID: "id", State: "running", Health: container.HealthHealthy}, nil).Once() var output bytes.Buffer - logger := log.New() - logger.SetOutput(&output) - require.NoError(t, newRunContext(0, &serviceContainer{name: "postgres", container: service}).waitForServiceContainers()(common.WithLogger(t.Context(), logger.WithFields(nil)))) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(&output, cyan), logging.LevelInfo)) + require.NoError(t, newRunContext(0, &serviceContainer{name: "postgres", container: service}).waitForServiceContainers()(common.WithLogger(t.Context(), logger))) assert.Equal(t, []time.Duration{0, time.Second, 2 * time.Second}, pollTimes) assert.Equal(t, 1, strings.Count(output.String(), "postgres service is starting.")) assert.Contains(t, output.String(), "postgres service is healthy.") @@ -1797,8 +1794,7 @@ func TestRunContextUpdateExtraPath(t *testing.T) { {name: "over 16 MiB", content: []byte(strings.Repeat("x", 16*1024*1024+1)), wantErr: true}, } { t.Run(testcase.name, func(t *testing.T) { - logger := log.New() - logger.SetOutput(io.Discard) + logger := logging.New(logging.DiscardHandler) ctx := common.WithLogger(t.Context(), logger) jobContainer := &containerMock{} jobContainer.On("GetContainerArchive", mock.Anything, "/github/path"). diff --git a/act/runner/runner.go b/act/runner/runner.go index 1bada894..51a451aa 100644 --- a/act/runner/runner.go +++ b/act/runner/runner.go @@ -16,6 +16,7 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/container" "gitea.com/gitea/runner/act/ghcontext" @@ -80,18 +81,18 @@ type Config struct { PlatformPicker func(labels []string) string KubernetesPicker func(labels []string) container.KubernetesOptions InstanceTransport http.RoundTripper - JobLoggerLevel *log.Level // the level of job logger - ValidVolumes []string // only volumes (and bind mounts) in this slice can be mounted on the job container or service containers - SharedToolCache bool // one tool cache for all jobs instead of one per job - InsecureSkipTLS bool // whether to skip verifying TLS certificate of the Gitea instance - ClientCertFile, ClientKeyFile string // PEM client certificate for the Gitea instance - MaxParallel int // max parallel jobs to run across all workflows (0 = no limit, uses CPU count) - AllocatePTY bool // allocate a pseudo-TTY for each step's process - ServiceReadyTimeout time.Duration // how long a job waits for its service containers to report healthy (0 uses the default) - NoSweep bool // keep the containers, networks and volumes a job creates through its docker proxy - RunnerName string // name this runner registered with, reported as `runner.name`, defaults to the hostname - JobStartedHook string // script run inside the job environment before the job's first step; ACTIONS_RUNNER_HOOK_JOB_STARTED is read from Env when empty - JobCompletedHook string // script run inside the job environment after the job's last step; ACTIONS_RUNNER_HOOK_JOB_COMPLETED is read from Env when empty + JobLoggerLevel *logging.Level // the level of job logger + ValidVolumes []string // only volumes (and bind mounts) in this slice can be mounted on the job container or service containers + SharedToolCache bool // one tool cache for all jobs instead of one per job + InsecureSkipTLS bool // whether to skip verifying TLS certificate of the Gitea instance + ClientCertFile, ClientKeyFile string // PEM client certificate for the Gitea instance + MaxParallel int // max parallel jobs to run across all workflows (0 = no limit, uses CPU count) + AllocatePTY bool // allocate a pseudo-TTY for each step's process + ServiceReadyTimeout time.Duration // how long a job waits for its service containers to report healthy (0 uses the default) + NoSweep bool // keep the containers, networks and volumes a job creates through its docker proxy + RunnerName string // name this runner registered with, reported as `runner.name`, defaults to the hostname + JobStartedHook string // script run inside the job environment before the job's first step; ACTIONS_RUNNER_HOOK_JOB_STARTED is read from Env when empty + JobCompletedHook string // script run inside the job environment after the job's last step; ACTIONS_RUNNER_HOOK_JOB_COMPLETED is read from Env when empty } // RunnerDebug reports whether debug logging is on, exposed as `runner.debug` and diff --git a/act/runner/step.go b/act/runner/step.go index 5f435dee..adad9c83 100644 --- a/act/runner/step.go +++ b/act/runner/step.go @@ -97,14 +97,14 @@ func runStepExecutor(step step, stage stepStage, executor common.Executor) commo if err != nil { stepResult.Conclusion = model.StepStatusFailure stepResult.Outcome = model.StepStatusFailure - logger.WithField("stepResult", stepResult.Conclusion).Infof("Failure - %s %s", stage, stepModel) + logger.With("stepResult", stepResult.Conclusion).Infof("Failure - %s %s", stage, stepModel) return err } if !runStep { stepResult.Conclusion = model.StepStatusSkipped stepResult.Outcome = model.StepStatusSkipped - logger.WithField("stepResult", stepResult.Conclusion).Debugf("Skipping step '%s' due to '%s'", stepModel, ifExpression) + logger.With("stepResult", stepResult.Conclusion).Debugf("Skipping step '%s' due to '%s'", stepModel, ifExpression) return nil } @@ -207,14 +207,14 @@ func runStepExecutor(step step, stage stepStage, executor common.Executor) commo _ = rc.JobContainer.Copy(actPath, files...)(fileCommandCtx) if err == nil { - logger.WithField("stepResult", stepResult.Conclusion).Infof("Success - %s %s", stage, stepString) + logger.With("stepResult", stepResult.Conclusion).Infof("Success - %s %s", stage, stepString) } else { stepResult.Outcome = model.StepStatusFailure continueOnError, parseErr := isContinueOnError(ctx, stepModel.RawContinueOnError, step, stage) if parseErr != nil { stepResult.Conclusion = model.StepStatusFailure - logger.WithField("stepResult", stepResult.Conclusion).Infof("Failure - %s %s", stage, stepString) + logger.With("stepResult", stepResult.Conclusion).Infof("Failure - %s %s", stage, stepString) return parseErr } @@ -229,7 +229,7 @@ func runStepExecutor(step step, stage stepStage, executor common.Executor) commo // Infof: Errorf entries are promoted to the user log by the reporter, // which would duplicate the ##[error] annotation emitted elsewhere. - logger.WithField("stepResult", stepResult.Conclusion).Infof("Failure - %s %s", stage, stepString) + logger.With("stepResult", stepResult.Conclusion).Infof("Failure - %s %s", stage, stepString) } return err } diff --git a/act/runner/step_action_builtin.go b/act/runner/step_action_builtin.go index 67ed6fca..f0943790 100644 --- a/act/runner/step_action_builtin.go +++ b/act/runner/step_action_builtin.go @@ -34,7 +34,7 @@ func (sab *stepActionBuiltin) main() common.Executor { } printRunActionHeader(ctx, sab.Step, sab.env, sab.RunContext) - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) defer rawLogger.Infof("::endgroup::") rc := sab.RunContext diff --git a/act/runner/step_action_local.go b/act/runner/step_action_local.go index 9f6f24ba..ec715f8f 100644 --- a/act/runner/step_action_local.go +++ b/act/runner/step_action_local.go @@ -43,7 +43,7 @@ func (sal *stepActionLocal) main() common.Executor { } printRunActionHeader(ctx, sal.Step, sal.env, sal.getRunContext()) - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) defer rawLogger.Infof("::endgroup::") actionDir := filepath.Join(sal.getRunContext().Config.Workdir, sal.Step.Uses) diff --git a/act/runner/step_action_remote.go b/act/runner/step_action_remote.go index b3de2339..d13d1686 100644 --- a/act/runner/step_action_remote.go +++ b/act/runner/step_action_remote.go @@ -134,7 +134,7 @@ func (sar *stepActionRemote) main() common.Executor { sar.prepareActionExecutor(), runStepExecutor(sar, stepStageMain, func(ctx context.Context) error { printRunActionHeader(ctx, sar.Step, sar.env, sar.RunContext) - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) defer rawLogger.Infof("::endgroup::") github := sar.getGithubContext(ctx) diff --git a/act/runner/step_run.go b/act/runner/step_run.go index c0f5f6a8..3901198d 100644 --- a/act/runner/step_run.go +++ b/act/runner/step_run.go @@ -14,12 +14,12 @@ import ( "strings" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/container" "gitea.com/gitea/runner/act/lookpath" "gitea.dev/actionslib/pkg/model" "github.com/kballard/go-shellquote" - "github.com/sirupsen/logrus" yaml "go.yaml.in/yaml/v4" ) @@ -58,8 +58,8 @@ func (sr *stepRun) main() common.Executor { // printRunScriptActionDetails mirrors actions/runner ScriptHandler.PrintActionDetails // for script steps. func (sr *stepRun) printRunScriptActionDetails(ctx context.Context) { - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) - scriptLineLogger := rawLogger.WithField(scriptLineCyanField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) + scriptLineLogger := rawLogger.With(scriptLineCyanField, true) normalized := strings.TrimRight(strings.ReplaceAll(sr.interpolatedScript, "\r\n", "\n"), "\n") @@ -84,7 +84,7 @@ func printRunActionHeader(ctx context.Context, step *model.Step, env map[string] if step == nil { return } - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) title := step.Uses if step.Name != "" { @@ -105,7 +105,7 @@ func printRunActionHeader(ctx context.Context, step *model.Step, env map[string] // printStepEnvBlock emits the declared-env block (YAML order, internal vars filtered) // shared by the run: and uses: "Run" headers. func printStepEnvBlock(ctx context.Context, step *model.Step, env map[string]string, rc *RunContext) { - rawLogger := common.Logger(ctx).WithField(rawOutputField, true) + rawLogger := common.Logger(ctx).With(rawOutputField, true) caseInsensitive := rc != nil && rc.JobContainer != nil && rc.JobContainer.IsEnvironmentCaseInsensitive() var visible []string for _, k := range stepDeclaredEnvKeysInOrder(step) { @@ -135,7 +135,7 @@ func printStepEnvBlock(ctx context.Context, step *model.Step, env map[string]str // logKeyedValue prints one row per line of value: Gitea stores one log row per line, so an // embedded newline would reach the user as a literal "\n". -func logKeyedValue(rawLogger *logrus.Entry, key, value string) { +func logKeyedValue(rawLogger *logging.Logger, key, value string) { lines := strings.Split(strings.ReplaceAll(value, "\r\n", "\n"), "\n") rawLogger.Infof(" %s: %s", key, lines[0]) for _, line := range lines[1:] { diff --git a/act/runner/step_run_print_test.go b/act/runner/step_run_print_test.go index da05030c..0da894db 100644 --- a/act/runner/step_run_print_test.go +++ b/act/runner/step_run_print_test.go @@ -7,13 +7,14 @@ package runner import ( "bytes" "context" + "io" "strings" "testing" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.dev/actionslib/pkg/model" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" yaml "go.yaml.in/yaml/v4" @@ -84,11 +85,8 @@ env: require.NoError(t, yaml.Unmarshal([]byte(raw), &step)) buf := &bytes.Buffer{} - logger := logrus.New() - logger.SetOutput(buf) - logger.SetLevel(logrus.InfoLevel) - logger.SetFormatter(&jobLogFormatter{color: cyan}) - entry := logger.WithFields(logrus.Fields{"job": "j1"}) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(buf, cyan), logging.LevelInfo)) + entry := logger.With("job", "j1") ctx := common.WithLogger(context.Background(), entry) sr := &stepRun{ @@ -133,11 +131,8 @@ env: require.NoError(t, yaml.Unmarshal([]byte(raw), &step)) buf := &bytes.Buffer{} - logger := logrus.New() - logger.SetOutput(buf) - logger.SetLevel(logrus.InfoLevel) - logger.SetFormatter(&jobLogFormatter{color: cyan}) - entry := logger.WithFields(logrus.Fields{"job": "j1"}) + logger := logging.New(logging.NewLevelHandler(newJobLogHandler(buf, cyan), logging.LevelInfo)) + entry := logger.With("job", "j1") ctx := common.WithLogger(context.Background(), entry) printRunActionHeader(ctx, &step, map[string]string{"CUSTOM": "value", "GITHUB_TOKEN": "tok"}, &RunContext{}) @@ -166,17 +161,17 @@ func TestIsInternalEnvKey(t *testing.T) { } func TestPrintColoredScriptLineCyan(t *testing.T) { - f := &jobLogFormatter{color: cyan} - entry := &logrus.Entry{ - Level: logrus.InfoLevel, + f := textFormatter{w: io.Discard, color: cyan} + record := logging.Record{ + Level: logging.LevelInfo, Message: "echo one", - Data: logrus.Fields{ - "job": "j1", - rawOutputField: true, - scriptLineCyanField: true, + Attrs: []logging.Attr{ + {Key: "job", Value: "j1"}, + {Key: rawOutputField, Value: true}, + {Key: scriptLineCyanField, Value: true}, }, } buf := &bytes.Buffer{} - f.printColored(buf, entry) + f.printColored(buf, record) assert.Equal(t, "\x1b[36m|\x1b[0m \x1b[36;1mecho one\x1b[0m", buf.String()) } diff --git a/act/runner/step_test.go b/act/runner/step_test.go index ef7c64a5..1a971965 100644 --- a/act/runner/step_test.go +++ b/act/runner/step_test.go @@ -14,13 +14,13 @@ import ( "testing/synctest" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" + "gitea.com/gitea/runner/act/common/logging/logtest" "gitea.com/gitea/runner/act/container" "gitea.com/gitea/runner/internal/pkg/telemetry" "gitea.dev/actionslib/pkg/model" runnerv1 "gitea.dev/actionslib/runner/v1" - log "github.com/sirupsen/logrus" - logrustest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -299,7 +299,7 @@ func TestIsStepEnabled(t *testing.T) { } } - log.SetLevel(log.DebugLevel) + logging.SetLevel(logging.LevelDebug) assertObject := assert.New(t) // success() @@ -383,7 +383,7 @@ func TestIsContinueOnError(t *testing.T) { } } - log.SetLevel(log.DebugLevel) + logging.SetLevel(logging.LevelDebug) assertObject := assert.New(t) // absent @@ -513,18 +513,20 @@ func TestRunStepExecutorParity(t *testing.T) { } { t.Run(test.name, func(t *testing.T) { step := newStep(t, test.step) - logger, hook := logrustest.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) err := runStepExecutor(step, stepStageMain, test.executor)(common.WithLogger(context.Background(), logger)) require.ErrorContains(t, err, test.wantError) assert.Equal(t, model.StepStatusFailure, step.RunContext.StepResults[test.step.ID].Conclusion) - assert.Equal(t, model.StepStatusFailure, hook.LastEntry().Data["stepResult"]) + assert.Equal(t, model.StepStatusFailure, lastRecordAttr(hook, "stepResult")) }) } t.Run("file command error honors continue-on-error", func(t *testing.T) { step := newStep(t, &model.Step{ID: "commands", RawContinueOnError: "true"}) - logger, hook := logrustest.NewNullLogger() + hook := logtest.New() + logger := logging.New(hook) err := runStepExecutor(step, stepStageMain, func(context.Context) error { require.NoError(t, os.WriteFile(step.env["GITHUB_ENV"], []byte("GOOD=1\nmalformed\n"), 0o600)) require.NoError(t, os.WriteFile(step.env["GITHUB_OUTPUT"], []byte("kept=value\n"), 0o600)) @@ -536,7 +538,7 @@ func TestRunStepExecutorParity(t *testing.T) { result := step.RunContext.StepResults[step.Step.ID] assert.Equal(t, model.StepStatusFailure, result.Outcome) assert.Equal(t, model.StepStatusSuccess, result.Conclusion) - assert.Equal(t, model.StepStatusSuccess, hook.LastEntry().Data["stepResult"]) + assert.Equal(t, model.StepStatusSuccess, lastRecordAttr(hook, "stepResult")) assert.Equal(t, "1", step.RunContext.Env["GOOD"]) assert.Equal(t, "value", result.Outputs["kept"]) assert.Equal(t, "value", step.RunContext.IntraActionState[step.Step.ID]["saved"]) @@ -630,3 +632,8 @@ func TestRunStepExecutorParity(t *testing.T) { } }) } + +func lastRecordAttr(h *logtest.Handler, key string) any { + v, _ := h.LastRecord().Attr(key) + return v +} diff --git a/internal/app/cmd/cache-server.go b/internal/app/cmd/cache-server.go index f7186082..aeeb1876 100644 --- a/internal/app/cmd/cache-server.go +++ b/internal/app/cmd/cache-server.go @@ -8,6 +8,7 @@ import ( "fmt" "gitea.com/gitea/runner/act/artifactcache" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/internal/app/run" "gitea.com/gitea/runner/internal/pkg/config" @@ -60,7 +61,7 @@ func runCacheServer(configFile *string, cacheArgs *cacheServerArgs) func(cmd *co Port: port, InternalSecret: secret, Policy: run.CachePolicy(cfg), - Logger: log.StandardLogger().WithField("module", "cache_request"), + Logger: logging.Default().With("module", "cache_request"), }) if err != nil { return err diff --git a/internal/app/cmd/exec.go b/internal/app/cmd/exec.go index 1c19c6d8..bed8d891 100644 --- a/internal/app/cmd/exec.go +++ b/internal/app/cmd/exec.go @@ -23,6 +23,7 @@ import ( "gitea.com/gitea/runner/act/artifactcache" "gitea.com/gitea/runner/act/artifacts" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/runner" "gitea.com/gitea/runner/internal/app/run" "gitea.com/gitea/runner/internal/pkg/config" @@ -482,7 +483,7 @@ func runExec(ctx context.Context, execArgs *executeArgs) func(cmd *cobra.Command // init a cache server handler, err := artifactcache.StartHandler(artifactcache.Options{ Policy: run.CachePolicy(&config.Config{Cache: config.DefaultCache()}), - Logger: log.StandardLogger().WithField("module", "cache_request"), + Logger: logging.Default().With("module", "cache_request"), }) if err != nil { return err @@ -553,7 +554,7 @@ func runExec(ctx context.Context, execArgs *executeArgs) func(cmd *cobra.Command } if !execArgs.debug { - logLevel := log.InfoLevel + logLevel := logging.LevelInfo config.JobLoggerLevel = &logLevel } diff --git a/internal/app/run/logging.go b/internal/app/run/logging.go index d0e6d1ca..8fefaea5 100644 --- a/internal/app/run/logging.go +++ b/internal/app/run/logging.go @@ -4,21 +4,15 @@ package run import ( - "io" - - log "github.com/sirupsen/logrus" + "gitea.com/gitea/runner/act/common/logging" ) // NullLogger is used to create a new JobLogger to discard logs. This // will prevent these logs from being logged to the stdout, but -// forward them to the Reporter via its hook. +// forward them to the Reporter via its handler. type NullLogger struct{} -// WithJobLogger creates a new logrus.Logger that will discard all logs. -func (n NullLogger) WithJobLogger() *log.Logger { - logger := log.New() - logger.SetOutput(io.Discard) - logger.SetLevel(log.TraceLevel) - - return logger +// WithJobLogger returns a handler that discards all logs. +func (n NullLogger) WithJobLogger() logging.Handler { + return logging.DiscardHandler } diff --git a/internal/app/run/post_task_script_test.go b/internal/app/run/post_task_script_test.go index 3ba2b1b5..44a208d4 100644 --- a/internal/app/run/post_task_script_test.go +++ b/internal/app/run/post_task_script_test.go @@ -10,12 +10,12 @@ import ( "testing" "time" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/internal/pkg/config" "gitea.com/gitea/runner/internal/pkg/metrics" "gitea.com/gitea/runner/internal/pkg/report" runnerv1 "gitea.dev/actionslib/runner/v1" - log "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "google.golang.org/protobuf/types/known/structpb" @@ -146,12 +146,12 @@ func TestRunPostTaskScriptIntegration(t *testing.T) { func setReporterJobResult(t *testing.T, reporter *report.Reporter, result runnerv1.Result) { t.Helper() - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, reporter.Handle(t.Context(), logging.Record{ Time: time.Now(), Message: "job finished", - Data: log.Fields{ - "stage": "Post", - "jobResult": metrics.ResultToStatusLabel(result), + Attrs: []logging.Attr{ + {Key: "stage", Value: "Post"}, + {Key: "jobResult", Value: metrics.ResultToStatusLabel(result)}, }, })) } diff --git a/internal/app/run/runner.go b/internal/app/run/runner.go index fda09012..84c90158 100644 --- a/internal/app/run/runner.go +++ b/internal/app/run/runner.go @@ -28,6 +28,7 @@ import ( "gitea.com/gitea/runner/act/artifactcache" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/container" "gitea.com/gitea/runner/act/runner" "gitea.com/gitea/runner/internal/pkg/client" @@ -109,7 +110,7 @@ func NewRunner(cfg *config.Config, reg *config.Registration, cli client.Client) Upstream: cfg.Cache.ExternalServer, S3: cacheS3(cfg), Policy: CachePolicy(cfg), - Logger: log.StandardLogger().WithField("module", "cache_request"), + Logger: logging.Default().With("module", "cache_request"), }) if err != nil { log.Errorf("cannot init cache server, it will be disabled: %v", err) @@ -645,7 +646,7 @@ func (r *Runner) run(ctx context.Context, task *runnerv1.Task, reporter *report. reporter.Logf("workflow prepared") // add logger recorders - ctx = common.WithLoggerHook(ctx, reporter) + ctx = common.WithLoggerHandler(ctx, reporter) if !log.IsLevelEnabled(log.DebugLevel) { ctx = runner.WithJobLoggerFactory(ctx, NullLogger{}) diff --git a/internal/app/run/runner_test.go b/internal/app/run/runner_test.go index aacae44c..de2d02a5 100644 --- a/internal/app/run/runner_test.go +++ b/internal/app/run/runner_test.go @@ -18,6 +18,7 @@ import ( "time" "gitea.com/gitea/runner/act/common" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/runner" clientmocks "gitea.com/gitea/runner/internal/pkg/client/mocks" "gitea.com/gitea/runner/internal/pkg/config" @@ -79,9 +80,9 @@ func TestRunnerRunningCountAndNullLogger(t *testing.T) { r.runningCount.Add(2) require.Equal(t, int64(2), r.RunningCount()) - logger := NullLogger{}.WithJobLogger() - require.NotNil(t, logger) - require.NotNil(t, logger.Out) + handler := NullLogger{}.WithJobLogger() + require.NotNil(t, handler) + require.False(t, handler.Enabled(t.Context(), logging.LevelError)) } func TestRunnerReclaimsVolumesAfterReporting(t *testing.T) { diff --git a/internal/pkg/report/joblog_test.go b/internal/pkg/report/joblog_test.go index f3d801df..d43f867c 100644 --- a/internal/pkg/report/joblog_test.go +++ b/internal/pkg/report/joblog_test.go @@ -11,12 +11,12 @@ import ( "testing" "time" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/internal/pkg/client/mocks" "gitea.com/gitea/runner/internal/pkg/config" connect_go "connectrpc.com/connect" runnerv1 "gitea.dev/actionslib/runner/v1" - log "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" @@ -52,10 +52,10 @@ func TestJobLog_MirrorsUploadedRows(t *testing.T) { reporter.ResetSteps(1) fire := func(message string) { - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: message, - Level: log.InfoLevel, - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Level: logging.LevelInfo, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, })) } fire("the token is s3cret-value") diff --git a/internal/pkg/report/reporter.go b/internal/pkg/report/reporter.go index cecbdec7..d9894947 100644 --- a/internal/pkg/report/reporter.go +++ b/internal/pkg/report/reporter.go @@ -8,11 +8,13 @@ import ( "errors" "fmt" "regexp" + "slices" "strings" "sync" "sync/atomic" "time" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/runner" "gitea.com/gitea/runner/internal/pkg/client" "gitea.com/gitea/runner/internal/pkg/config" @@ -166,8 +168,30 @@ func (r *Reporter) ResetSteps(l int) { } } -func (r *Reporter) Levels() []log.Level { - return log.AllLevels +// Enabled makes the Reporter see every record, the job logger's level filter runs before it. +func (r *Reporter) Enabled(context.Context, logging.Level) bool { return true } + +// WithAttrs returns a Handler feeding the same Reporter, with attrs added to every record. +func (r *Reporter) WithAttrs(attrs []logging.Attr) logging.Handler { + return &reporterHandler{r: r, attrs: attrs} +} + +type reporterHandler struct { + r *Reporter + attrs []logging.Attr +} + +func (h *reporterHandler) Enabled(ctx context.Context, level logging.Level) bool { + return h.r.Enabled(ctx, level) +} + +func (h *reporterHandler) Handle(ctx context.Context, rec logging.Record) error { + rec.Attrs = slices.Concat(h.attrs, rec.Attrs) + return h.r.Handle(ctx, rec) +} + +func (h *reporterHandler) WithAttrs(attrs []logging.Attr) logging.Handler { + return &reporterHandler{r: h.r, attrs: slices.Concat(h.attrs, attrs)} } // appendLogRow masks a row before buffering it for Gitea and the local job.log, the one point @@ -181,11 +205,19 @@ func (r *Reporter) appendLogRow(row *runnerv1.LogRow) { r.jobLog.write(row.Time.AsTime(), row.Content) } +func attrArgs(attrs []logging.Attr) []any { + args := make([]any, len(attrs)) + for i, a := range attrs { + args[i] = a + } + return args +} + // isJobStepEntry is used to not report composite step results incorrectly as step result // returns true if the logentry is on job level // returns false for composite action step messages -func isJobStepEntry(entry *log.Entry) bool { - if v, ok := entry.Data["stepID"]; ok { +func isJobStepEntry(rec logging.Record) bool { + if v, ok := rec.Attr("stepID"); ok { if v, ok := v.([]string); ok && len(v) > 1 { return false } @@ -219,15 +251,15 @@ func (r *Reporter) unlockAndNotify(urgentState bool) { } } -func (r *Reporter) Fire(entry *log.Entry) error { +func (r *Reporter) Handle(_ context.Context, entry logging.Record) error { urgentState := false r.stateMu.Lock() r.stateChanged = true - if log.IsLevelEnabled(log.TraceLevel) { - log.WithFields(entry.Data).Trace(r.mask(entry.Message)) // the process masker has no ::add-mask:: value + if logging.Enabled(logging.LevelTrace) { + logging.With(attrArgs(entry.Attrs)...).Trace(r.mask(entry.Message)) // the process masker has no ::add-mask:: value } timestamp := entry.Time @@ -235,10 +267,10 @@ func (r *Reporter) Fire(entry *log.Entry) error { r.state.StartedAt = timestamppb.New(timestamp) } - stage := entry.Data["stage"] + stage, _ := entry.Attr("stage") if stage != "Main" { - if v, ok := entry.Data["jobResult"]; ok { + if v, ok := entry.Attr("jobResult"); ok { if jobResult, ok := r.parseResult(v); ok { // We need to ensure log upload before this upload r.state.Result = jobResult @@ -262,7 +294,7 @@ func (r *Reporter) Fire(entry *log.Entry) error { } var step *runnerv1.StepState - if v, ok := entry.Data["stepNumber"]; ok { + if v, ok := entry.Attr("stepNumber"); ok { if v, ok := v.(int); ok && len(r.state.Steps) > v { step = r.state.Steps[v] } @@ -284,11 +316,12 @@ func (r *Reporter) Fire(entry *log.Entry) error { } // Force reporting log errors as raw output to prevent silent failures - if entry.Level == log.ErrorLevel { - entry.Data["raw_output"] = true + v, ok := entry.Attr("raw_output") + if entry.Level >= logging.LevelError { + v, ok = true, true } - if v, ok := entry.Data["raw_output"]; ok { + if ok { if rawOutput, ok := v.(bool); ok && rawOutput { if row := r.parseLogRow(entry); row != nil { if step.LogLength == 0 { @@ -301,7 +334,7 @@ func (r *Reporter) Fire(entry *log.Entry) error { } else if r.shouldAppendLogRow(entry) { r.appendLogRow(r.parseLogRow(entry)) } - if v, ok := entry.Data["stepResult"]; ok && isJobStepEntry(entry) { + if v, ok := entry.Attr("stepResult"); ok && isJobStepEntry(entry) { if stepResult, ok := r.parseResult(v); ok { if step.LogLength == 0 { step.LogIndex = int64(r.logOffset + len(r.logRows)) @@ -671,7 +704,7 @@ func (r *Reporter) ReportState(reportResult bool) error { r.outputsMu.Unlock() // Consume stateChanged atomically with the snapshot; restored on error - // below so a concurrent Fire() during UpdateTask isn't silently lost. + // below so a log record handled during UpdateTask isn't silently lost. // Heartbeat at stateReportInterval even when nothing changed, so the server // doesn't time out long-running silent jobs as orphaned (#826). last := r.lastReportedAtNanos.Load() @@ -753,8 +786,8 @@ func (r *Reporter) duringSteps() bool { // shouldAppendLogRow reports whether a non-raw_output entry should be written // to the job log: only when we are between steps and the entry's level is // within the globally configured log level. -func (r *Reporter) shouldAppendLogRow(entry *log.Entry) bool { - return !r.duringSteps() && entry.Level <= log.GetLevel() +func (r *Reporter) shouldAppendLogRow(entry logging.Record) bool { + return !r.duringSteps() && entry.Level >= logging.GetLevel() } var stringToResult = map[string]runnerv1.Result{ @@ -879,7 +912,7 @@ func cutPrefixFold(s, prefix string) (string, bool) { return s[len(prefix):], true } -func (r *Reporter) parseLogRow(entry *log.Entry) *runnerv1.LogRow { +func (r *Reporter) parseLogRow(entry logging.Record) *runnerv1.LogRow { content := strings.TrimRight(entry.Message, "\r\n") // cmdRegex only covers the ::cmd:: form, so the ##[add-mask] one would otherwise reach diff --git a/internal/pkg/report/reporter_test.go b/internal/pkg/report/reporter_test.go index 6b4cb507..1f4b3f32 100644 --- a/internal/pkg/report/reporter_test.go +++ b/internal/pkg/report/reporter_test.go @@ -17,6 +17,7 @@ import ( "testing" "time" + "gitea.com/gitea/runner/act/common/logging" "gitea.com/gitea/runner/act/runner" "gitea.com/gitea/runner/internal/pkg/client/mocks" "gitea.com/gitea/runner/internal/pkg/config" @@ -25,7 +26,6 @@ import ( connect_go "connectrpc.com/connect" "gitea.dev/actionslib/pkg/model" runnerv1 "gitea.dev/actionslib/runner/v1" - log "github.com/sirupsen/logrus" logrustest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" @@ -206,7 +206,7 @@ func TestReporter_parseLogRow(t *testing.T) { debugOutputEnabled: tt.debugOutputEnabled, } for idx, arg := range tt.args { - rv := r.parseLogRow(&log.Entry{Message: arg}) + rv := r.parseLogRow(logging.Record{Message: arg}) got := "" if rv != nil { @@ -225,13 +225,13 @@ func TestReporter_parseLogRowAddMask(t *testing.T) { for _, line := range []string{"::add-mask::supersecret", "##[add-mask]supersecret"} { r := &Reporter{logReplacer: strings.NewReplacer()} - assert.Nil(t, r.parseLogRow(&log.Entry{Message: line}), line) + assert.Nil(t, r.parseLogRow(logging.Record{Message: line}), line) assert.Equal(t, "using *** now", r.mask("using supersecret now"), line) } } -func TestReporter_Fire(t *testing.T) { +func TestReporter_Handle(t *testing.T) { t.Run("ignore command lines", func(t *testing.T) { client := mocks.NewClient(t) client.On("UpdateLog", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateLogRequest]) (*connect_go.Response[runnerv1.UpdateLogResponse], error) { @@ -263,13 +263,13 @@ func TestReporter_Fire(t *testing.T) { "raw_output": true, } - require.NoError(t, reporter.Fire(&log.Entry{Message: "regular log line", Data: dataStep0})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "::debug::debug log line", Data: dataStep0})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "regular log line", Data: dataStep0})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "::debug::debug log line", Data: dataStep0})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "::debug::debug log line", Data: dataStep0})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "regular log line", Data: dataStep0})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "composite step result", Data: map[string]any{ + require.NoError(t, fire(reporter, logEntry{Message: "regular log line", Data: dataStep0})) + require.NoError(t, fire(reporter, logEntry{Message: "::debug::debug log line", Data: dataStep0})) + require.NoError(t, fire(reporter, logEntry{Message: "regular log line", Data: dataStep0})) + require.NoError(t, fire(reporter, logEntry{Message: "::debug::debug log line", Data: dataStep0})) + require.NoError(t, fire(reporter, logEntry{Message: "::debug::debug log line", Data: dataStep0})) + require.NoError(t, fire(reporter, logEntry{Message: "regular log line", Data: dataStep0})) + require.NoError(t, fire(reporter, logEntry{Message: "composite step result", Data: map[string]any{ "stage": "Main", "stepID": []string{"0", "0"}, "stepNumber": 0, @@ -277,7 +277,7 @@ func TestReporter_Fire(t *testing.T) { "stepResult": model.StepStatusFailure, }})) assert.Equal(t, runnerv1.Result_RESULT_UNSPECIFIED, reporter.state.Steps[0].Result) - require.NoError(t, reporter.Fire(&log.Entry{Message: "step result", Data: map[string]any{ + require.NoError(t, fire(reporter, logEntry{Message: "step result", Data: map[string]any{ "stage": "Main", "stepNumber": 0, "raw_output": true, @@ -291,9 +291,9 @@ func TestReporter_Fire(t *testing.T) { func TestReporter_LogLevelFiltering(t *testing.T) { // Set global level to Info so Debug entries should be filtered. - origLevel := log.GetLevel() - log.SetLevel(log.InfoLevel) - defer log.SetLevel(origLevel) + origLevel := logging.GetLevel() + logging.SetLevel(logging.LevelInfo) + defer logging.SetLevel(origLevel) client := mocks.NewClient(t) client.On("UpdateLog", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateLogRequest]) (*connect_go.Response[runnerv1.UpdateLogResponse], error) { @@ -316,27 +316,27 @@ func TestReporter_LogLevelFiltering(t *testing.T) { }() reporter.ResetSteps(2) - dataStep0 := log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true} - dataStep0Internal := log.Fields{"stage": "Main", "stepNumber": 0} + dataStep0 := map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true} + dataStep0Internal := map[string]any{"stage": "Main", "stepNumber": 0} // raw_output entries always appear in job log regardless of level. - require.NoError(t, reporter.Fire(&log.Entry{Message: "step output", Data: dataStep0, Level: log.InfoLevel})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "step debug output", Data: dataStep0, Level: log.DebugLevel})) + require.NoError(t, fire(reporter, logEntry{Message: "step output", Data: dataStep0, Level: logging.LevelInfo})) + require.NoError(t, fire(reporter, logEntry{Message: "step debug output", Data: dataStep0, Level: logging.LevelDebug})) assert.Equal(t, int64(2), reporter.state.Steps[0].LogLength, "raw_output entries must always be forwarded") // Non-raw_output entries during steps are not added to logRows regardless of level. - require.NoError(t, reporter.Fire(&log.Entry{Message: "internal info", Data: dataStep0Internal, Level: log.InfoLevel})) - require.NoError(t, reporter.Fire(&log.Entry{Message: "internal debug", Data: dataStep0Internal, Level: log.DebugLevel})) + require.NoError(t, fire(reporter, logEntry{Message: "internal info", Data: dataStep0Internal, Level: logging.LevelInfo})) + require.NoError(t, fire(reporter, logEntry{Message: "internal debug", Data: dataStep0Internal, Level: logging.LevelDebug})) // stepResult at DebugLevel (skipped step) must still update state even when filtered from log. - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "Skipping step", - Data: log.Fields{ + Data: map[string]any{ "stage": "Main", "stepNumber": 1, "stepResult": "skipped", }, - Level: log.DebugLevel, + Level: logging.LevelDebug, })) assert.Equal(t, runnerv1.Result_RESULT_SKIPPED, reporter.state.Steps[1].Result, "stepResult at DebugLevel must update step state even when log entry is filtered from job log output") @@ -383,9 +383,9 @@ func TestReporter_EphemeralRunnerDeletion(t *testing.T) { reporter.ResetSteps(1) // Fire a log entry to create pending data - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "build output", - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, })) // Step 1: RunDaemon calls ReportLog(false) — runner is still alive @@ -500,9 +500,9 @@ func TestReporter_MaxLatencyTimer(t *testing.T) { }() // Fire a single log line — not enough to trigger batch flush - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "single log line", - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, })) // maxLatencyTimer should flush within ~100ms. Wait up to 500ms. @@ -552,9 +552,9 @@ func TestReporter_BatchSizeFlush(t *testing.T) { // Fire exactly batchSize log lines for i := range 5 { - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: fmt.Sprintf("log line %d", i), - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, })) } @@ -565,7 +565,7 @@ func TestReporter_BatchSizeFlush(t *testing.T) { "batch size threshold should have triggered immediate flush") } -// TestReporter_StateChangedNotLostDuringReport asserts that a Fire() arriving +// TestReporter_StateChangedNotLostDuringReport asserts that a log record arriving // mid-UpdateTask re-dirties the flag so the change is picked up by the next report. func TestReporter_StateChangedNotLostDuringReport(t *testing.T) { var updateTaskCalls atomic.Int64 @@ -607,11 +607,11 @@ func TestReporter_StateChangedNotLostDuringReport(t *testing.T) { // Wait until UpdateTask is in flight (snapshot taken, flag consumed). <-inFlight - // Concurrent Fire() modifies state — must re-flip stateChanged so the + // A concurrent log record modifies state — must re-flip stateChanged so the // change is not lost when the in-flight ReportState finishes. - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "step starts", - Data: log.Fields{"stage": "Main", "stepNumber": 1, "raw_output": true}, + Data: map[string]any{"stage": "Main", "stepNumber": 1, "raw_output": true}, })) // Release the in-flight UpdateTask and wait for it to return. @@ -619,15 +619,15 @@ func TestReporter_StateChangedNotLostDuringReport(t *testing.T) { require.NoError(t, <-done) // stateChanged must still be true so the next ReportState picks up the - // concurrent Fire()'s change instead of skipping via the early-return path. + // concurrent record's change instead of skipping via the early-return path. reporter.stateMu.RLock() changed := reporter.stateChanged reporter.stateMu.RUnlock() - assert.True(t, changed, "stateChanged must remain true after a concurrent Fire() during in-flight ReportState") + assert.True(t, changed, "stateChanged must remain true after a concurrent log record during in-flight ReportState") // And the next ReportState must actually send a second UpdateTask. require.NoError(t, reporter.ReportState(false)) - assert.Equal(t, int64(2), updateTaskCalls.Load(), "concurrent Fire() change must trigger a second UpdateTask, not be silently lost") + assert.Equal(t, int64(2), updateTaskCalls.Load(), "concurrent log record change must trigger a second UpdateTask, not be silently lost") } // TestReporter_StateChangedRestoredOnError verifies that when UpdateTask fails, @@ -709,9 +709,9 @@ func TestReporter_StateNotifyFlush(t *testing.T) { }() // Fire a log entry that starts a step — this triggers stateNotify - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "step starting", - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, })) // stateNotify should trigger immediate UpdateTask call @@ -1054,8 +1054,8 @@ func TestAppendLogRow(t *testing.T) { assert.Equal(t, "***", r.logRows[0].Content) } -func TestReporter_Levels(t *testing.T) { - assert.Equal(t, log.AllLevels, (&Reporter{}).Levels()) +func TestReporter_Enabled(t *testing.T) { + assert.True(t, (&Reporter{}).Enabled(t.Context(), logging.LevelTrace)) } func TestReporter_Result(t *testing.T) { @@ -1218,10 +1218,10 @@ func TestReporter_AckIndexBeyondBuffer(t *testing.T) { reporter := NewReporter(ctx, cancel, client, &runnerv1.Task{Context: taskCtx}, cfg) reporter.ResetSteps(1) - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "hello", - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, - Level: log.InfoLevel, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Level: logging.LevelInfo, })) require.NoError(t, reporter.ReportLog(false)) @@ -1258,10 +1258,10 @@ func TestReporter_CloseWithStuckDaemon(t *testing.T) { reporter.RunDaemon() reporter.ResetSteps(1) - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: "hello", - Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true}, - Level: log.InfoLevel, + Data: map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true}, + Level: logging.LevelInfo, })) select { @@ -1441,17 +1441,17 @@ func TestReporter_StepRangeCoversAckedRows(t *testing.T) { _ = reporter.Close("") }() - stepData := log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true} + stepData := map[string]any{"stage": "Main", "stepNumber": 0, "raw_output": true} // The step's first row is a transition, so it flushes state as well as logs. - require.NoError(t, reporter.Fire(&log.Entry{Message: "step starting", Data: stepData})) + require.NoError(t, fire(reporter, logEntry{Message: "step starting", Data: stepData})) require.Eventually(t, func() bool { rows, claimed := server.snapshot() return rows == 1 && claimed == rows }, time.Second, 10*time.Millisecond, "the step transition should have flushed both log and state") for i := range cfg.Runner.LogReportBatchSize { - require.NoError(t, reporter.Fire(&log.Entry{ + require.NoError(t, fire(reporter, logEntry{ Message: fmt.Sprintf("step output %d", i), Data: stepData, })) @@ -1489,3 +1489,18 @@ func TestReporter_FlushWithoutAckedRowsSkipsState(t *testing.T) { reporter.Logf("row") reporter.reportLogWithState() } + +// logEntry is the record a job logger hands the Reporter, with the fields it accumulated as Data. +type logEntry struct { + Message string + Data map[string]any + Level logging.Level +} + +func fire(r *Reporter, e logEntry) error { + attrs := make([]logging.Attr, 0, len(e.Data)) + for k, v := range e.Data { + attrs = append(attrs, logging.Attr{Key: k, Value: v}) + } + return r.WithAttrs(attrs).Handle(context.Background(), logging.Record{Message: e.Message, Level: e.Level}) +}