diff --git a/.golangci.yml b/.golangci.yml index 4ec18eda..f6b61763 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -39,13 +39,15 @@ linters: deny: - pkg: golang.org/x/exp desc: it's experimental and unreliable - logrus: + logging: files: - $all - "!**/act/common/logging/**" deny: - pkg: github.com/sirupsen/logrus desc: log through gitea.com/gitea/runner/act/common/logging + - pkg: log/slog + desc: log through gitea.com/gitea/runner/act/common/logging nolintlint: allow-unused: false require-explanation: true diff --git a/act/common/logging/console.go b/act/common/logging/console.go new file mode 100644 index 00000000..1b0bb22b --- /dev/null +++ b/act/common/logging/console.go @@ -0,0 +1,287 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package logging + +import ( + "bytes" + "context" + "fmt" + "io" + "log/slog" + "reflect" + "runtime" + "slices" + "strconv" + "strings" + "sync" + "time" +) + +const ( + ansiReset = "\x1b[0m" + ansiRed = "\x1b[31m" + ansiYellow = "\x1b[33m" + ansiCyan = "\x1b[36m" + ansiDimCyan = "\x1b[2;36m" + ansiDimWhite = "\x1b[2;37m" +) + +// consoleStart is the zero of the elapsed-seconds stamp used when full timestamps are off. +var consoleStart = time.Now() + +// console is the state shared by every consoleHandler derived from one another. +type console struct { + mu sync.Mutex + out io.Writer + terminal bool + opts TextOptions + reportCaller bool + level slog.LevelVar +} + +func newConsole(out io.Writer) *console { + c := &console{} + c.setOutput(out) + return c +} + +func (c *console) setOutput(w io.Writer) { + terminal := checkIfTerminal(w) + c.mu.Lock() + defer c.mu.Unlock() + c.out, c.terminal = w, terminal +} + +// consoleHandler is a slog.Handler writing the text format the runner has always used, so that +// moving off logrus changes nothing a user can see: sorted key=value fields on a plain stream, +// and a colored prefix with elapsed or full time on a terminal. +type consoleHandler struct { + c *console + attrs []slog.Attr +} + +func (h *consoleHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.c.level.Level() +} + +func (h *consoleHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &consoleHandler{c: h.c, attrs: append(slices.Clone(h.attrs), attrs...)} +} + +// WithGroup is a no-op, as only NewSlogHandler wraps a consoleHandler and it never groups. +func (h *consoleHandler) WithGroup(string) slog.Handler { return h } + +func (h *consoleHandler) Handle(_ context.Context, r slog.Record) error { + c := h.c + c.mu.Lock() + opts, reportCaller, terminal := c.opts, c.reportCaller, c.terminal + c.mu.Unlock() + + data := make(map[string]any, len(h.attrs)+r.NumAttrs()) + for _, a := range h.attrs { + data[a.Key] = a.Value.Resolve().Any() + } + r.Attrs(func(a slog.Attr) bool { + data[a.Key] = a.Value.Resolve().Any() + return true + }) + + var caller *runtime.Frame + if reportCaller && r.PC != 0 { + frame, _ := runtime.CallersFrames([]uintptr{r.PC}).Next() + caller = &frame + } + prefixFieldClashes(data, caller != nil) + + keys := make([]string, 0, len(data)) + for k := range data { + keys = append(keys, k) + } + slices.Sort(keys) + + var b bytes.Buffer + if terminal && !opts.DisableColors { + printColored(&b, opts, r, caller, keys, data) + } else { + printPlain(&b, opts, r, caller, keys, data) + } + + line := b.Bytes() + if opts.Filter != nil { + line = opts.Filter(line) + } + c.mu.Lock() + defer c.mu.Unlock() + _, err := c.out.Write(line) + return err +} + +// prefixFieldClashes moves fields that share a name with a fixed key out of its way. +func prefixFieldClashes(data map[string]any, reportCaller bool) { + for _, key := range []string{"time", "level", "msg"} { + if v, ok := data[key]; ok { + data["fields."+key] = v + delete(data, key) + } + } + if reportCaller { + for _, key := range []string{"func", "file"} { + if v, ok := data[key]; ok { + data["fields."+key] = v + } + } + } +} + +func printPlain(b *bytes.Buffer, opts TextOptions, r slog.Record, caller *runtime.Frame, keys []string, data map[string]any) { + if !opts.DisableTimestamp { + appendKeyValue(b, "time", r.Time.Format(time.RFC3339)) + } + appendKeyValue(b, "level", plainLevel(Level(r.Level))) + if r.Message != "" { + appendKeyValue(b, "msg", r.Message) + } + if caller != nil { + funcVal, fileVal := callerText(opts, caller) + if funcVal != "" { + appendKeyValue(b, "func", funcVal) + } + if fileVal != "" { + appendKeyValue(b, "file", fileVal) + } + } + for _, k := range keys { + appendKeyValue(b, k, data[k]) + } + b.WriteByte('\n') +} + +func callerText(opts TextOptions, caller *runtime.Frame) (funcVal, fileVal string) { + if opts.CallerPrettyfier != nil { + return opts.CallerPrettyfier(caller) + } + return caller.Function, caller.File + ":" + strconv.Itoa(caller.Line) +} + +func printColored(b *bytes.Buffer, opts TextOptions, r slog.Record, caller *runtime.Frame, keys []string, data map[string]any) { + msg := strings.TrimSuffix(r.Message, "\n") + + var callerStr string + if caller != nil { + funcVal, fileVal := callerText(opts, caller) + if opts.CallerPrettyfier == nil && caller.Function != "" { + funcVal += "()" + } + switch { + case fileVal == "": + callerStr = funcVal + case funcVal == "": + callerStr = fileVal + default: + callerStr = fileVal + " " + funcVal + } + } + + level := Level(r.Level) + prefix := colorize(level, strings.ToUpper(plainLevel(level))[:4]) + switch { + case opts.DisableTimestamp: + fmt.Fprintf(b, "%s%s %-44s ", prefix, callerStr, msg) + case !opts.FullTimestamp: + fmt.Fprintf(b, "%s[%04d]%s %-44s ", prefix, int(r.Time.Sub(consoleStart)/time.Second), callerStr, msg) + default: + fmt.Fprintf(b, "%s[%s]%s %-44s ", prefix, r.Time.Format(time.RFC3339), callerStr, msg) + } + for _, k := range keys { + b.WriteByte(' ') + b.WriteString(colorize(level, k)) + b.WriteByte('=') + appendValue(b, data[k]) + } + b.WriteByte('\n') +} + +// plainLevel spells Warn the way logrus did, as "warning". +func plainLevel(l Level) string { + if s := l.String(); s != "warn" { + return s + } + return "warning" +} + +func colorize(l Level, s string) string { + var color string + switch { + case l <= LevelTrace: + color = ansiDimWhite + case l <= LevelDebug: + color = ansiDimCyan + case l <= LevelInfo: + color = ansiCyan + case l <= LevelWarn: + color = ansiYellow + default: + color = ansiRed + } + return color + s + ansiReset +} + +func appendKeyValue(b *bytes.Buffer, key string, value any) { + if b.Len() > 0 { + b.WriteByte(' ') + } + b.WriteString(key) + b.WriteByte('=') + appendValue(b, value) +} + +func appendValue(b *bytes.Buffer, value any) { + switch v := value.(type) { + case string: + appendString(b, v) + case []byte: + appendString(b, string(v)) + case error: + appendFormatted(b, v, v.Error) + case fmt.Stringer: + appendFormatted(b, v, v.String) + default: + appendString(b, fmt.Sprint(value)) + } +} + +// appendFormatted writes what get returns, and "" if that panics on a nil receiver. +func appendFormatted(b *bytes.Buffer, v any, get func() string) { + defer func() { + if r := recover(); r != nil { + if rv := reflect.ValueOf(v); rv.Kind() == reflect.Pointer && rv.IsNil() { + appendString(b, "") + } else { + appendString(b, fmt.Sprintf("%%!v(PANIC=%v)", r)) + } + } + }() + appendString(b, get()) +} + +func appendString(b *bytes.Buffer, s string) { + if needsQuoting(s) { + b.WriteString(strconv.Quote(s)) + return + } + b.WriteString(s) +} + +func needsQuoting(s string) bool { + for i := range len(s) { + c := s[i] + switch { + case c >= 'a' && c <= 'z', c >= 'A' && c <= 'Z', c >= '0' && c <= '9': + case c == '-', c == '.', c == '_', c == '/', c == '@', c == '^', c == '+': + default: + return true + } + } + return false +} diff --git a/act/common/logging/console_test.go b/act/common/logging/console_test.go new file mode 100644 index 00000000..8ca0fe07 --- /dev/null +++ b/act/common/logging/console_test.go @@ -0,0 +1,78 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package logging + +import ( + "bytes" + "errors" + "log/slog" + "runtime" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func consoleLine(t *testing.T, opts TextOptions, terminal, reportCaller bool, build func(*Logger)) string { + t.Helper() + var out bytes.Buffer + c := newConsole(&out) + c.opts, c.terminal, c.reportCaller = opts, terminal, reportCaller + c.level.Set(slog.LevelDebug) + build(New(NewSlogHandler(&consoleHandler{c: c}))) + return out.String() +} + +func TestConsolePlain(t *testing.T) { + line := consoleLine(t, TextOptions{DisableTimestamp: true}, false, false, func(l *Logger) { + l.With("job", "build x", "n", 3).WithError(errors.New("boom")).Warnf("hello world") + l.With("msg", "clash", "empty", "").Info("") + }) + assert.Equal(t, "level=warning msg=\"hello world\" error=boom job=\"build x\" n=3\n"+ + "level=info empty= fields.msg=clash\n", line) +} + +func TestConsolePlainTimeFilterAndCaller(t *testing.T) { + opts := TextOptions{ + CallerPrettyfier: func(f *runtime.Frame) (string, string) { + return "[fn]", "[" + strings.TrimPrefix(f.Function, "x") + "]" + }, + Filter: func(b []byte) []byte { return bytes.ReplaceAll(b, []byte("secret"), []byte("***")) }, + } + line := consoleLine(t, opts, false, true, func(l *Logger) { l.With("k", "secret").Debugf("a secret") }) + assert.Regexp(t, `^time="[^"]+" level=debug msg="a \*\*\*" func="\[fn\]" file="\[.*TestConsolePlainTimeFilterAndCaller[^"]*\]" k=\*\*\*\n$`, line) +} + +func TestConsoleColored(t *testing.T) { + line := consoleLine(t, TextOptions{DisableTimestamp: true}, true, false, func(l *Logger) { + l.With("job", "j").Warn("careful") + }) + assert.Equal(t, "\x1b[33mWARN\x1b[0m "+"careful"+strings.Repeat(" ", 44-len("careful"))+" \x1b[33mjob\x1b[0m=j\n", line) + + full := consoleLine(t, TextOptions{FullTimestamp: true}, true, false, func(l *Logger) { l.Error("bad") }) + assert.Regexp(t, `^\x1b\[31mERRO\x1b\[0m\[\d{4}-\d\d-\d\dT[^\]]+\] bad`, full) + + elapsed := consoleLine(t, TextOptions{}, true, false, func(l *Logger) { l.Info("x") }) + assert.Regexp(t, `^\x1b\[36mINFO\x1b\[0m\[\d{4}\] x`, elapsed) + + plain := consoleLine(t, TextOptions{DisableColors: true, DisableTimestamp: true}, true, false, func(l *Logger) { l.Info("x") }) + assert.Equal(t, "level=info msg=x\n", plain) +} + +func TestConsoleLevelAndOutput(t *testing.T) { + var out bytes.Buffer + c := newConsole(&out) + h := &consoleHandler{c: c} + assert.False(t, h.Enabled(t.Context(), slog.LevelDebug)) // info unless raised + c.level.Set(slog.LevelError) + assert.False(t, h.Enabled(t.Context(), slog.LevelWarn)) + assert.True(t, h.Enabled(t.Context(), slog.LevelError)) + + rec := slog.NewRecord(time.Unix(0, 0), slog.LevelError, "m", 0) + rec.AddAttrs(slog.String("c", "3")) + require.NoError(t, h.WithAttrs([]slog.Attr{slog.Int("a", 1)}).Handle(t.Context(), rec)) + assert.Contains(t, out.String(), "a=1 c=3") +} diff --git a/act/common/logging/format.go b/act/common/logging/format.go deleted file mode 100644 index de1e8a64..00000000 --- a/act/common/logging/format.go +++ /dev/null @@ -1,50 +0,0 @@ -// Copyright 2026 The Gitea Authors. All rights reserved. -// SPDX-License-Identifier: MIT - -package logging - -import ( - "runtime" - - "github.com/sirupsen/logrus" -) - -// TextOptions describes how the process-wide Logger writes a record as text. -type TextOptions struct { - DisableColors bool - DisableTimestamp bool - FullTimestamp bool - // CallerPrettyfier renames the function and file reported with a record when ReportCaller is on. - CallerPrettyfier func(*runtime.Frame) (function, file string) - // Filter rewrites each formatted line, for example to mask secrets. - Filter func(line []byte) []byte -} - -// SetTextFormat sets the text format of the process-wide Logger. -func SetTextFormat(o TextOptions) { - logrus.SetFormatter(&filteringFormatter{ - inner: &logrus.TextFormatter{ - DisableColors: o.DisableColors, - DisableTimestamp: o.DisableTimestamp, - FullTimestamp: o.FullTimestamp, - CallerPrettyfier: o.CallerPrettyfier, - }, - filter: o.Filter, - }) -} - -// SetReportCaller makes the process-wide Logger record where each call came from, which costs time. -func SetReportCaller(on bool) { logrus.SetReportCaller(on) } - -type filteringFormatter struct { - inner logrus.Formatter - filter func([]byte) []byte -} - -func (f *filteringFormatter) Format(e *logrus.Entry) ([]byte, error) { - line, err := f.inner.Format(e) - if err != nil || f.filter == nil { - return line, err - } - return f.filter(line), nil -} diff --git a/act/common/logging/global.go b/act/common/logging/global.go index 62873733..f93ab868 100644 --- a/act/common/logging/global.go +++ b/act/common/logging/global.go @@ -5,15 +5,32 @@ package logging import ( "io" + "log/slog" + "os" + "runtime" "sync/atomic" "github.com/sirupsen/logrus" ) -var std atomic.Pointer[Logger] +// TextOptions describes how the process-wide Logger writes a record as text. +type TextOptions struct { + DisableColors bool + DisableTimestamp bool + FullTimestamp bool + // CallerPrettyfier renames the function and file reported with a record when ReportCaller is on. + CallerPrettyfier func(*runtime.Frame) (function, file string) + // Filter rewrites each formatted line, for example to mask secrets. + Filter func(line []byte) []byte +} + +var ( + std atomic.Pointer[Logger] + stdState = newConsole(os.Stderr) +) func init() { - std.Store(New(NewLogrusHandler(logrus.StandardLogger()))) + std.Store(New(NewSlogHandler(&consoleHandler{c: stdState}))) } // Default returns the process-wide Logger. @@ -21,20 +38,42 @@ func Default() *Logger { return std.Load() } // SetDefault replaces the process-wide Logger, which tests use to capture what the package // functions log. SetLevel, GetLevel, SetOutput and the format functions keep configuring the -// initial logrus-backed Logger. +// initial console Logger. func SetDefault(l *Logger) { std.Store(l) } -// SetLevel sets the minimum level of the process-wide Logger. -func SetLevel(level Level) { logrus.SetLevel(toLogrusLevel(level)) } +// SetLevel sets the minimum level of the initial process-wide Logger and of what libraries log through logrus. +func SetLevel(level Level) { + stdState.level.Set(slog.Level(level)) + logrus.SetLevel(toLogrusLevel(level)) +} -// GetLevel returns the minimum level of the process-wide Logger. -func GetLevel() Level { return fromLogrusLevel(logrus.GetLevel()) } +// GetLevel returns the minimum level of the initial process-wide Logger. +func GetLevel() Level { return Level(stdState.level.Level()) } -// SetOutput sets where the process-wide Logger writes. -func SetOutput(w io.Writer) { logrus.SetOutput(w) } +// SetOutput sets where the initial process-wide Logger writes. +func SetOutput(w io.Writer) { stdState.setOutput(w) } -// Output returns where the process-wide Logger writes. -func Output() io.Writer { return logrus.StandardLogger().Out } +// Output returns where the initial process-wide Logger writes. +func Output() io.Writer { + stdState.mu.Lock() + defer stdState.mu.Unlock() + return stdState.out +} + +// SetTextFormat sets the text format of the initial process-wide Logger. +func SetTextFormat(o TextOptions) { + stdState.mu.Lock() + defer stdState.mu.Unlock() + stdState.opts = o +} + +// SetReportCaller makes the initial process-wide Logger record where each call came from, which costs time. +func SetReportCaller(on bool) { + stdState.mu.Lock() + defer stdState.mu.Unlock() + stdState.reportCaller = on + logrus.SetReportCaller(on) +} func Enabled(level Level) bool { return Default().Enabled(level) } diff --git a/act/common/logging/logging_test.go b/act/common/logging/logging_test.go index 517275c8..ae1c4aec 100644 --- a/act/common/logging/logging_test.go +++ b/act/common/logging/logging_test.go @@ -5,17 +5,15 @@ package logging_test import ( "errors" - "io" + "log/slog" "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" ) @@ -95,62 +93,19 @@ func TestCallerPC(t *testing.T) { l, h := logtest.NewLogger() 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 := logging.Output(), std.ReportCaller, std.ReplaceHooks(logrus.LevelHooks{}) - t.Cleanup(func() { - logging.SetOutput(prevOut) - std.SetReportCaller(prevCaller) - std.ReplaceHooks(prevHooks) - }) - logging.SetOutput(io.Discard) - std.SetReportCaller(true) - hook := logrustest.NewGlobal() + prev := logging.Default() + t.Cleanup(func() { logging.SetDefault(prev) }) + logging.SetDefault(l) 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) + require.Len(t, h.AllRecords(), 4) + for _, r := range h.AllRecords() { + assert.True(t, strings.HasSuffix(frameOf(t, r.PC).Function, "TestCallerPC"), r.Message) } } -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) }) @@ -160,3 +115,72 @@ func TestDefaultLevel(t *testing.T) { assert.True(t, logging.Enabled(logging.LevelError)) assert.False(t, logging.Enabled(logging.LevelInfo)) } + +func TestSlogHandler(t *testing.T) { + var buf strings.Builder + slogger := slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})) + l := logging.New(logging.NewSlogHandler(slogger.Handler())).With("job", "j1") + + l.Tracef("dropped") + assert.False(t, l.Enabled(logging.LevelTrace)) + l.WithError(errors.New("boom")).Errorf("fail %s", "x") + + out := buf.String() + assert.Contains(t, out, "level=ERROR") + assert.Contains(t, out, `msg="fail x"`) + assert.Contains(t, out, "job=j1") + assert.Contains(t, out, "error=boom") +} + +func TestLogrusBridge(t *testing.T) { + prevLevel, prevDefault := logging.GetLevel(), logging.Default() + t.Cleanup(func() { + logging.SetLevel(prevLevel) + logging.SetReportCaller(false) + logging.SetDefault(prevDefault) + }) + logging.SetLevel(logging.LevelInfo) + assert.False(t, logrus.IsLevelEnabled(logrus.DebugLevel)) + logging.SetLevel(logging.LevelTrace) + logging.SetReportCaller(true) + h := logtest.NewWithLevel(logging.LevelTrace) + logging.SetDefault(logging.New(h)) + + logrus.WithField("lib", "docker").Warnf("from a library %d", 1) + _, _, line, _ := runtime.Caller(0) + logrus.Debug("below") + logrus.Trace("lowest") + + recs := h.AllRecords() + require.Len(t, recs, 3) + assert.Equal(t, "from a library 1", recs[0].Message) + assert.Equal(t, logging.LevelWarn, recs[0].Level) + v, _ := recs[0].Attr("lib") + assert.Equal(t, "docker", v) + assert.Equal(t, logging.LevelDebug, recs[1].Level) + f := frameOf(t, recs[1].PC) + assert.True(t, strings.HasSuffix(f.Function, "TestLogrusBridge"), f.Function) + assert.Equal(t, line+1, f.Line) + assert.Equal(t, logging.LevelTrace, recs[2].Level) + + h = logtest.New() // logrus passes Debug, the Logger does not + logging.SetDefault(logging.New(h)) + logrus.Debug("dropped") + assert.Empty(t, h.AllRecords()) +} + +func TestLogrusBridgeIntact(t *testing.T) { + assert.True(t, logging.LogrusBridgeIntact()) + + prev := logrus.StandardLogger().Out + t.Cleanup(func() { logrus.SetOutput(prev) }) + logrus.SetOutput(&strings.Builder{}) // what a dependency doing this would do + assert.False(t, logging.LogrusBridgeIntact()) + logrus.SetOutput(prev) + assert.True(t, logging.LogrusBridgeIntact()) + + prevLevel := logrus.GetLevel() + t.Cleanup(func() { logrus.SetLevel(prevLevel) }) + logrus.SetLevel(logrus.PanicLevel) + assert.False(t, logging.LogrusBridgeIntact()) +} diff --git a/act/common/logging/logrus.go b/act/common/logging/logrus.go deleted file mode 100644 index c7c4116b..00000000 --- a/act/common/logging/logrus.go +++ /dev/null @@ -1,87 +0,0 @@ -// 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/logrus_bridge.go b/act/common/logging/logrus_bridge.go new file mode 100644 index 00000000..a5d3ac88 --- /dev/null +++ b/act/common/logging/logrus_bridge.go @@ -0,0 +1,102 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package logging + +import ( + "context" + "io" + + "github.com/sirupsen/logrus" +) + +// Libraries the runner depends on, such as the workflow model and the Docker client, log through +// logrus's global logger. Hand what they log to the process-wide Logger, so it follows the same +// level, format and secret masking as the rest of the output. +func init() { + logrus.SetOutput(io.Discard) + logrus.SetFormatter(discardFormatter{}) + logrus.SetLevel(toLogrusLevel(GetLevel())) + logrus.AddHook(bridgeHook{}) +} + +type discardFormatter struct{} + +func (discardFormatter) Format(*logrus.Entry) ([]byte, error) { return nil, nil } + +type bridgeHook struct{} + +func (bridgeHook) Levels() []logrus.Level { return logrus.AllLevels } + +func (bridgeHook) Fire(e *logrus.Entry) error { + l := Default() + level := fromLogrusLevel(e.Level) + ctx := e.Context + if ctx == nil { + ctx = context.Background() + } + if !l.h.Enabled(ctx, level) { + return nil + } + attrs := make([]Attr, 0, len(e.Data)) + for k, v := range e.Data { + attrs = append(attrs, Attr{Key: k, Value: v}) + } + r := Record{Time: e.Time, Level: level, Message: e.Message, Attrs: attrs} + if e.Caller != nil { + r.PC = e.Caller.PC + 1 // Frame.PC is one below the return address Record.PC holds + } + return l.h.Handle(ctx, r) +} + +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 + } +} + +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 + } +} + +// LogrusBridgeIntact reports whether logrus's global logger is still set up as the bridge needs, +// discarding its own output and following the process-wide level. A dependency that calls +// logrus.SetOutput or SetLevel breaks that, and its lines then show up twice, or at the wrong level. +func LogrusBridgeIntact() bool { + std := logrus.StandardLogger() + if std.Out != io.Discard || std.GetLevel() != toLogrusLevel(GetLevel()) { + return false + } + for _, level := range logrus.AllLevels { + found := false + for _, h := range std.Hooks[level] { + if _, ok := h.(bridgeHook); ok { + found = true + } + } + if !found { + return false + } + } + return true +} diff --git a/act/common/logging/slog.go b/act/common/logging/slog.go new file mode 100644 index 00000000..8f269861 --- /dev/null +++ b/act/common/logging/slog.go @@ -0,0 +1,40 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +package logging + +import ( + "context" + "log/slog" +) + +type slogHandler struct { + h slog.Handler +} + +// NewSlogHandler writes to h. Levels map one to one, as Level uses slog's values. +func NewSlogHandler(h slog.Handler) Handler { + return slogHandler{h: h} +} + +func (s slogHandler) Enabled(ctx context.Context, level Level) bool { + return s.h.Enabled(ctx, slog.Level(level)) +} + +func (s slogHandler) Handle(ctx context.Context, r Record) error { + rec := slog.NewRecord(r.Time, slog.Level(r.Level), r.Message, r.PC) + rec.AddAttrs(toSlogAttrs(r.Attrs)...) + return s.h.Handle(ctx, rec) +} + +func (s slogHandler) WithAttrs(attrs []Attr) Handler { + return slogHandler{h: s.h.WithAttrs(toSlogAttrs(attrs))} +} + +func toSlogAttrs(attrs []Attr) []slog.Attr { + out := make([]slog.Attr, len(attrs)) + for i, a := range attrs { + out[i] = slog.Any(a.Key, a.Value) + } + return out +} diff --git a/act/common/logging/terminal_other.go b/act/common/logging/terminal_other.go new file mode 100644 index 00000000..10ca204a --- /dev/null +++ b/act/common/logging/terminal_other.go @@ -0,0 +1,20 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +//go:build !windows + +package logging + +import ( + "io" + "os" + + "golang.org/x/term" +) + +func checkIfTerminal(w io.Writer) bool { + if f, ok := w.(*os.File); ok { + return term.IsTerminal(int(f.Fd())) + } + return false +} diff --git a/act/common/logging/terminal_windows.go b/act/common/logging/terminal_windows.go new file mode 100644 index 00000000..5523b292 --- /dev/null +++ b/act/common/logging/terminal_windows.go @@ -0,0 +1,27 @@ +// Copyright 2026 The Gitea Authors. All rights reserved. +// SPDX-License-Identifier: MIT + +//go:build windows + +package logging + +import ( + "io" + "os" + + "golang.org/x/sys/windows" +) + +// checkIfTerminal also turns on virtual terminal processing, which the console needs to show colors. +func checkIfTerminal(w io.Writer) bool { + f, ok := w.(*os.File) + if !ok { + return false + } + handle := windows.Handle(f.Fd()) + var mode uint32 + if err := windows.GetConsoleMode(handle, &mode); err != nil { + return false + } + return windows.SetConsoleMode(handle, mode|windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING) == nil +} diff --git a/docs/post-task-script.md b/docs/post-task-script.md index b632c0f5..cca3f4bb 100644 --- a/docs/post-task-script.md +++ b/docs/post-task-script.md @@ -82,7 +82,7 @@ The script environment is **not** a full copy of the job container environment. ## Output and errors -- **Stdout/stderr** are written to the **runner process log** (logrus), prefixed with `post-task script stdout:` / `post-task script stderr:`. +- **Stdout/stderr** are written to the **runner process log**, prefixed with `post-task script stdout:` / `post-task script stderr:`. - **Non-zero exit codes** are logged as warnings only. They do **not** change the job result already reported to Gitea. - **Timeouts and start failures** are logged as warnings; the runner still completes the task acknowledgement. diff --git a/internal/app/cmd/daemon_test.go b/internal/app/cmd/daemon_test.go index a13cb580..aa5c2ba3 100644 --- a/internal/app/cmd/daemon_test.go +++ b/internal/app/cmd/daemon_test.go @@ -188,3 +188,10 @@ func TestShouldRetryDeclare(t *testing.T) { require.Equal(t, tc.retry, shouldRetryDeclare(tc.err), tc.err.Error()) } } + +// A dependency that reconfigures logrus's global logger when it is loaded makes its own log lines +// show up twice or not at all, so this fails when upgrading one starts doing that. It does not +// cover a dependency that does so later, while running. +func TestLogrusBridgeSurvivesDependencies(t *testing.T) { + require.True(t, logging.LogrusBridgeIntact()) +}