mirror of
https://gitea.com/gitea/act_runner.git
synced 2026-11-01 04:48:49 +08:00
refactor(logging): replace the logrus backend with log/slog (#1304)
Log through `log/slog`, with a console `slog.Handler` that writes the text the runner has always written (sorted `key=value` fields on a plain stream, a colored prefix on a terminal), so nothing changes for users. I compared its output byte for byte with logrus's `TextFormatter` over plain, colored, timestamped and caller cases. Why not `slog.TextHandler`: its output differs from what users and their log parsers see today, and `ReplaceAttr` cannot close the gap. - level is `WARN` where logrus wrote `warning`, and time has milliseconds and no quotes - fields keep call order instead of being sorted - the caller is one `source=` key, where the runner writes `func=` and `file=` (reshaped by `callPrettyfier`), and `ReplaceAttr` returns a single attribute - no colored prefix on a terminal - no hook to rewrite a whole formatted line, which the process-wide secret masking relies on Libraries that log through logrus's global logger (the workflow model, the Docker client) are forwarded to the process-wide logger, so they keep following its level, format and secret masking. This is why logrus stays in `go.mod`. Stacked on https://gitea.com/gitea/runner/pulls/1303. Assisted-by: Codet Co-authored-by: bircni <bircni@icloud.com> Reviewed-on: https://gitea.com/gitea/runner/pulls/1304 Reviewed-by: bircni <bircni@icloud.com>
This commit is contained in:
@@ -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
|
||||
|
||||
287
act/common/logging/console.go
Normal file
287
act/common/logging/console.go
Normal file
@@ -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 "<nil>" 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, "<nil>")
|
||||
} 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
|
||||
}
|
||||
78
act/common/logging/console_test.go
Normal file
78
act/common/logging/console_test.go
Normal file
@@ -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")
|
||||
}
|
||||
@@ -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
|
||||
}
|
||||
@@ -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) }
|
||||
|
||||
|
||||
@@ -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())
|
||||
}
|
||||
|
||||
@@ -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
|
||||
}
|
||||
}
|
||||
102
act/common/logging/logrus_bridge.go
Normal file
102
act/common/logging/logrus_bridge.go
Normal file
@@ -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
|
||||
}
|
||||
40
act/common/logging/slog.go
Normal file
40
act/common/logging/slog.go
Normal file
@@ -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
|
||||
}
|
||||
20
act/common/logging/terminal_other.go
Normal file
20
act/common/logging/terminal_other.go
Normal file
@@ -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
|
||||
}
|
||||
27
act/common/logging/terminal_windows.go
Normal file
27
act/common/logging/terminal_windows.go
Normal file
@@ -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
|
||||
}
|
||||
@@ -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.
|
||||
|
||||
|
||||
@@ -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())
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user