diff --git a/.golangci.yml b/.golangci.yml index 98859bad6c7d9..ecc5e7c8e253f 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -115,14 +115,6 @@ linters-settings: desc: 'use "crypto" or "x/crypto" instead' # Prevent importing any additional logging libraries. logging: - files: - # Integrations are still allowed to use logrus becuase they haven't - # been converted to slog yet. Once they use slog, remove this exception. - - '!**/integrations/**' - # The log package still contains the logrus formatter consumed by the integrations. - # Remove this exception when said formatter is deleted. - - '!**/lib/utils/log/**' - - '!**/lib/utils/cli.go' deny: - pkg: github.com/sirupsen/logrus desc: 'use "log/slog" instead' diff --git a/go.mod b/go.mod index 3c35132910093..78f04732806b6 100644 --- a/go.mod +++ b/go.mod @@ -179,7 +179,6 @@ require ( github.com/sigstore/cosign/v2 v2.4.1 github.com/sigstore/sigstore v1.8.11 github.com/sijms/go-ora/v2 v2.8.22 - github.com/sirupsen/logrus v1.9.3 github.com/snowflakedb/gosnowflake v1.12.1 github.com/spf13/cobra v1.8.1 github.com/spiffe/go-spiffe/v2 v2.4.0 @@ -501,6 +500,7 @@ require ( github.com/sigstore/protobuf-specs v0.3.2 // indirect github.com/sigstore/rekor v1.3.6 // indirect github.com/sigstore/timestamp-authority v1.2.2 // indirect + github.com/sirupsen/logrus v1.9.3 // indirect github.com/sourcegraph/conc v0.3.0 // indirect github.com/spf13/afero v1.11.0 // indirect github.com/spf13/cast v1.7.0 // indirect diff --git a/lib/client/api.go b/lib/client/api.go index ed94462aa9c73..8b4c317265573 100644 --- a/lib/client/api.go +++ b/lib/client/api.go @@ -2853,7 +2853,7 @@ type execResult struct { // sharedWriter is an [io.Writer] implementation that protects // writes with a mutex. This allows a single [io.Writer] to be shared -// by both logrus and slog without their output clobbering each other. +// by multiple command runners. type sharedWriter struct { mu sync.Mutex io.Writer diff --git a/lib/srv/desktop/rdp/rdpclient/client.go b/lib/srv/desktop/rdp/rdpclient/client.go index 821408d2208fa..534644e6be1df 100644 --- a/lib/srv/desktop/rdp/rdpclient/client.go +++ b/lib/srv/desktop/rdp/rdpclient/client.go @@ -93,7 +93,7 @@ func init() { var rustLogLevel string // initialize the Rust logger by setting $RUST_LOG based - // on the logrus log level + // on the slog log level // (unless RUST_LOG is already explicitly set, then we // assume the user knows what they want) rl := os.Getenv("RUST_LOG") diff --git a/lib/utils/cli.go b/lib/utils/cli.go index e79c0bc2aa8f0..648cf7095352f 100644 --- a/lib/utils/cli.go +++ b/lib/utils/cli.go @@ -26,7 +26,6 @@ import ( "flag" "fmt" "io" - stdlog "log" "log/slog" "os" "runtime" @@ -38,7 +37,6 @@ import ( "github.com/alecthomas/kingpin/v2" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/term" "github.com/gravitational/teleport" @@ -100,59 +98,18 @@ func InitLogger(purpose LoggingPurpose, level slog.Level, opts ...LoggerOption) opt(&o) } - logrus.StandardLogger().ReplaceHooks(make(logrus.LevelHooks)) - logrus.SetLevel(logutils.SlogLevelToLogrusLevel(level)) - - var ( - w io.Writer - enableColors bool - ) - switch purpose { - case LoggingForCLI: - // If debug logging was asked for on the CLI, then write logs to stderr. - // Otherwise, discard all logs. - if level == slog.LevelDebug { - enableColors = IsTerminal(os.Stderr) - w = logutils.NewSharedWriter(os.Stderr) - } else { - w = io.Discard - enableColors = false - } - case LoggingForDaemon: - enableColors = IsTerminal(os.Stderr) - w = logutils.NewSharedWriter(os.Stderr) - } - - var ( - formatter logrus.Formatter - handler slog.Handler - ) - switch o.format { - case LogFormatText, "": - textFormatter := logutils.NewDefaultTextFormatter(enableColors) - - // Calling CheckAndSetDefaults enables the timestamp field to - // be included in the output. The error returned is ignored - // because the default formatter cannot be invalid. - if purpose == LoggingForCLI && level == slog.LevelDebug { - _ = textFormatter.CheckAndSetDefaults() - } - - formatter = textFormatter - handler = logutils.NewSlogTextHandler(w, logutils.SlogTextHandlerConfig{ - Level: level, - EnableColors: enableColors, - }) - case LogFormatJSON: - formatter = &logutils.JSONFormatter{} - handler = logutils.NewSlogJSONHandler(w, logutils.SlogJSONHandlerConfig{ - Level: level, - }) + // If debug or trace logging is not enabled for CLIs, + // then discard all log output. + if purpose == LoggingForCLI && level > slog.LevelDebug { + slog.SetDefault(slog.New(logutils.DiscardHandler{})) + return } - logrus.SetFormatter(formatter) - logrus.SetOutput(w) - slog.SetDefault(slog.New(handler)) + logutils.Initialize(logutils.Config{ + Severity: level.String(), + Format: o.format, + EnableColors: IsTerminal(os.Stderr), + }) } var initTestLoggerOnce = sync.Once{} @@ -163,56 +120,24 @@ func InitLoggerForTests() { // Parse flags to check testing.Verbose(). flag.Parse() - level := slog.LevelWarn - w := io.Discard - if testing.Verbose() { - level = slog.LevelDebug - w = os.Stderr + if !testing.Verbose() { + slog.SetDefault(slog.New(logutils.DiscardHandler{})) + return } - logger := logrus.StandardLogger() - logger.SetFormatter(logutils.NewTestJSONFormatter()) - logger.SetLevel(logutils.SlogLevelToLogrusLevel(level)) - - output := logutils.NewSharedWriter(w) - logger.SetOutput(output) - slog.SetDefault(slog.New(logutils.NewSlogJSONHandler(output, logutils.SlogJSONHandlerConfig{Level: level}))) + logutils.Initialize(logutils.Config{ + Severity: slog.LevelDebug.String(), + Format: LogFormatJSON, + }) }) } -// NewLoggerForTests creates a new logrus logger for test environments. -func NewLoggerForTests() *logrus.Logger { - InitLoggerForTests() - return logrus.StandardLogger() -} - // NewSlogLoggerForTests creates a new slog logger for test environments. func NewSlogLoggerForTests() *slog.Logger { InitLoggerForTests() return slog.Default() } -// WrapLogger wraps an existing logger entry and returns -// a value satisfying the Logger interface -func WrapLogger(logger *logrus.Entry) Logger { - return &logWrapper{Entry: logger} -} - -// NewLogger creates a new empty logrus logger. -func NewLogger() *logrus.Logger { - return logrus.StandardLogger() -} - -// Logger describes a logger value -type Logger interface { - logrus.FieldLogger - // GetLevel specifies the level at which this logger - // value is logging - GetLevel() logrus.Level - // SetLevel sets the logger's level to the specified value - SetLevel(level logrus.Level) -} - // FatalError is for CLI front-ends: it detects gravitational/trace debugging // information, sends it to the logger, strips it off and prints a clean message to stderr func FatalError(err error) { @@ -231,7 +156,7 @@ func GetIterations() int { if err != nil { panic(err) } - logrus.Debugf("Starting tests with %v iterations.", iter) + slog.DebugContext(context.Background(), "Running tests multiple times due to presence of ITERATIONS environment variable", "iterations", iter) return iter } @@ -484,47 +409,6 @@ func AllowWhitespace(s string) string { return sb.String() } -// NewStdlogger creates a new stdlib logger that uses the specified leveled logger -// for output and the given component as a logging prefix. -func NewStdlogger(logger LeveledOutputFunc, component string) *stdlog.Logger { - return stdlog.New(&stdlogAdapter{ - log: logger, - }, component, stdlog.LstdFlags) -} - -// Write writes the specified buffer p to the underlying leveled logger. -// Implements io.Writer -func (r *stdlogAdapter) Write(p []byte) (n int, err error) { - r.log(string(p)) - return len(p), nil -} - -// stdlogAdapter is an io.Writer that writes into an instance -// of logrus.Logger -type stdlogAdapter struct { - log LeveledOutputFunc -} - -// LeveledOutputFunc describes a function that emits given -// arguments at a specific level to an underlying logger -type LeveledOutputFunc func(args ...interface{}) - -// GetLevel returns the level of the underlying logger -func (r *logWrapper) GetLevel() logrus.Level { - return r.Entry.Logger.GetLevel() -} - -// SetLevel sets the logging level to the given value -func (r *logWrapper) SetLevel(level logrus.Level) { - r.Entry.Logger.SetLevel(level) -} - -// logWrapper wraps a log entry. -// Implements Logger -type logWrapper struct { - *logrus.Entry -} - // needsQuoting returns true if any non-printable characters are found. func needsQuoting(text string) bool { for _, r := range text { diff --git a/lib/utils/log/formatter_test.go b/lib/utils/log/formatter_test.go index 9abb0310ba0be..aff0ec8be3a74 100644 --- a/lib/utils/log/formatter_test.go +++ b/lib/utils/log/formatter_test.go @@ -22,7 +22,6 @@ import ( "bytes" "context" "encoding/json" - "errors" "fmt" "io" "log/slog" @@ -38,7 +37,6 @@ import ( "github.com/google/go-cmp/cmp/cmpopts" "github.com/gravitational/trace" "github.com/jonboulle/clockwork" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -48,7 +46,7 @@ import ( const message = "Adding diagnostic debugging handlers.\t To connect with profiler, use go tool pprof diag_addr." var ( - logErr = errors.New("the quick brown fox jumped really high") + logErr = &trace.BadParameterError{Message: "the quick brown fox jumped really high"} addr = fakeAddr{addr: "127.0.0.1:1234"} fields = map[string]any{ @@ -72,6 +70,10 @@ func (a fakeAddr) String() string { return a.addr } +func (a fakeAddr) MarshalText() (text []byte, err error) { + return []byte(a.addr), nil +} + func TestOutput(t *testing.T) { loc, err := time.LoadLocation("Africa/Cairo") require.NoError(t, err, "failed getting timezone") @@ -89,58 +91,50 @@ func TestOutput(t *testing.T) { // 4) the caller outputRegex := regexp.MustCompile(`(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z)(\s+.*)(".*diag_addr\.")(.*)(\slog/formatter_test.go:\d{3})`) + expectedFields := map[string]string{ + "local": addr.String(), + "remote": addr.String(), + "login": "llama", + "teleportUser": "user", + "id": "1234", + "test": "123", + "animal": `"llama\n"`, + "error": "[" + trace.DebugReport(logErr) + "]", + "diag_addr": addr.String(), + } + tests := []struct { - name string - logrusLevel logrus.Level - slogLevel slog.Level + name string + slogLevel slog.Level }{ { - name: "trace", - logrusLevel: logrus.TraceLevel, - slogLevel: TraceLevel, + name: "trace", + slogLevel: TraceLevel, }, { - name: "debug", - logrusLevel: logrus.DebugLevel, - slogLevel: slog.LevelDebug, + name: "debug", + slogLevel: slog.LevelDebug, }, { - name: "info", - logrusLevel: logrus.InfoLevel, - slogLevel: slog.LevelInfo, + name: "info", + slogLevel: slog.LevelInfo, }, { - name: "warn", - logrusLevel: logrus.WarnLevel, - slogLevel: slog.LevelWarn, + name: "warn", + slogLevel: slog.LevelWarn, }, { - name: "error", - logrusLevel: logrus.ErrorLevel, - slogLevel: slog.LevelError, + name: "error", + slogLevel: slog.LevelError, }, { - name: "fatal", - logrusLevel: logrus.FatalLevel, - slogLevel: slog.LevelError + 1, + name: "fatal", + slogLevel: slog.LevelError + 1, }, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { - // Create a logrus logger using the custom formatter which outputs to a local buffer. - var logrusOutput bytes.Buffer - formatter := NewDefaultTextFormatter(true) - formatter.timestampEnabled = true - require.NoError(t, formatter.CheckAndSetDefaults()) - - logrusLogger := logrus.New() - logrusLogger.SetFormatter(formatter) - logrusLogger.SetOutput(&logrusOutput) - logrusLogger.ReplaceHooks(logrus.LevelHooks{}) - logrusLogger.SetLevel(test.logrusLevel) - entry := logrusLogger.WithField(teleport.ComponentKey, "test").WithTime(clock.Now().UTC()) - // Create a slog logger using the custom handler which outputs to a local buffer. var slogOutput bytes.Buffer slogConfig := SlogTextHandlerConfig{ @@ -155,13 +149,6 @@ func TestOutput(t *testing.T) { } slogLogger := slog.New(NewSlogTextHandler(&slogOutput, slogConfig)).With(teleport.ComponentKey, "test") - // Add some fields and output the message at the desired log level via logrus. - l := entry.WithField("test", 123).WithField("animal", "llama\n").WithField("error", logErr) - logrusTestLogLineNumber := func() int { - l.WithField("diag_addr", &addr).WithField(teleport.ComponentFields, fields).Log(test.logrusLevel, message) - return getCallerLineNumber() - 1 // Get the line number of this call, and assume the log call is right above it - }() - // Add some fields and output the message at the desired log level via slog. l2 := slogLogger.With("test", 123).With("animal", "llama\n").With("error", logErr) slogTestLogLineNumber := func() int { @@ -169,163 +156,144 @@ func TestOutput(t *testing.T) { return getCallerLineNumber() - 1 // Get the line number of this call, and assume the log call is right above it }() - // Validate that both loggers produces the same output. The added complexity comes from the fact that - // our custom slog handler does NOT sort the additional fields like our logrus formatter does. - logrusMatches := outputRegex.FindStringSubmatch(logrusOutput.String()) - require.NotEmpty(t, logrusMatches, "logrus output was in unexpected format: %s", logrusOutput.String()) + // Validate the logger output. The added complexity comes from the fact that + // our custom slog handler does NOT sort the additional fields. slogMatches := outputRegex.FindStringSubmatch(slogOutput.String()) require.NotEmpty(t, slogMatches, "slog output was in unexpected format: %s", slogOutput.String()) // The first match is the timestamp: 2023-10-31T10:09:06+02:00 - logrusTime, err := time.Parse(time.RFC3339, logrusMatches[1]) - assert.NoError(t, err, "invalid logrus timestamp found %s", logrusMatches[1]) - slogTime, err := time.Parse(time.RFC3339, slogMatches[1]) assert.NoError(t, err, "invalid slog timestamp found %s", slogMatches[1]) - - assert.InDelta(t, logrusTime.Unix(), slogTime.Unix(), 10) + assert.InDelta(t, clock.Now().Unix(), slogTime.Unix(), 10) // Match level, and component: DEBU [TEST] - assert.Empty(t, cmp.Diff(logrusMatches[2], slogMatches[2]), "level, and component to be identical") - // Match the log message: "Adding diagnostic debugging handlers.\t To connect with profiler, use go tool pprof diag_addr.\n" - assert.Empty(t, cmp.Diff(logrusMatches[3], slogMatches[3]), "expected output messages to be identical") + expectedLevel := formatLevel(test.slogLevel, true) + expectedComponent := formatComponent(slog.StringValue("test"), defaultComponentPadding) + expectedMatch := " " + expectedLevel + " " + expectedComponent + " " + assert.Equal(t, expectedMatch, slogMatches[2], "level, and component to be identical") + // Match the log message + assert.Equal(t, `"Adding diagnostic debugging handlers.\t To connect with profiler, use go tool pprof diag_addr."`, slogMatches[3], "expected output messages to be identical") // The last matches are the caller information - assert.Equal(t, fmt.Sprintf(" log/formatter_test.go:%d", logrusTestLogLineNumber), logrusMatches[5]) assert.Equal(t, fmt.Sprintf(" log/formatter_test.go:%d", slogTestLogLineNumber), slogMatches[5]) // The third matches are the fields which will be key value pairs(animal:llama) separated by a space. Since - // logrus sorts the fields and slog doesn't we can't just assert equality and instead build a map of the key + // slog doesn't sort the fields, we can't assert equality and instead build a map of the key // value pairs to ensure they are all present and accounted for. - logrusFieldMatches := fieldsRegex.FindAllStringSubmatch(logrusMatches[4], -1) slogFieldMatches := fieldsRegex.FindAllStringSubmatch(slogMatches[4], -1) // The first match is the key, the second match is the value - logrusFields := map[string]string{} - for _, match := range logrusFieldMatches { - logrusFields[strings.TrimSpace(match[1])] = strings.TrimSpace(match[2]) - } - slogFields := map[string]string{} for _, match := range slogFieldMatches { slogFields[strings.TrimSpace(match[1])] = strings.TrimSpace(match[2]) } - assert.Equal(t, slogFields, logrusFields) + require.Empty(t, + cmp.Diff( + expectedFields, + slogFields, + cmpopts.SortMaps(func(a, b string) bool { return a < b }), + ), + ) }) } }) t.Run("json", func(t *testing.T) { tests := []struct { - name string - logrusLevel logrus.Level - slogLevel slog.Level + name string + slogLevel slog.Level }{ { - name: "trace", - logrusLevel: logrus.TraceLevel, - slogLevel: TraceLevel, + name: "trace", + slogLevel: TraceLevel, }, { - name: "debug", - logrusLevel: logrus.DebugLevel, - slogLevel: slog.LevelDebug, + name: "debug", + slogLevel: slog.LevelDebug, }, { - name: "info", - logrusLevel: logrus.InfoLevel, - slogLevel: slog.LevelInfo, + name: "info", + slogLevel: slog.LevelInfo, }, { - name: "warn", - logrusLevel: logrus.WarnLevel, - slogLevel: slog.LevelWarn, + name: "warn", + slogLevel: slog.LevelWarn, }, { - name: "error", - logrusLevel: logrus.ErrorLevel, - slogLevel: slog.LevelError, + name: "error", + slogLevel: slog.LevelError, }, { - name: "fatal", - logrusLevel: logrus.FatalLevel, - slogLevel: slog.LevelError + 1, + name: "fatal", + slogLevel: slog.LevelError + 1, + }, + } + + expectedFields := map[string]any{ + "trace.fields": map[string]any{ + "teleportUser": "user", + "id": float64(1234), + "local": addr.String(), + "login": "llama", + "remote": addr.String(), }, + "test": float64(123), + "animal": `llama`, + "error": logErr.Error(), + "diag_addr": addr.String(), + "component": "test", + "message": message, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { - // Create a logrus logger using the custom formatter which outputs to a local buffer. - var logrusOut bytes.Buffer - formatter := &JSONFormatter{ - ExtraFields: nil, - callerEnabled: true, - } - require.NoError(t, formatter.CheckAndSetDefaults()) - - logrusLogger := logrus.New() - logrusLogger.SetFormatter(formatter) - logrusLogger.SetOutput(&logrusOut) - logrusLogger.ReplaceHooks(logrus.LevelHooks{}) - logrusLogger.SetLevel(test.logrusLevel) - entry := logrusLogger.WithField(teleport.ComponentKey, "test") - // Create a slog logger using the custom formatter which outputs to a local buffer. var slogOutput bytes.Buffer slogLogger := slog.New(NewSlogJSONHandler(&slogOutput, SlogJSONHandlerConfig{Level: test.slogLevel})).With(teleport.ComponentKey, "test") - // Add some fields and output the message at the desired log level via logrus. - l := entry.WithField("test", 123).WithField("animal", "llama").WithField("error", trace.Wrap(logErr)) - logrusTestLogLineNumber := func() int { - l.WithField("diag_addr", addr.String()).Log(test.logrusLevel, message) - return getCallerLineNumber() - 1 // Get the line number of this call, and assume the log call is right above it - }() - // Add some fields and output the message at the desired log level via slog. l2 := slogLogger.With("test", 123).With("animal", "llama").With("error", trace.Wrap(logErr)) slogTestLogLineNumber := func() int { - l2.Log(context.Background(), test.slogLevel, message, "diag_addr", &addr) + l2.With(teleport.ComponentFields, fields).Log(context.Background(), test.slogLevel, message, "diag_addr", &addr) return getCallerLineNumber() - 1 // Get the line number of this call, and assume the log call is right above it }() - // The order of the fields emitted by the two loggers is different, so comparing the output directly - // for equality won't work. Instead, a map is built with all the key value pairs, excluding the caller - // and that map is compared to ensure all items are present and match. - var logrusData map[string]any - require.NoError(t, json.Unmarshal(logrusOut.Bytes(), &logrusData), "invalid logrus output format") - var slogData map[string]any require.NoError(t, json.Unmarshal(slogOutput.Bytes(), &slogData), "invalid slog output format") - logrusCaller, ok := logrusData["caller"].(string) - delete(logrusData, "caller") - assert.True(t, ok, "caller was missing from logrus output") - assert.Equal(t, fmt.Sprintf("log/formatter_test.go:%d", logrusTestLogLineNumber), logrusCaller) - slogCaller, ok := slogData["caller"].(string) delete(slogData, "caller") assert.True(t, ok, "caller was missing from slog output") assert.Equal(t, fmt.Sprintf("log/formatter_test.go:%d", slogTestLogLineNumber), slogCaller) - logrusTimestamp, ok := logrusData["timestamp"].(string) - delete(logrusData, "timestamp") - assert.True(t, ok, "time was missing from logrus output") + slogLevel, ok := slogData["level"].(string) + delete(slogData, "level") + assert.True(t, ok, "level was missing from slog output") + var expectedLevel string + switch test.slogLevel { + case TraceLevel: + expectedLevel = "trace" + case slog.LevelWarn: + expectedLevel = "warning" + case slog.LevelError + 1: + expectedLevel = "fatal" + default: + expectedLevel = test.slogLevel.String() + } + assert.Equal(t, strings.ToLower(expectedLevel), slogLevel) slogTimestamp, ok := slogData["timestamp"].(string) delete(slogData, "timestamp") assert.True(t, ok, "time was missing from slog output") - logrusTime, err := time.Parse(time.RFC3339, logrusTimestamp) - assert.NoError(t, err, "invalid logrus timestamp %s", logrusTimestamp) - slogTime, err := time.Parse(time.RFC3339, slogTimestamp) assert.NoError(t, err, "invalid slog timestamp %s", slogTimestamp) - assert.InDelta(t, logrusTime.Unix(), slogTime.Unix(), 10) + assert.InDelta(t, clock.Now().Unix(), slogTime.Unix(), 10) require.Empty(t, cmp.Diff( - logrusData, + expectedFields, slogData, cmpopts.SortMaps(func(a, b string) bool { return a < b }), ), @@ -347,38 +315,6 @@ func getCallerLineNumber() int { func BenchmarkFormatter(b *testing.B) { ctx := context.Background() b.ReportAllocs() - b.Run("logrus", func(b *testing.B) { - b.Run("text", func(b *testing.B) { - formatter := NewDefaultTextFormatter(true) - require.NoError(b, formatter.CheckAndSetDefaults()) - logger := logrus.New() - logger.SetFormatter(formatter) - logger.SetOutput(io.Discard) - b.ResetTimer() - - entry := logger.WithField(teleport.ComponentKey, "test") - for i := 0; i < b.N; i++ { - l := entry.WithField("test", 123).WithField("animal", "llama\n").WithField("error", logErr) - l.WithField("diag_addr", &addr).WithField(teleport.ComponentFields, fields).Info(message) - } - }) - - b.Run("json", func(b *testing.B) { - formatter := &JSONFormatter{} - require.NoError(b, formatter.CheckAndSetDefaults()) - logger := logrus.New() - logger.SetFormatter(formatter) - logger.SetOutput(io.Discard) - logger.ReplaceHooks(logrus.LevelHooks{}) - b.ResetTimer() - - entry := logger.WithField(teleport.ComponentKey, "test") - for i := 0; i < b.N; i++ { - l := entry.WithField("test", 123).WithField("animal", "llama\n").WithField("error", logErr) - l.WithField("diag_addr", &addr).WithField(teleport.ComponentFields, fields).Info(message) - } - }) - }) b.Run("slog", func(b *testing.B) { b.Run("default_text", func(b *testing.B) { @@ -430,47 +366,26 @@ func BenchmarkFormatter(b *testing.B) { } func TestConcurrentOutput(t *testing.T) { - t.Run("logrus", func(t *testing.T) { - debugFormatter := NewDefaultTextFormatter(true) - require.NoError(t, debugFormatter.CheckAndSetDefaults()) - logrus.SetFormatter(debugFormatter) - logrus.SetOutput(os.Stdout) - - logger := logrus.WithField(teleport.ComponentKey, "test") - - var wg sync.WaitGroup - for i := 0; i < 1000; i++ { - wg.Add(1) - go func(i int) { - defer wg.Done() - logger.Infof("Detected Teleport component %d is running in a degraded state.", i) - }(i) - } - wg.Wait() - }) + logger := slog.New(NewSlogTextHandler(os.Stdout, SlogTextHandlerConfig{ + EnableColors: true, + })).With(teleport.ComponentKey, "test") - t.Run("slog", func(t *testing.T) { - logger := slog.New(NewSlogTextHandler(os.Stdout, SlogTextHandlerConfig{ - EnableColors: true, - })).With(teleport.ComponentKey, "test") - - var wg sync.WaitGroup - ctx := context.Background() - for i := 0; i < 1000; i++ { - wg.Add(1) - go func(i int) { - defer wg.Done() - logger.InfoContext(ctx, "Teleport component entered degraded state", - slog.Int("component", i), - slog.Group("group", - slog.String("test", "123"), - slog.String("animal", "llama"), - ), - ) - }(i) - } - wg.Wait() - }) + var wg sync.WaitGroup + ctx := context.Background() + for i := 0; i < 1000; i++ { + wg.Add(1) + go func(i int) { + defer wg.Done() + logger.InfoContext(ctx, "Teleport component entered degraded state", + slog.Int("component", i), + slog.Group("group", + slog.String("test", "123"), + slog.String("animal", "llama"), + ), + ) + }(i) + } + wg.Wait() } // allPossibleSubsets returns all combinations of subsets for the @@ -493,58 +408,34 @@ func allPossibleSubsets(in []string) [][]string { return subsets } -// TestExtraFields validates that the output is identical for the -// logrus formatter and slog handler based on the configured extra -// fields. +// TestExtraFields validates that the output is expected for the +// slog handler based on the configured extra fields. func TestExtraFields(t *testing.T) { // Capture a fake time that all output will use. now := clockwork.NewFakeClock().Now() // Capture the caller information to be injected into all messages. pc, _, _, _ := runtime.Caller(0) - fs := runtime.CallersFrames([]uintptr{pc}) - f, _ := fs.Next() - callerTrace := &trace.Trace{ - Func: f.Function, - Path: f.File, - Line: f.Line, - } const message = "testing 123" - // Test against every possible configured combination of allowed format fields. - fields := allPossibleSubsets(defaultFormatFields) - t.Run("text", func(t *testing.T) { - for _, configuredFields := range fields { + // Test against every possible configured combination of allowed format fields. + for _, configuredFields := range allPossibleSubsets(defaultFormatFields) { name := "not configured" if len(configuredFields) > 0 { name = strings.Join(configuredFields, " ") } t.Run(name, func(t *testing.T) { - logrusFormatter := TextFormatter{ - ExtraFields: configuredFields, - } - // Call CheckAndSetDefaults to exercise the extra fields logic. Since - // FormatCaller is always overridden within CheckAndSetDefaults, it is - // explicitly set afterward so the caller points to our fake call site. - require.NoError(t, logrusFormatter.CheckAndSetDefaults()) - logrusFormatter.FormatCaller = callerTrace.String - - var slogOutput bytes.Buffer - var slogHandler slog.Handler = NewSlogTextHandler(&slogOutput, SlogTextHandlerConfig{ConfiguredFields: configuredFields}) - - entry := &logrus.Entry{ - Data: logrus.Fields{"animal": "llama", "vegetable": "carrot", teleport.ComponentKey: "test"}, - Time: now, - Level: logrus.DebugLevel, - Caller: &f, - Message: message, - } - - logrusOut, err := logrusFormatter.Format(entry) - require.NoError(t, err) + replaced := map[string]struct{}{} + var slogHandler slog.Handler = NewSlogTextHandler(io.Discard, SlogTextHandlerConfig{ + ConfiguredFields: configuredFields, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + replaced[a.Key] = struct{}{} + return a + }, + }) record := slog.Record{ Time: now, @@ -557,42 +448,29 @@ func TestExtraFields(t *testing.T) { require.NoError(t, slogHandler.Handle(context.Background(), record)) - require.Equal(t, string(logrusOut), slogOutput.String()) + for k := range replaced { + delete(replaced, k) + } + + require.Empty(t, replaced, replaced) }) } }) t.Run("json", func(t *testing.T) { - for _, configuredFields := range fields { + // Test against every possible configured combination of allowed format fields. + // Note, the json handler limits the allowed fields to a subset of those allowed + // by the text handler. + for _, configuredFields := range allPossibleSubsets([]string{CallerField, ComponentField, TimestampField}) { name := "not configured" if len(configuredFields) > 0 { name = strings.Join(configuredFields, " ") } t.Run(name, func(t *testing.T) { - logrusFormatter := JSONFormatter{ - ExtraFields: configuredFields, - } - // Call CheckAndSetDefaults to exercise the extra fields logic. Since - // FormatCaller is always overridden within CheckAndSetDefaults, it is - // explicitly set afterward so the caller points to our fake call site. - require.NoError(t, logrusFormatter.CheckAndSetDefaults()) - logrusFormatter.FormatCaller = callerTrace.String - var slogOutput bytes.Buffer var slogHandler slog.Handler = NewSlogJSONHandler(&slogOutput, SlogJSONHandlerConfig{ConfiguredFields: configuredFields}) - entry := &logrus.Entry{ - Data: logrus.Fields{"animal": "llama", "vegetable": "carrot", teleport.ComponentKey: "test"}, - Time: now, - Level: logrus.DebugLevel, - Caller: &f, - Message: message, - } - - logrusOut, err := logrusFormatter.Format(entry) - require.NoError(t, err) - record := slog.Record{ Time: now, Message: message, @@ -604,11 +482,31 @@ func TestExtraFields(t *testing.T) { require.NoError(t, slogHandler.Handle(context.Background(), record)) - var slogData, logrusData map[string]any - require.NoError(t, json.Unmarshal(logrusOut, &logrusData)) + var slogData map[string]any require.NoError(t, json.Unmarshal(slogOutput.Bytes(), &slogData)) - require.Equal(t, slogData, logrusData) + delete(slogData, "animal") + delete(slogData, "vegetable") + delete(slogData, "message") + delete(slogData, "level") + + var expectedLen int + expectedFields := configuredFields + switch l := len(configuredFields); l { + case 0: + // The level field was removed above, but is included in the default fields + expectedLen = len(defaultFormatFields) - 1 + expectedFields = defaultFormatFields + default: + expectedLen = l + } + require.Len(t, slogData, expectedLen, slogData) + + for _, f := range expectedFields { + delete(slogData, f) + } + + require.Empty(t, slogData, slogData) }) } }) diff --git a/lib/utils/log/logrus_formatter.go b/lib/utils/log/logrus_formatter.go deleted file mode 100644 index 14ad8441da7cc..0000000000000 --- a/lib/utils/log/logrus_formatter.go +++ /dev/null @@ -1,427 +0,0 @@ -/* - * Teleport - * Copyright (C) 2023 Gravitational, Inc. - * - * This program is free software: you can redistribute it and/or modify - * it under the terms of the GNU Affero General Public License as published by - * the Free Software Foundation, either version 3 of the License, or - * (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU Affero General Public License for more details. - * - * You should have received a copy of the GNU Affero General Public License - * along with this program. If not, see . - */ - -package log - -import ( - "fmt" - "regexp" - "runtime" - "slices" - "strconv" - "strings" - - "github.com/gravitational/trace" - "github.com/sirupsen/logrus" - - "github.com/gravitational/teleport" -) - -// TextFormatter is a [logrus.Formatter] that outputs messages in -// a textual format. -type TextFormatter struct { - // ComponentPadding is a padding to pick when displaying - // and formatting component field, defaults to DefaultComponentPadding - ComponentPadding int - // EnableColors enables colored output - EnableColors bool - // FormatCaller is a function to return (part) of source file path for output. - // Defaults to filePathAndLine() if unspecified - FormatCaller func() (caller string) - // ExtraFields represent the extra fields that will be added to the log message - ExtraFields []string - // TimestampEnabled specifies if timestamp is enabled in logs - timestampEnabled bool - // CallerEnabled specifies if caller is enabled in logs - callerEnabled bool -} - -type writer struct { - b *buffer -} - -func newWriter() *writer { - return &writer{b: &buffer{}} -} - -func (w *writer) Len() int { - return len(*w.b) -} - -func (w *writer) WriteString(s string) (int, error) { - return w.b.WriteString(s) -} - -func (w *writer) WriteByte(c byte) error { - return w.b.WriteByte(c) -} - -func (w *writer) Bytes() []byte { - return *w.b -} - -// NewDefaultTextFormatter creates a TextFormatter with -// the default options set. -func NewDefaultTextFormatter(enableColors bool) *TextFormatter { - return &TextFormatter{ - ComponentPadding: defaultComponentPadding, - FormatCaller: formatCallerWithPathAndLine, - ExtraFields: defaultFormatFields, - EnableColors: enableColors, - callerEnabled: true, - timestampEnabled: false, - } -} - -// CheckAndSetDefaults checks and sets log format configuration. -func (tf *TextFormatter) CheckAndSetDefaults() error { - // set padding - if tf.ComponentPadding == 0 { - tf.ComponentPadding = defaultComponentPadding - } - // set caller - tf.FormatCaller = formatCallerWithPathAndLine - - // set log formatting - if tf.ExtraFields == nil { - tf.timestampEnabled = true - tf.callerEnabled = true - tf.ExtraFields = defaultFormatFields - return nil - } - - if slices.Contains(tf.ExtraFields, TimestampField) { - tf.timestampEnabled = true - } - - if slices.Contains(tf.ExtraFields, CallerField) { - tf.callerEnabled = true - } - - return nil -} - -// Format formats each log line as configured in teleport config file. -func (tf *TextFormatter) Format(e *logrus.Entry) ([]byte, error) { - caller := tf.FormatCaller() - w := newWriter() - - // write timestamp first if enabled - if tf.timestampEnabled { - *w.b = appendRFC3339Millis(*w.b, e.Time.Round(0)) - } - - for _, field := range tf.ExtraFields { - switch field { - case LevelField: - var color int - var level string - switch e.Level { - case logrus.TraceLevel: - level = "TRACE" - color = gray - case logrus.DebugLevel: - level = "DEBUG" - color = gray - case logrus.InfoLevel: - level = "INFO" - color = blue - case logrus.WarnLevel: - level = "WARN" - color = yellow - case logrus.ErrorLevel: - level = "ERROR" - color = red - case logrus.FatalLevel: - level = "FATAL" - color = red - default: - color = blue - level = strings.ToUpper(e.Level.String()) - } - - if !tf.EnableColors { - color = noColor - } - - w.writeField(padMax(level, defaultLevelPadding), color) - case ComponentField: - padding := defaultComponentPadding - if tf.ComponentPadding != 0 { - padding = tf.ComponentPadding - } - if w.Len() > 0 { - w.WriteByte(' ') - } - component, ok := e.Data[teleport.ComponentKey].(string) - if ok && component != "" { - component = fmt.Sprintf("[%v]", component) - } - component = strings.ToUpper(padMax(component, padding)) - if component[len(component)-1] != ' ' { - component = component[:len(component)-1] + "]" - } - - w.WriteString(component) - default: - if _, ok := knownFormatFields[field]; !ok { - return nil, trace.BadParameter("invalid log format key: %v", field) - } - } - } - - // always use message - if e.Message != "" { - w.writeField(e.Message, noColor) - } - - if len(e.Data) > 0 { - w.writeMap(e.Data) - } - - // write caller last if enabled - if tf.callerEnabled && caller != "" { - w.writeField(caller, noColor) - } - - w.WriteByte('\n') - return w.Bytes(), nil -} - -// JSONFormatter implements the [logrus.Formatter] interface and adds extra -// fields to log entries. -type JSONFormatter struct { - logrus.JSONFormatter - - ExtraFields []string - // FormatCaller is a function to return (part) of source file path for output. - // Defaults to filePathAndLine() if unspecified - FormatCaller func() (caller string) - - callerEnabled bool - componentEnabled bool -} - -// CheckAndSetDefaults checks and sets log format configuration. -func (j *JSONFormatter) CheckAndSetDefaults() error { - // set log formatting - if j.ExtraFields == nil { - j.ExtraFields = defaultFormatFields - } - // set caller - j.FormatCaller = formatCallerWithPathAndLine - - if slices.Contains(j.ExtraFields, CallerField) { - j.callerEnabled = true - } - - if slices.Contains(j.ExtraFields, ComponentField) { - j.componentEnabled = true - } - - // rename default fields - j.JSONFormatter = logrus.JSONFormatter{ - FieldMap: logrus.FieldMap{ - logrus.FieldKeyTime: TimestampField, - logrus.FieldKeyLevel: LevelField, - logrus.FieldKeyMsg: messageField, - }, - DisableTimestamp: !slices.Contains(j.ExtraFields, TimestampField), - } - - return nil -} - -// Format formats each log line as configured in teleport config file. -func (j *JSONFormatter) Format(e *logrus.Entry) ([]byte, error) { - if j.callerEnabled { - path := j.FormatCaller() - e.Data[CallerField] = path - } - - if j.componentEnabled { - e.Data[ComponentField] = e.Data[teleport.ComponentKey] - } - - delete(e.Data, teleport.ComponentKey) - - return j.JSONFormatter.Format(e) -} - -// NewTestJSONFormatter creates a JSONFormatter that is -// configured for output in tests. -func NewTestJSONFormatter() *JSONFormatter { - formatter := &JSONFormatter{} - if err := formatter.CheckAndSetDefaults(); err != nil { - panic(err) - } - return formatter -} - -func (w *writer) writeError(value interface{}) { - switch err := value.(type) { - case trace.Error: - *w.b = fmt.Appendf(*w.b, "[%v]", err.DebugReport()) - default: - *w.b = fmt.Appendf(*w.b, "[%v]", value) - } -} - -func (w *writer) writeField(value interface{}, color int) { - if w.Len() > 0 { - w.WriteByte(' ') - } - w.writeValue(value, color) -} - -func (w *writer) writeKeyValue(key string, value interface{}) { - if w.Len() > 0 { - w.WriteByte(' ') - } - w.WriteString(key) - w.WriteByte(':') - if key == logrus.ErrorKey { - w.writeError(value) - return - } - w.writeValue(value, noColor) -} - -func (w *writer) writeValue(value interface{}, color int) { - if s, ok := value.(string); ok { - if color != noColor { - *w.b = fmt.Appendf(*w.b, "\u001B[%dm", color) - } - - if needsQuoting(s) { - *w.b = strconv.AppendQuote(*w.b, s) - } else { - *w.b = fmt.Append(*w.b, s) - } - - if color != noColor { - *w.b = fmt.Append(*w.b, "\u001B[0m") - } - return - } - - if color != noColor { - *w.b = fmt.Appendf(*w.b, "\x1b[%dm%v\x1b[0m", color, value) - return - } - - *w.b = fmt.Appendf(*w.b, "%v", value) -} - -func (w *writer) writeMap(m map[string]any) { - if len(m) == 0 { - return - } - keys := make([]string, 0, len(m)) - for key := range m { - keys = append(keys, key) - } - slices.Sort(keys) - for _, key := range keys { - if key == teleport.ComponentKey { - continue - } - switch value := m[key].(type) { - case map[string]any: - w.writeMap(value) - case logrus.Fields: - w.writeMap(value) - default: - w.writeKeyValue(key, value) - } - } -} - -type frameCursor struct { - // current specifies the current stack frame. - // if omitted, rest contains the complete stack - current *runtime.Frame - // rest specifies the rest of stack frames to explore - rest *runtime.Frames - // n specifies the total number of stack frames - n int -} - -// formatCallerWithPathAndLine formats the caller in the form path/segment: -// for output in the log -func formatCallerWithPathAndLine() (path string) { - if cursor := findFrame(); cursor != nil { - t := newTraceFromFrames(*cursor, nil) - return t.Loc() - } - return "" -} - -var frameIgnorePattern = regexp.MustCompile(`github\.com/sirupsen/logrus`) - -// findFrames positions the stack pointer to the first -// function that does not match the frameIngorePattern -// and returns the rest of the stack frames -func findFrame() *frameCursor { - var buf [32]uintptr - // Skip enough frames to start at user code. - // This number is a mere hint to the following loop - // to start as close to user code as possible and getting it right is not mandatory. - // The skip count might need to get updated if the call to findFrame is - // moved up/down the call stack - n := runtime.Callers(4, buf[:]) - pcs := buf[:n] - frames := runtime.CallersFrames(pcs) - for i := 0; i < n; i++ { - frame, _ := frames.Next() - if !frameIgnorePattern.MatchString(frame.Function) { - return &frameCursor{ - current: &frame, - rest: frames, - n: n, - } - } - } - return nil -} - -func newTraceFromFrames(cursor frameCursor, err error) *trace.TraceErr { - traces := make(trace.Traces, 0, cursor.n) - if cursor.current != nil { - traces = append(traces, frameToTrace(*cursor.current)) - } - for { - frame, more := cursor.rest.Next() - traces = append(traces, frameToTrace(frame)) - if !more { - break - } - } - return &trace.TraceErr{ - Err: err, - Traces: traces, - } -} - -func frameToTrace(frame runtime.Frame) trace.Trace { - return trace.Trace{ - Func: frame.Function, - Path: frame.File, - Line: frame.Line, - } -} diff --git a/lib/utils/log/slog.go b/lib/utils/log/slog.go index 46f0e13627b3e..bfb34f4a94114 100644 --- a/lib/utils/log/slog.go +++ b/lib/utils/log/slog.go @@ -27,7 +27,6 @@ import ( "unicode" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" oteltrace "go.opentelemetry.io/otel/trace" ) @@ -68,25 +67,6 @@ var SupportedLevelsText = []string{ slog.LevelError.String(), } -// SlogLevelToLogrusLevel converts a [slog.Level] to its equivalent -// [logrus.Level]. -func SlogLevelToLogrusLevel(level slog.Level) logrus.Level { - switch level { - case TraceLevel: - return logrus.TraceLevel - case slog.LevelDebug: - return logrus.DebugLevel - case slog.LevelInfo: - return logrus.InfoLevel - case slog.LevelWarn: - return logrus.WarnLevel - case slog.LevelError: - return logrus.ErrorLevel - default: - return logrus.FatalLevel - } -} - // DiscardHandler is a [slog.Handler] that discards all messages. It // is more efficient than a [slog.Handler] which outputs to [io.Discard] since // it performs zero formatting. diff --git a/lib/utils/log/slog_text_handler.go b/lib/utils/log/slog_text_handler.go index 7f93a388977bb..612615ba8582d 100644 --- a/lib/utils/log/slog_text_handler.go +++ b/lib/utils/log/slog_text_handler.go @@ -150,45 +150,12 @@ func (s *SlogTextHandler) Handle(ctx context.Context, r slog.Record) error { // Processing fields in this manner allows users to // configure the level and component position in the output. - // This matches the behavior of the original logrus. All other + // This matches the behavior of the original logrus formatter. All other // fields location in the output message are static. for _, field := range s.cfg.ConfiguredFields { switch field { case LevelField: - var color int - var level string - switch r.Level { - case TraceLevel: - level = "TRACE" - color = gray - case slog.LevelDebug: - level = "DEBUG" - color = gray - case slog.LevelInfo: - level = "INFO" - color = blue - case slog.LevelWarn: - level = "WARN" - color = yellow - case slog.LevelError: - level = "ERROR" - color = red - case slog.LevelError + 1: - level = "FATAL" - color = red - default: - color = blue - level = r.Level.String() - } - - if !s.cfg.EnableColors { - color = noColor - } - - level = padMax(level, defaultLevelPadding) - if color != noColor { - level = fmt.Sprintf("\u001B[%dm%s\u001B[0m", color, level) - } + level := formatLevel(r.Level, s.cfg.EnableColors) if rep == nil { state.appendKey(slog.LevelKey) @@ -211,12 +178,8 @@ func (s *SlogTextHandler) Handle(ctx context.Context, r slog.Record) error { if attr.Key != teleport.ComponentKey { return true } - component = fmt.Sprintf("[%v]", attr.Value) - component = strings.ToUpper(padMax(component, s.cfg.Padding)) - if component[len(component)-1] != ' ' { - component = component[:len(component)-1] + "]" - } + component = formatComponent(attr.Value, s.cfg.Padding) return false }) @@ -271,6 +234,55 @@ func (s *SlogTextHandler) Handle(ctx context.Context, r slog.Record) error { return err } +func formatLevel(value slog.Level, enableColors bool) string { + var color int + var level string + switch value { + case TraceLevel: + level = "TRACE" + color = gray + case slog.LevelDebug: + level = "DEBUG" + color = gray + case slog.LevelInfo: + level = "INFO" + color = blue + case slog.LevelWarn: + level = "WARN" + color = yellow + case slog.LevelError: + level = "ERROR" + color = red + case slog.LevelError + 1: + level = "FATAL" + color = red + default: + color = blue + level = value.String() + } + + if !enableColors { + color = noColor + } + + level = padMax(level, defaultLevelPadding) + if color != noColor { + level = fmt.Sprintf("\u001B[%dm%s\u001B[0m", color, level) + } + + return level +} + +func formatComponent(value slog.Value, padding int) string { + component := fmt.Sprintf("[%v]", value) + component = strings.ToUpper(padMax(component, padding)) + if component[len(component)-1] != ' ' { + component = component[:len(component)-1] + "]" + } + + return component +} + func (s *SlogTextHandler) clone() *SlogTextHandler { // We can't use assignment because we can't copy the mutex. return &SlogTextHandler{ diff --git a/lib/utils/log/writer.go b/lib/utils/log/writer.go deleted file mode 100644 index 77cf3037a8b66..0000000000000 --- a/lib/utils/log/writer.go +++ /dev/null @@ -1,45 +0,0 @@ -/* - * Teleport - * Copyright (C) 2023 Gravitational, Inc. - * - * This program is free software: you can redistribute it and/or modify - * it under the terms of the GNU Affero General Public License as published by - * the Free Software Foundation, either version 3 of the License, or - * (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU Affero General Public License for more details. - * - * You should have received a copy of the GNU Affero General Public License - * along with this program. If not, see . - */ - -package log - -import ( - "io" - "sync" -) - -// SharedWriter is an [io.Writer] implementation that protects -// writes with a mutex. This allows a single [io.Writer] to be shared -// by both logrus and slog without their output clobbering each other. -type SharedWriter struct { - mu sync.Mutex - io.Writer -} - -func (s *SharedWriter) Write(p []byte) (int, error) { - s.mu.Lock() - defer s.mu.Unlock() - - return s.Writer.Write(p) -} - -// NewSharedWriter wraps the provided [io.Writer] in a writer that -// is thread safe. -func NewSharedWriter(w io.Writer) *SharedWriter { - return &SharedWriter{Writer: w} -}