From b3bb90964b45a6a1d11c290547f555fdab6861b6 Mon Sep 17 00:00:00 2001 From: rosstimothy <39066650+rosstimothy@users.noreply.github.com> Date: Thu, 26 Dec 2024 06:37:16 -0500 Subject: [PATCH] Fix: prevent race in slog text handler group handling (#50451) (#50502) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes https://github.com/gravitational/teleport/issues/50450. This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450. Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file. Benchmarks indicate that the changes here don't move the needle much. ``` goos: darwin goarch: arm64 pkg: github.com/gravitational/teleport/lib/utils/log cpu: Apple M2 Pro │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Formatter/logrus/text-12 8.665µ ± 16% 8.187µ ± 9% ~ (p=0.280 n=10) Formatter/logrus/json-12 8.879µ ± 2% 8.820µ ± 1% ~ (p=0.089 n=10) Formatter/slog/default_text-12 3.936µ ± 3% 3.946µ ± 4% ~ (p=0.839 n=10) Formatter/slog/text-12 3.789µ ± 2% 3.431µ ± 1% -9.45% (p=0.000 n=10) Formatter/slog/default_json-12 3.005µ ± 4% 3.032µ ± 3% ~ (p=0.739 n=10) Formatter/slog/json-12 3.029µ ± 6% 3.022µ ± 1% ~ (p=0.381 n=10) geomean 4.675µ 4.557µ -2.52% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Formatter/logrus/text-12 5.936Ki ± 0% 5.936Ki ± 0% ~ (p=0.752 n=10) Formatter/logrus/json-12 6.212Ki ± 0% 6.211Ki ± 0% ~ (p=0.752 n=10) Formatter/slog/default_text-12 2.534Ki ± 0% 2.534Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 2.144Ki ± 0% 2.167Ki ± 0% +1.09% (p=0.000 n=10) Formatter/slog/default_json-12 2.448Ki ± 0% 2.448Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 2.318Ki ± 0% 2.318Ki ± 0% ~ (p=1.000 n=10) ¹ geomean 3.231Ki 3.236Ki +0.18% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Formatter/logrus/text-12 54.00 ± 0% 54.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/logrus/json-12 76.00 ± 0% 76.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/default_text-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 52.00 ± 0% 33.00 ± 0% -36.54% (p=0.000 n=10) Formatter/slog/default_json-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 42.00 ± 0% 42.00 ± 0% ~ (p=1.000 n=10) ¹ geomean 49.70 46.07 -7.30% ¹ all samples are equal ``` --- lib/utils/log/buffer.go | 37 +- lib/utils/log/formatter_test.go | 17 +- lib/utils/log/handle_state.go | 352 +++++++++++++++ lib/utils/log/logrus_formatter.go | 2 +- lib/utils/log/slog.go | 131 ++++++ lib/utils/log/slog_handler.go | 681 ----------------------------- lib/utils/log/slog_handler_test.go | 12 +- lib/utils/log/slog_json_handler.go | 167 +++++++ lib/utils/log/slog_text_handler.go | 359 +++++++++++++++ 9 files changed, 1034 insertions(+), 724 deletions(-) create mode 100644 lib/utils/log/handle_state.go create mode 100644 lib/utils/log/slog.go delete mode 100644 lib/utils/log/slog_handler.go create mode 100644 lib/utils/log/slog_json_handler.go create mode 100644 lib/utils/log/slog_text_handler.go diff --git a/lib/utils/log/buffer.go b/lib/utils/log/buffer.go index c158808bd545c..d12ac9e11bab0 100644 --- a/lib/utils/log/buffer.go +++ b/lib/utils/log/buffer.go @@ -21,6 +21,14 @@ func newBuffer() *buffer { return bufPool.Get().(*buffer) } +func (b *buffer) Len() int { + return len(*b) +} + +func (b *buffer) SetLen(n int) { + *b = (*b)[:n] +} + func (b *buffer) Free() { // To reduce peak allocation, return only smaller buffers to the pool. const maxBufferSize = 16 << 10 @@ -49,35 +57,6 @@ func (b *buffer) WriteByte(c byte) error { return nil } -func (b *buffer) WritePosInt(i int) { - b.WritePosIntWidth(i, 0) -} - -// WritePosIntWidth writes non-negative integer i to the buffer, padded on the left -// by zeroes to the given width. Use a width of 0 to omit padding. -func (b *buffer) WritePosIntWidth(i, width int) { - // Cheap integer to fixed-width decimal ASCII. - // Copied from log/log.go. - - if i < 0 { - panic("negative int") - } - - // Assemble decimal in reverse order. - var bb [20]byte - bp := len(bb) - 1 - for i >= 10 || width > 1 { - width-- - q := i / 10 - bb[bp] = byte('0' + i - q*10) - bp-- - i = q - } - // i < 10 - bb[bp] = byte('0' + i) - b.Write(bb[bp:]) -} - func (b *buffer) String() string { return string(*b) } diff --git a/lib/utils/log/formatter_test.go b/lib/utils/log/formatter_test.go index 39c717df3425d..e11a9f63620fb 100644 --- a/lib/utils/log/formatter_test.go +++ b/lib/utils/log/formatter_test.go @@ -45,7 +45,7 @@ import ( "github.com/gravitational/teleport" ) -const message = "Adding diagnostic debugging handlers.\t To connect with profiler, use `go tool pprof diag_addr`." +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") @@ -76,7 +76,6 @@ func TestOutput(t *testing.T) { loc, err := time.LoadLocation("Africa/Cairo") require.NoError(t, err, "failed getting timezone") clock := clockwork.NewFakeClockAt(time.Now().In(loc)) - formattedNow := clock.Now().UTC().Format(time.RFC3339) t.Run("text", func(t *testing.T) { // fieldsRegex matches all the key value pairs emitted after the message and before the caller. All fields are @@ -88,7 +87,7 @@ func TestOutput(t *testing.T) { // 2) the message // 3) the fields // 4) the caller - outputRegex := regexp.MustCompile("(\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}Z)(\\s+.*)(\".*diag_addr`\\.\")(.*)(\\slog/formatter_test.go:\\d{3})") + 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})`) tests := []struct { name string @@ -149,7 +148,7 @@ func TestOutput(t *testing.T) { EnableColors: true, ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { if a.Key == slog.TimeKey { - a.Value = slog.StringValue(formattedNow) + a.Value = slog.TimeValue(clock.Now().UTC()) } return a }, @@ -188,7 +187,7 @@ func TestOutput(t *testing.T) { // 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" + // 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") // The last matches are the caller information assert.Equal(t, fmt.Sprintf(" log/formatter_test.go:%d", logrusTestLogLineNumber), logrusMatches[5]) @@ -461,7 +460,13 @@ func TestConcurrentOutput(t *testing.T) { wg.Add(1) go func(i int) { defer wg.Done() - logger.InfoContext(ctx, "Teleport component entered degraded state", "component", i) + 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() diff --git a/lib/utils/log/handle_state.go b/lib/utils/log/handle_state.go new file mode 100644 index 0000000000000..c60132b28e48e --- /dev/null +++ b/lib/utils/log/handle_state.go @@ -0,0 +1,352 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package log + +import ( + "encoding" + "fmt" + "log/slog" + "reflect" + "strconv" + "sync" + "time" + + "github.com/gravitational/trace" + "github.com/sirupsen/logrus" + + "github.com/gravitational/teleport" +) + +// handleState adapted from go/src/log/slog/handler.go +type handleState struct { + h *SlogTextHandler + buf *buffer + freeBuf bool // should buf be freed? + prefix *buffer // for text: key prefix + groups *[]string // pool-allocated slice of active groups, for ReplaceAttr +} + +var groupPool = sync.Pool{New: func() any { + s := make([]string, 0, 10) + return &s +}} + +func (s *handleState) free() { + if s.freeBuf { + s.buf.Free() + } + if gs := s.groups; gs != nil { + *gs = (*gs)[:0] + groupPool.Put(gs) + } + s.prefix.Free() +} + +func (s *handleState) openGroups() { + for _, n := range s.h.groups[s.h.nOpenGroups:] { + s.openGroup(n) + } +} + +// openGroup starts a new group of attributes +// with the given name. +func (s *handleState) openGroup(name string) { + s.prefix.WriteString(name) + s.prefix.WriteByte('.') + + // Collect group names for ReplaceAttr. + if s.groups != nil { + *s.groups = append(*s.groups, name) + } +} + +// closeGroup ends the group with the given name. +func (s *handleState) closeGroup(name string) { + *s.prefix = (*s.prefix)[:len(*s.prefix)-len(name)-1 /* for keyComponentSep */] + + if s.groups != nil { + *s.groups = (*s.groups)[:len(*s.groups)-1] + } +} + +// appendAttrs appends the slice of Attrs. +// It reports whether something was appended. +func (s *handleState) appendAttrs(as []slog.Attr) bool { + nonEmpty := false + for _, a := range as { + if s.appendAttr(a) { + nonEmpty = true + } + } + return nonEmpty +} + +// appendAttr appends the Attr's key and value. +// It handles replacement and checking for an empty key. +// It reports whether something was appended. +func (s *handleState) appendAttr(a slog.Attr) bool { + a.Value = a.Value.Resolve() + if rep := s.h.cfg.ReplaceAttr; rep != nil && a.Value.Kind() != slog.KindGroup { + var gs []string + if s.groups != nil { + gs = *s.groups + } + // a.Value is resolved before calling ReplaceAttr, so the user doesn't have to. + a = rep(gs, a) + // The ReplaceAttr function may return an unresolved Attr. + a.Value = a.Value.Resolve() + } + // Elide empty Attrs. + if a.Equal(slog.Attr{}) { + return false + } + + // Handle nested attributes from within component fields. + if a.Key == teleport.ComponentFields { + nonEmpty := false + switch fields := a.Value.Any().(type) { + case map[string]any: + for k, v := range fields { + if s.appendAttr(slog.Any(k, v)) { + nonEmpty = true + } + } + return nonEmpty + case logrus.Fields: + for k, v := range fields { + if s.appendAttr(slog.Any(k, v)) { + nonEmpty = true + } + } + return nonEmpty + } + } + + // Handle special cases before formatting. + if a.Value.Kind() == slog.KindAny { + switch v := a.Value.Any().(type) { + case *slog.Source: + a.Value = slog.StringValue(fmt.Sprintf(" %s:%d", v.File, v.Line)) + case trace.Error: + a.Value = slog.StringValue("[" + v.DebugReport() + "]") + case error: + a.Value = slog.StringValue(fmt.Sprintf("[%v]", v)) + } + } + + if a.Value.Kind() == slog.KindGroup { + attrs := a.Value.Group() + // Output only non-empty groups. + if len(attrs) > 0 { + // The group may turn out to be empty even though it has attrs (for + // example, ReplaceAttr may delete all the attrs). + // So remember where we are in the buffer, to restore the position + // later if necessary. + pos := s.buf.Len() + // Inline a group with an empty key. + if a.Key != "" { + s.openGroup(a.Key) + } + if !s.appendAttrs(attrs) { + s.buf.SetLen(pos) + return false + } + if a.Key != "" { + s.closeGroup(a.Key) + } + } + + return true + } + + if a.Value.Kind() == slog.KindString && a.Key != slog.LevelKey { + val := a.Value.String() + if needsQuoting(val) { + a.Value = slog.StringValue(strconv.Quote(val)) + } + } + + s.appendKey(a.Key) + + // Write the log key directly to avoid quoting + // color formatting that exists. + if a.Key == slog.LevelKey { + s.buf.WriteString(a.Value.String()) + } else { + s.appendValue(a.Value) + } + + return true +} + +func (s *handleState) appendError(err error) { + s.appendString(fmt.Sprintf("!ERROR:%v", err)) +} + +func (s *handleState) appendKey(key string) { + if s.buf.Len() > 0 { + s.buf.WriteString(" ") + } + + // These keys should not be included in the output to match + // the behavior of the lorgus formatter. + if key == slog.TimeKey || + key == teleport.ComponentKey || + key == slog.LevelKey || + key == CallerField || + key == slog.MessageKey || + key == slog.SourceKey { + return + } + + if s.prefix != nil && len(*s.prefix) > 0 { + // TODO: optimize by avoiding allocation. + s.appendString(string(*s.prefix) + key) + } else { + s.appendString(key) + } + + s.buf.WriteByte(':') +} + +func (s *handleState) appendString(str string) { + if str == "" { + return + } + + if needsQuoting(str) { + *s.buf = strconv.AppendQuote(*s.buf, str) + } else { + s.buf.WriteString(str) + } +} + +func (s *handleState) appendValue(v slog.Value) { + defer func() { + if r := recover(); r != nil { + // If it panics with a nil pointer, the most likely cases are + // an encoding.TextMarshaler or error fails to guard against nil, + // in which case "" seems to be the feasible choice. + // + // Adapted from the code in fmt/print.go. + if v := reflect.ValueOf(v.Any()); v.Kind() == reflect.Pointer && v.IsNil() { + s.appendString("") + return + } + + // Otherwise just print the original panic message. + s.appendString(fmt.Sprintf("!PANIC: %v", r)) + } + }() + + if err := appendTextValue(s, v); err != nil { + s.appendError(err) + } +} + +func (s *handleState) appendTime(t time.Time) { + *s.buf = appendRFC3339Millis(*s.buf, t) +} + +func (s *handleState) appendNonBuiltIns(r slog.Record) { + // preformatted Attrs + if pfa := s.h.preformatted; len(pfa) > 0 { + s.buf.WriteString(" ") + s.buf.Write(pfa) + } + // Attrs in Record -- unlike the built-in ones, they are in groups started + // from WithGroup. + // If the record has no Attrs, don't output any groups. + if r.NumAttrs() > 0 { + s.prefix.WriteString(s.h.groupPrefix) + // The group may turn out to be empty even though it has attrs (for + // example, ReplaceAttr may delete all the attrs). + // So remember where we are in the buffer, to restore the position + // later if necessary. + pos := s.buf.Len() + s.openGroups() + empty := true + r.Attrs(func(a slog.Attr) bool { + // The component is handled by the top level handler. + if a.Key == teleport.ComponentKey { + return true + } + if s.appendAttr(a) { + empty = false + } + return true + }) + if empty { + s.buf.SetLen(pos) + } + } +} + +func byteSlice(a any) ([]byte, bool) { + if bs, ok := a.([]byte); ok { + return bs, true + } + // Like Printf's %s, we allow both the slice type and the byte element type to be named. + t := reflect.TypeOf(a) + if t != nil && t.Kind() == reflect.Slice && t.Elem().Kind() == reflect.Uint8 { + return reflect.ValueOf(a).Bytes(), true + } + return nil, false +} + +func appendTextValue(s *handleState, v slog.Value) error { + switch v.Kind() { + case slog.KindString: + s.appendString(v.String()) + case slog.KindTime: + s.appendTime(v.Time()) + case slog.KindAny: + if tm, ok := v.Any().(encoding.TextMarshaler); ok { + data, err := tm.MarshalText() + if err != nil { + return err + } + // TODO: avoid the conversion to string. + s.appendString(string(data)) + return nil + } + if bs, ok := byteSlice(v.Any()); ok { + // As of Go 1.19, this only allocates for strings longer than 32 bytes. + s.buf.WriteString(strconv.Quote(string(bs))) + return nil + } + s.appendString(fmt.Sprintf("%+v", v.Any())) + case slog.KindInt64: + *s.buf = strconv.AppendInt(*s.buf, v.Int64(), 10) + case slog.KindUint64: + *s.buf = strconv.AppendUint(*s.buf, v.Uint64(), 10) + case slog.KindFloat64: + *s.buf = strconv.AppendFloat(*s.buf, v.Float64(), 'g', -1, 64) + case slog.KindBool: + *s.buf = strconv.AppendBool(*s.buf, v.Bool()) + case slog.KindDuration: + *s.buf = append(*s.buf, v.Duration().String()...) + case slog.KindGroup: + *s.buf = fmt.Append(*s.buf, v.Group()) + case slog.KindLogValuer: + *s.buf = fmt.Append(*s.buf, v.Any()) + default: + panic(fmt.Sprintf("bad kind: %s", v.Kind())) + } + return nil +} + +func appendRFC3339Millis(b []byte, t time.Time) []byte { + // Format according to time.RFC3339Nano since it is highly optimized, + // but truncate it to use millisecond resolution. + // Unfortunately, that format trims trailing 0s, so add 1/10 millisecond + // to guarantee that there are exactly 4 digits after the period. + const prefixLen = len("2006-01-02T15:04:05.000") + n := len(b) + t = t.Truncate(time.Millisecond).Add(time.Millisecond / 10) + b = t.AppendFormat(b, time.RFC3339Nano) + b = append(b[:n+prefixLen], b[n+prefixLen+1:]...) // drop the 4th digit + return b +} diff --git a/lib/utils/log/logrus_formatter.go b/lib/utils/log/logrus_formatter.go index 87b3bff3bdc24..a21d922adf809 100644 --- a/lib/utils/log/logrus_formatter.go +++ b/lib/utils/log/logrus_formatter.go @@ -145,7 +145,7 @@ func (tf *TextFormatter) Format(e *logrus.Entry) ([]byte, error) { // write timestamp first if enabled if tf.timestampEnabled { - writeTimeRFC3339(w.b, e.Time) + *w.b = appendRFC3339Millis(*w.b, e.Time.Round(0)) } for _, field := range tf.ExtraFields { diff --git a/lib/utils/log/slog.go b/lib/utils/log/slog.go new file mode 100644 index 0000000000000..b1b0678ec5487 --- /dev/null +++ b/lib/utils/log/slog.go @@ -0,0 +1,131 @@ +/* + * 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 ( + "context" + "fmt" + "log/slog" + "reflect" + "strings" + + oteltrace "go.opentelemetry.io/otel/trace" +) + +const ( + // TraceLevel is the logging level when set to Trace verbosity. + TraceLevel = slog.LevelDebug - 1 + + // TraceLevelText is the text representation of Trace verbosity. + TraceLevelText = "TRACE" +) + +// 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. +// TODO(tross): Use slog.DiscardHandler once upgraded to Go 1.24. +type DiscardHandler struct{} + +func (dh DiscardHandler) Enabled(context.Context, slog.Level) bool { return false } +func (dh DiscardHandler) Handle(context.Context, slog.Record) error { return nil } +func (dh DiscardHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return dh } +func (dh DiscardHandler) WithGroup(name string) slog.Handler { return dh } + +func addTracingContextToRecord(ctx context.Context, r *slog.Record) { + const ( + traceID = "trace_id" + spanID = "span_id" + ) + + span := oteltrace.SpanFromContext(ctx) + if span == nil { + return + } + + spanContext := span.SpanContext() + if spanContext.HasTraceID() { + r.AddAttrs(slog.String(traceID, spanContext.TraceID().String())) + } + + if spanContext.HasSpanID() { + r.AddAttrs(slog.String(spanID, spanContext.SpanID().String())) + } +} + +// getCaller retrieves source information from the attribute +// and returns the file and line of the caller. The file is +// truncated from the absolute path to package/filename. +func getCaller(s *slog.Source) (file string, line int) { + count := 0 + idx := strings.LastIndexFunc(s.File, func(r rune) bool { + if r == '/' { + count++ + } + + return count == 2 + }) + file = s.File[idx+1:] + line = s.Line + + return file, line +} + +type stringerAttr struct { + fmt.Stringer +} + +// StringerAttr creates a [slog.LogValuer] that will defer to +// the provided [fmt.Stringer]. All slog attributes are always evaluated, +// even if the log event is discarded due to the configured log level. +// A text [slog.Handler] will try to defer evaluation if the attribute is a +// [fmt.Stringer], however, the JSON [slog.Handler] only defers to [json.Marshaler]. +// This means that to defer evaluation and creation of the string representation, +// the object must implement [fmt.Stringer] and [json.Marshaler], otherwise additional +// and unwanted values may be emitted if the logger is configured to use JSON +// instead of text. This wrapping mechanism allows a value that implements [fmt.Stringer], +// to be guaranteed to be lazily constructed and always output the same +// content regardless of the output format. +func StringerAttr(s fmt.Stringer) slog.LogValuer { + return stringerAttr{Stringer: s} +} + +func (s stringerAttr) LogValue() slog.Value { + if s.Stringer == nil { + return slog.StringValue("") + } + return slog.StringValue(s.Stringer.String()) +} + +type typeAttr struct { + val any +} + +// TypeAttr creates a lazily evaluated log value that presents the pretty type name of a value +// as a string. It is roughly equivalent to the '%T' format option, and should only perform +// reflection in the event that logs are actually being generated. +func TypeAttr(val any) slog.LogValuer { + return typeAttr{val} +} + +func (a typeAttr) LogValue() slog.Value { + if t := reflect.TypeOf(a.val); t != nil { + return slog.StringValue(t.String()) + } + return slog.StringValue("nil") +} diff --git a/lib/utils/log/slog_handler.go b/lib/utils/log/slog_handler.go deleted file mode 100644 index b69b83d2a1adb..0000000000000 --- a/lib/utils/log/slog_handler.go +++ /dev/null @@ -1,681 +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 ( - "context" - "fmt" - "io" - "log/slog" - "reflect" - "runtime" - "slices" - "strconv" - "strings" - "sync" - "time" - - "github.com/gravitational/trace" - "github.com/sirupsen/logrus" - oteltrace "go.opentelemetry.io/otel/trace" - - "github.com/gravitational/teleport" -) - -// TraceLevel is the logging level when set to Trace verbosity. -const TraceLevel = slog.LevelDebug - 1 - -// TraceLevelText is the text representation of Trace verbosity. -const TraceLevelText = "TRACE" - -// SlogTextHandler is a [slog.Handler] that outputs messages in a textual -// manner as configured by the Teleport configuration. -type SlogTextHandler struct { - cfg SlogTextHandlerConfig - // withCaller indicates whether the location the log was emitted from - // should be included in the output message. - withCaller bool - // withTimestamp indicates whether the times that the log was emitted at - // should be included in the output message. - withTimestamp bool - // component is the Teleport subcomponent that emitted the log. - component string - // preformatted data from previous calls to WithGroup and WithAttrs. - preformatted []byte - // groupPrefix is for the text handler only. - // It holds the prefix for groups that were already pre-formatted. - // A group will appear here when a call to WithGroup is followed by - // a call to WithAttrs. - groupPrefix buffer - // groups passed in via WithGroup and WithAttrs. - groups []string - // nOpenGroups the number of groups opened in preformatted. - nOpenGroups int - - // mu protects out - it needs to be a pointer so that all cloned - // SlogTextHandler returned from WithAttrs and WithGroup share the - // same mutex. Otherwise, output may be garbled since each clone - // will use its own copy of the mutex to protect out. See - // https://github.com/golang/go/issues/61321 for more details. - mu *sync.Mutex - out io.Writer -} - -// SlogTextHandlerConfig allow the SlogTextHandler functionality -// to be tweaked. -type SlogTextHandlerConfig struct { - // Level is the minimum record level that will be logged. - Level slog.Leveler - // EnableColors allows the level to be printed in color. - EnableColors bool - // Padding to use for various components. - Padding int - // ConfiguredFields are fields explicitly set by users to be included in - // the output message. If there are any entries configured, they will be honored. - // If empty, the default fields will be populated and included in the output. - ConfiguredFields []string - // ReplaceAttr is called to rewrite each non-group attribute before - // it is logged. - ReplaceAttr func(groups []string, a slog.Attr) slog.Attr -} - -// NewSlogTextHandler creates a SlogTextHandler that writes messages to w. -func NewSlogTextHandler(w io.Writer, cfg SlogTextHandlerConfig) *SlogTextHandler { - if cfg.Padding == 0 { - cfg.Padding = defaultComponentPadding - } - - handler := SlogTextHandler{ - cfg: cfg, - withCaller: len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, CallerField), - withTimestamp: len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, TimestampField), - out: w, - mu: &sync.Mutex{}, - } - - if handler.cfg.ConfiguredFields == nil { - handler.cfg.ConfiguredFields = defaultFormatFields - } - - return &handler -} - -// Enabled returns whether the provided level will be included in output. -func (s *SlogTextHandler) Enabled(ctx context.Context, level slog.Level) bool { - minLevel := slog.LevelInfo - if s.cfg.Level != nil { - minLevel = s.cfg.Level.Level() - } - return level >= minLevel -} - -func (s *SlogTextHandler) appendAttr(buf []byte, a slog.Attr) []byte { - if rep := s.cfg.ReplaceAttr; rep != nil && a.Value.Kind() != slog.KindGroup { - var gs []string - if s.groups != nil { - gs = s.groups - } - // Resolve before calling ReplaceAttr, so the user doesn't have to. - a.Value = a.Value.Resolve() - a = rep(gs, a) - } - - // Resolve the Attr's value before doing anything else. - a.Value = a.Value.Resolve() - // Ignore empty Attrs. - if a.Equal(slog.Attr{}) { - return buf - } - - switch a.Value.Kind() { - case slog.KindString: - value := a.Value.String() - if a.Key == slog.TimeKey { - buf = fmt.Append(buf, value) - break - } - - if a.Key == teleport.ComponentFields { - switch fields := a.Value.Any().(type) { - case map[string]any: - for k, v := range fields { - buf = s.appendAttr(buf, slog.Any(k, v)) - } - case logrus.Fields: - for k, v := range fields { - buf = s.appendAttr(buf, slog.Any(k, v)) - } - } - } - - if needsQuoting(value) { - if a.Key == teleport.ComponentKey || a.Key == slog.LevelKey || a.Key == CallerField || a.Key == slog.MessageKey { - if len(buf) > 0 { - buf = fmt.Append(buf, " ") - } - } else { - if len(buf) > 0 { - buf = fmt.Append(buf, " ") - } - buf = fmt.Appendf(buf, "%s%s:", s.groupPrefix, a.Key) - } - buf = strconv.AppendQuote(buf, value) - break - } - - if a.Key == teleport.ComponentKey || a.Key == slog.LevelKey || a.Key == CallerField || a.Key == slog.MessageKey { - if len(buf) > 0 { - buf = fmt.Append(buf, " ") - } - buf = fmt.Appendf(buf, "%s", a.Value.String()) - break - } - - buf = fmt.Appendf(buf, " %s%s:%s", s.groupPrefix, a.Key, a.Value.String()) - case slog.KindGroup: - attrs := a.Value.Group() - // Ignore empty groups. - if len(attrs) == 0 { - return buf - } - // If the key is non-empty, write it out and indent the rest of the attrs. - // Otherwise, inline the attrs. - if a.Key != "" { - s.groupPrefix = fmt.Append(s.groupPrefix, a.Key) - s.groupPrefix = fmt.Append(s.groupPrefix, ".") - } - for _, ga := range attrs { - buf = s.appendAttr(buf, ga) - } - if a.Key != "" { - s.groupPrefix = s.groupPrefix[:len(s.groupPrefix)-len(a.Key)-1 /* for keyComponentSep */] - if s.groups != nil { - s.groups = (s.groups)[:len(s.groups)-1] - } - } - default: - switch err := a.Value.Any().(type) { - case trace.Error: - buf = fmt.Appendf(buf, " error:[%v]", err.DebugReport()) - case error: - buf = fmt.Appendf(buf, " error:[%v]", a.Value) - default: - buf = fmt.Appendf(buf, " %s:%s", a.Key, a.Value) - } - } - return buf -} - -// writeTimeRFC3339 writes the time in [time.RFC3339Nano] to the buffer. -// This takes half the time of [time.Time.AppendFormat]. Adapted from -// go/src/log/slog/handler.go. -func writeTimeRFC3339(buf *buffer, t time.Time) { - year, month, day := t.Date() - buf.WritePosIntWidth(year, 4) - buf.WriteByte('-') - buf.WritePosIntWidth(int(month), 2) - buf.WriteByte('-') - buf.WritePosIntWidth(day, 2) - buf.WriteByte('T') - hour, min, sec := t.Clock() - buf.WritePosIntWidth(hour, 2) - buf.WriteByte(':') - buf.WritePosIntWidth(min, 2) - buf.WriteByte(':') - buf.WritePosIntWidth(sec, 2) - _, offsetSeconds := t.Zone() - if offsetSeconds == 0 { - buf.WriteByte('Z') - } else { - offsetMinutes := offsetSeconds / 60 - if offsetMinutes < 0 { - buf.WriteByte('-') - offsetMinutes = -offsetMinutes - } else { - buf.WriteByte('+') - } - buf.WritePosIntWidth(offsetMinutes/60, 2) - buf.WriteByte(':') - buf.WritePosIntWidth(offsetMinutes%60, 2) - } -} - -// Handle formats the provided record and writes the output to the -// destination. -func (s *SlogTextHandler) Handle(ctx context.Context, r slog.Record) error { - buf := newBuffer() - defer buf.Free() - - addTracingContextToRecord(ctx, &r) - - if s.withTimestamp && !r.Time.IsZero() { - if s.cfg.ReplaceAttr != nil { - *buf = s.appendAttr(*buf, slog.Time(slog.TimeKey, r.Time)) - } else { - writeTimeRFC3339(buf, r.Time) - } - } - - // 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 - // 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 { - *buf = s.appendAttr(*buf, slog.String(slog.LevelKey, level)) - } else { - *buf = fmt.Appendf(*buf, " \u001B[%dm%s\u001B[0m", color, level) - } - case ComponentField: - // If a component is provided with the attributes, it should be used instead of - // the component set on the handler. Note that if there are multiple components - // specified in the arguments, the one with the lowest index is used and the others are ignored. - // In the example below, the resulting component in the message output would be "alpaca". - // - // logger := logger.With(teleport.ComponentKey, "fish") - // logger.InfoContext(ctx, "llama llama llama", teleport.ComponentKey, "alpaca", "foo", 123, teleport.ComponentKey, "shark") - component := s.component - r.Attrs(func(attr slog.Attr) bool { - if attr.Key == teleport.ComponentKey { - component = fmt.Sprintf("[%v]", attr.Value) - component = strings.ToUpper(padMax(component, s.cfg.Padding)) - if component[len(component)-1] != ' ' { - component = component[:len(component)-1] + "]" - } - - return false - } - - return true - }) - - *buf = s.appendAttr(*buf, slog.String(teleport.ComponentKey, component)) - default: - if _, ok := knownFormatFields[field]; !ok { - return trace.BadParameter("invalid log format key: %v", field) - } - } - } - - *buf = s.appendAttr(*buf, slog.String(slog.MessageKey, r.Message)) - - // Insert preformatted attributes just after built-in ones. - *buf = append(*buf, s.preformatted...) - if r.NumAttrs() > 0 { - if len(s.groups) > 0 { - for _, n := range s.groups[s.nOpenGroups:] { - s.groupPrefix = fmt.Append(s.groupPrefix, n) - s.groupPrefix = fmt.Append(s.groupPrefix, ".") - } - } - - r.Attrs(func(a slog.Attr) bool { - // Skip adding any component attrs since they are processed above. - if a.Key == teleport.ComponentKey { - return true - } - - *buf = s.appendAttr(*buf, a) - return true - }) - } - - if r.PC != 0 && s.withCaller { - fs := runtime.CallersFrames([]uintptr{r.PC}) - f, _ := fs.Next() - - src := &slog.Source{ - Function: f.Function, - File: f.File, - Line: f.Line, - } - - file, line := getCaller(src) - *buf = fmt.Appendf(*buf, " %s:%d", file, line) - } - - buf.WriteByte('\n') - - s.mu.Lock() - defer s.mu.Unlock() - _, err := s.out.Write(*buf) - return err -} - -// WithAttrs clones the current handler with the provided attributes -// added to any existing attributes. The values are preformatted here -// so that they do not need to be formatted per call to Handle. -func (s *SlogTextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - if len(attrs) == 0 { - return s - } - s2 := *s - // Force an append to copy the underlying arrays. - s2.preformatted = slices.Clip(s.preformatted) - s2.groups = slices.Clip(s.groups) - - // Add all groups from WithGroup that haven't already been added to the prefix. - if len(s.groups) > 0 { - for _, n := range s.groups[s.nOpenGroups:] { - s2.groupPrefix = fmt.Append(s2.groupPrefix, n) - s2.groupPrefix = fmt.Append(s2.groupPrefix, ".") - } - } - - // Now all groups have been opened. - s2.nOpenGroups = len(s2.groups) - - component := s.component - - // Pre-format the attributes. - for _, a := range attrs { - switch a.Key { - case teleport.ComponentKey: - component = fmt.Sprintf("[%v]", a.Value.String()) - component = strings.ToUpper(padMax(component, s.cfg.Padding)) - if component[len(component)-1] != ' ' { - component = component[:len(component)-1] + "]" - } - case teleport.ComponentFields: - switch fields := a.Value.Any().(type) { - case map[string]any: - for k, v := range fields { - s2.appendAttr(s2.preformatted, slog.Any(k, v)) - } - case logrus.Fields: - for k, v := range fields { - s2.preformatted = s2.appendAttr(s2.preformatted, slog.Any(k, v)) - } - } - default: - s2.preformatted = s2.appendAttr(s2.preformatted, a) - } - } - - s2.component = component - // Remember how many opened groups are in preformattedAttrs, - // so we don't open them again when we handle a Record. - s2.nOpenGroups = len(s2.groups) - return &s2 -} - -// WithGroup opens a new group. -func (s *SlogTextHandler) WithGroup(name string) slog.Handler { - if name == "" { - return s - } - - s2 := *s - s2.groups = append(s2.groups, name) - return &s2 -} - -// SlogJSONHandlerConfig allow the SlogJSONHandler functionality -// to be tweaked. -type SlogJSONHandlerConfig struct { - // Level is the minimum record level that will be logged. - Level slog.Leveler - // ConfiguredFields are fields explicitly set by users to be included in - // the output message. If there are any entries configured, they will be honored. - // If empty, the default fields will be populated and included in the output. - ConfiguredFields []string - // ReplaceAttr is called to rewrite each non-group attribute before - // it is logged. - ReplaceAttr func(groups []string, a slog.Attr) slog.Attr -} - -// SlogJSONHandler is a [slog.Handler] that outputs messages in a json -// format per the config file. -type SlogJSONHandler struct { - *slog.JSONHandler -} - -// NewSlogJSONHandler creates a SlogJSONHandler that outputs to w. -func NewSlogJSONHandler(w io.Writer, cfg SlogJSONHandlerConfig) *SlogJSONHandler { - withCaller := len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, CallerField) - withComponent := len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, ComponentField) - withTimestamp := len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, TimestampField) - - return &SlogJSONHandler{ - JSONHandler: slog.NewJSONHandler(w, &slog.HandlerOptions{ - AddSource: true, - Level: cfg.Level, - ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { - switch a.Key { - case teleport.ComponentKey: - if !withComponent { - return slog.Attr{} - } - if a.Value.Kind() != slog.KindString { - return a - } - - a.Key = ComponentField - case slog.LevelKey: - // The slog.JSONHandler will inject "level" Attr. - // However, this lib's consumer might add an Attr using the same key ("level") and we end up with two records named "level". - // We must check its type before assuming this was injected by the slog.JSONHandler. - lvl, ok := a.Value.Any().(slog.Level) - if !ok { - return a - } - - var level string - switch lvl { - case TraceLevel: - level = "trace" - case slog.LevelDebug: - level = "debug" - case slog.LevelInfo: - level = "info" - case slog.LevelWarn: - level = "warning" - case slog.LevelError: - level = "error" - case slog.LevelError + 1: - level = "fatal" - default: - level = strings.ToLower(lvl.String()) - } - - a.Value = slog.StringValue(level) - case slog.TimeKey: - if !withTimestamp { - return slog.Attr{} - } - - // The slog.JSONHandler will inject "time" Attr. - // However, this lib's consumer might add an Attr using the same key ("time") and we end up with two records named "time". - // We must check its type before assuming this was injected by the slog.JSONHandler. - if a.Value.Kind() != slog.KindTime { - return a - } - - t := a.Value.Time() - if t.IsZero() { - return a - } - - a.Key = TimestampField - a.Value = slog.StringValue(t.Format(time.RFC3339)) - case slog.MessageKey: - // The slog.JSONHandler will inject "msg" Attr. - // However, this lib's consumer might add an Attr using the same key ("msg") and we end up with two records named "msg". - // We must check its type before assuming this was injected by the slog.JSONHandler. - if a.Value.Kind() != slog.KindString { - return a - } - a.Key = messageField - case slog.SourceKey: - if !withCaller { - return slog.Attr{} - } - - // The slog.JSONHandler will inject "source" Attr when AddSource is true. - // However, this lib's consumer might add an Attr using the same key ("source") and we end up with two records named "source". - // We must check its type before assuming this was injected by the slog.JSONHandler. - s, ok := a.Value.Any().(*slog.Source) - if !ok { - return a - } - - file, line := getCaller(s) - a = slog.String(CallerField, fmt.Sprintf("%s:%d", file, line)) - } - - // Convert [slog.KindAny] values that are backed by an [error] or [fmt.Stringer] - // to strings so that only the message is output instead of a json object. The kind is - // first checked to avoid allocating an interface for the values stored inline - // in [slog.Attr]. - if a.Value.Kind() == slog.KindAny { - if err, ok := a.Value.Any().(error); ok { - a.Value = slog.StringValue(err.Error()) - } - - if stringer, ok := a.Value.Any().(fmt.Stringer); ok { - a.Value = slog.StringValue(stringer.String()) - } - } - - return a - }, - }), - } -} - -const ( - traceID = "trace_id" - spanID = "span_id" -) - -func addTracingContextToRecord(ctx context.Context, r *slog.Record) { - span := oteltrace.SpanFromContext(ctx) - if span == nil { - return - } - - spanContext := span.SpanContext() - if spanContext.HasTraceID() { - r.AddAttrs(slog.String(traceID, spanContext.TraceID().String())) - } - - if spanContext.HasSpanID() { - r.AddAttrs(slog.String(spanID, spanContext.SpanID().String())) - } -} - -func (j *SlogJSONHandler) Handle(ctx context.Context, r slog.Record) error { - addTracingContextToRecord(ctx, &r) - return j.JSONHandler.Handle(ctx, r) -} - -// getCaller retrieves source information from the attribute -// and returns the file and line of the caller. The file is -// truncated from the absolute path to package/filename. -func getCaller(s *slog.Source) (file string, line int) { - count := 0 - idx := strings.LastIndexFunc(s.File, func(r rune) bool { - if r == '/' { - count++ - } - - return count == 2 - }) - file = s.File[idx+1:] - line = s.Line - - return file, line -} - -type stringerAttr struct { - fmt.Stringer -} - -// StringerAttr creates a [slog.LogValuer] that will defer to -// the provided [fmt.Stringer]. All slog attributes are always evaluated, -// even if the log event is discarded due to the configured log level. -// A text [slog.Handler] will try to defer evaluation if the attribute is a -// [fmt.Stringer], however, the JSON [slog.Handler] only defers to [json.Marshaler]. -// This means that to defer evaluation and creation of the string representation, -// the object must implement [fmt.Stringer] and [json.Marshaler], otherwise additional -// and unwanted values may be emitted if the logger is configured to use JSON -// instead of text. This wrapping mechanism allows a value that implements [fmt.Stringer], -// to be guaranteed to be lazily constructed and always output the same -// content regardless of the output format. -func StringerAttr(s fmt.Stringer) slog.LogValuer { - return stringerAttr{Stringer: s} -} - -func (s stringerAttr) LogValue() slog.Value { - if s.Stringer == nil { - return slog.StringValue("") - } - return slog.StringValue(s.Stringer.String()) -} - -type typeAttr struct { - val any -} - -// TypeAttr creates a lazily evaluated log value that presents the pretty type name of a value -// as a string. It is roughly equivalent to the '%T' format option, and should only perform -// reflection in the event that logs are actually being generated. -func TypeAttr(val any) slog.LogValuer { - return typeAttr{val} -} - -func (a typeAttr) LogValue() slog.Value { - if t := reflect.TypeOf(a.val); t != nil { - return slog.StringValue(t.String()) - } - return slog.StringValue("nil") -} diff --git a/lib/utils/log/slog_handler_test.go b/lib/utils/log/slog_handler_test.go index 20876b6c4df1c..a75d57fc66994 100644 --- a/lib/utils/log/slog_handler_test.go +++ b/lib/utils/log/slog_handler_test.go @@ -22,13 +22,11 @@ import ( "bytes" "context" "encoding/json" - "fmt" "log/slog" "regexp" "strings" "testing" "testing/slogtest" - "time" "github.com/jonboulle/clockwork" "github.com/stretchr/testify/assert" @@ -41,16 +39,17 @@ import ( func TestSlogTextHandler(t *testing.T) { t.Parallel() clock := clockwork.NewFakeClock() - now := clock.Now().UTC().Format(time.RFC3339) + now := clock.Now().UTC() // Create a handler that doesn't report the caller and automatically sets // the time to whatever time the fake clock has in UTC time. Since the timestamp // is not important for this test overriding, it allows the regex to be simpler. var buf bytes.Buffer h := NewSlogTextHandler(&buf, SlogTextHandlerConfig{ + ConfiguredFields: []string{LevelField, ComponentField, TimestampField}, ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { if a.Key == slog.TimeKey { - a.Value = slog.StringValue(now) + a.Value = slog.TimeValue(now) } return a }, @@ -62,8 +61,7 @@ func TestSlogTextHandler(t *testing.T) { // Group 2: verbosity level of output // Group 3: message contents // Group 4: additional attributes - regex := fmt.Sprintf("^(?:(%s)?)\\s?([A-Z]{4})\\s+(\\w+)(?:\\s(.*))?$", now) - lineRegex := regexp.MustCompile(regex) + lineRegex := regexp.MustCompile(`^(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z)?\s?([A-Z]{4})\s+(\w+)(?:\s(.*))?$`) results := func() []map[string]any { var ms []map[string]any @@ -75,7 +73,7 @@ func TestSlogTextHandler(t *testing.T) { var m map[string]any matches := lineRegex.FindSubmatch(line) if len(matches) == 0 { - assert.Failf(t, "log output did not match regular expression", "regex: %s output: %s", regex, string(line)) + assert.Failf(t, "log output did not match regular expression", "regex: %s output: %s", lineRegex.String(), string(line)) ms = append(ms, m) continue } diff --git a/lib/utils/log/slog_json_handler.go b/lib/utils/log/slog_json_handler.go new file mode 100644 index 0000000000000..f5c3ec4062b09 --- /dev/null +++ b/lib/utils/log/slog_json_handler.go @@ -0,0 +1,167 @@ +// Teleport +// Copyright (C) 2024 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 ( + "context" + "fmt" + "io" + "log/slog" + "slices" + "strings" + "time" + + "github.com/gravitational/teleport" +) + +// SlogJSONHandlerConfig allows the SlogJSONHandler functionality +// to be tweaked. +type SlogJSONHandlerConfig struct { + // Level is the minimum record level that will be logged. + Level slog.Leveler + // ConfiguredFields are fields explicitly set by users to be included in + // the output message. If there are any entries configured, they will be honored. + // If empty, the default fields will be populated and included in the output. + ConfiguredFields []string + // ReplaceAttr is called to rewrite each non-group attribute before + // it is logged. + ReplaceAttr func(groups []string, a slog.Attr) slog.Attr +} + +// SlogJSONHandler is a [slog.Handler] that outputs messages in a json +// format per the config file. +type SlogJSONHandler struct { + *slog.JSONHandler +} + +// NewSlogJSONHandler creates a SlogJSONHandler that outputs to w. +func NewSlogJSONHandler(w io.Writer, cfg SlogJSONHandlerConfig) *SlogJSONHandler { + withCaller := len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, CallerField) + withComponent := len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, ComponentField) + withTimestamp := len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, TimestampField) + + return &SlogJSONHandler{ + JSONHandler: slog.NewJSONHandler(w, &slog.HandlerOptions{ + AddSource: true, + Level: cfg.Level, + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + switch a.Key { + case teleport.ComponentKey: + if !withComponent { + return slog.Attr{} + } + if a.Value.Kind() != slog.KindString { + return a + } + + a.Key = ComponentField + case slog.LevelKey: + // The slog.JSONHandler will inject "level" Attr. + // However, this lib's consumer might add an Attr using the same key ("level") and we end up with two records named "level". + // We must check its type before assuming this was injected by the slog.JSONHandler. + lvl, ok := a.Value.Any().(slog.Level) + if !ok { + return a + } + + var level string + switch lvl { + case TraceLevel: + level = "trace" + case slog.LevelDebug: + level = "debug" + case slog.LevelInfo: + level = "info" + case slog.LevelWarn: + level = "warning" + case slog.LevelError: + level = "error" + case slog.LevelError + 1: + level = "fatal" + default: + level = strings.ToLower(lvl.String()) + } + + a.Value = slog.StringValue(level) + case slog.TimeKey: + if !withTimestamp { + return slog.Attr{} + } + + // The slog.JSONHandler will inject "time" Attr. + // However, this lib's consumer might add an Attr using the same key ("time") and we end up with two records named "time". + // We must check its type before assuming this was injected by the slog.JSONHandler. + if a.Value.Kind() != slog.KindTime { + return a + } + + t := a.Value.Time() + if t.IsZero() { + return a + } + + a.Key = TimestampField + a.Value = slog.StringValue(t.Format(time.RFC3339)) + case slog.MessageKey: + // The slog.JSONHandler will inject "msg" Attr. + // However, this lib's consumer might add an Attr using the same key ("msg") and we end up with two records named "msg". + // We must check its type before assuming this was injected by the slog.JSONHandler. + if a.Value.Kind() != slog.KindString { + return a + } + a.Key = messageField + case slog.SourceKey: + if !withCaller { + return slog.Attr{} + } + + // The slog.JSONHandler will inject "source" Attr when AddSource is true. + // However, this lib's consumer might add an Attr using the same key ("source") and we end up with two records named "source". + // We must check its type before assuming this was injected by the slog.JSONHandler. + s, ok := a.Value.Any().(*slog.Source) + if !ok { + return a + } + + file, line := getCaller(s) + a = slog.String(CallerField, fmt.Sprintf("%s:%d", file, line)) + } + + // Convert [slog.KindAny] values that are backed by an [error] or [fmt.Stringer] + // to strings so that only the message is output instead of a json object. The kind is + // first checked to avoid allocating an interface for the values stored inline + // in [slog.Attr]. + if a.Value.Kind() == slog.KindAny { + if err, ok := a.Value.Any().(error); ok { + a.Value = slog.StringValue(err.Error()) + } + + if stringer, ok := a.Value.Any().(fmt.Stringer); ok { + a.Value = slog.StringValue(stringer.String()) + } + } + + return a + }, + }), + } +} + +func (j *SlogJSONHandler) Handle(ctx context.Context, r slog.Record) error { + addTracingContextToRecord(ctx, &r) + return j.JSONHandler.Handle(ctx, r) +} diff --git a/lib/utils/log/slog_text_handler.go b/lib/utils/log/slog_text_handler.go new file mode 100644 index 0000000000000..b3bc4900ac64c --- /dev/null +++ b/lib/utils/log/slog_text_handler.go @@ -0,0 +1,359 @@ +// Teleport +// Copyright (C) 2024 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 ( + "context" + "fmt" + "io" + "log/slog" + "runtime" + "slices" + "strings" + "sync" + + "github.com/gravitational/trace" + "github.com/sirupsen/logrus" + + "github.com/gravitational/teleport" +) + +// SlogTextHandler is a [slog.Handler] that outputs messages in a textual +// manner as configured by the Teleport configuration. +type SlogTextHandler struct { + cfg SlogTextHandlerConfig + // withCaller indicates whether the location the log was emitted from + // should be included in the output message. + withCaller bool + // withTimestamp indicates whether the times that the log was emitted at + // should be included in the output message. + withTimestamp bool + // component is the Teleport subcomponent that emitted the log. + component string + // preformatted data from previous calls to WithGroup and WithAttrs. + preformatted []byte + // groupPrefix is for the text handler only. + // It holds the prefix for groups that were already pre-formatted. + // A group will appear here when a call to WithGroup is followed by + // a call to WithAttrs. + groupPrefix string + // groups passed in via WithGroup and WithAttrs. + groups []string + // nOpenGroups the number of groups opened in preformatted. + nOpenGroups int + + // mu protects out - it needs to be a pointer so that all cloned + // SlogTextHandler returned from WithAttrs and WithGroup share the + // same mutex. Otherwise, output may be garbled since each clone + // will use its own copy of the mutex to protect out. See + // https://github.com/golang/go/issues/61321 for more details. + mu *sync.Mutex + out io.Writer +} + +// SlogTextHandlerConfig allow the SlogTextHandler functionality +// to be tweaked. +type SlogTextHandlerConfig struct { + // Level is the minimum record level that will be logged. + Level slog.Leveler + // EnableColors allows the level to be printed in color. + EnableColors bool + // Padding to use for various components. + Padding int + // ConfiguredFields are fields explicitly set by users to be included in + // the output message. If there are any entries configured, they will be honored. + // If empty, the default fields will be populated and included in the output. + ConfiguredFields []string + // ReplaceAttr is called to rewrite each non-group attribute before + // it is logged. + ReplaceAttr func(groups []string, a slog.Attr) slog.Attr +} + +// NewSlogTextHandler creates a SlogTextHandler that writes messages to w. +func NewSlogTextHandler(w io.Writer, cfg SlogTextHandlerConfig) *SlogTextHandler { + if cfg.Padding == 0 { + cfg.Padding = defaultComponentPadding + } + + handler := SlogTextHandler{ + cfg: cfg, + withCaller: len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, CallerField), + withTimestamp: len(cfg.ConfiguredFields) == 0 || slices.Contains(cfg.ConfiguredFields, TimestampField), + out: w, + mu: &sync.Mutex{}, + } + + if handler.cfg.ConfiguredFields == nil { + handler.cfg.ConfiguredFields = defaultFormatFields + } + + return &handler +} + +// Enabled returns whether the provided level will be included in output. +func (s *SlogTextHandler) Enabled(ctx context.Context, level slog.Level) bool { + minLevel := slog.LevelInfo + if s.cfg.Level != nil { + minLevel = s.cfg.Level.Level() + } + return level >= minLevel +} + +func (s *SlogTextHandler) newHandleState(buf *buffer, freeBuf bool) handleState { + state := handleState{ + h: s, + buf: buf, + freeBuf: freeBuf, + prefix: newBuffer(), + } + if s.cfg.ReplaceAttr != nil { + state.groups = groupPool.Get().(*[]string) + *state.groups = append(*state.groups, s.groups[:s.nOpenGroups]...) + } + return state +} + +// Handle formats the provided record and writes the output to the +// destination. +func (s *SlogTextHandler) Handle(ctx context.Context, r slog.Record) error { + state := s.newHandleState(newBuffer(), true) + defer state.free() + + addTracingContextToRecord(ctx, &r) + + // Built-in attributes. They are not in a group. + stateGroups := state.groups + state.groups = nil // So ReplaceAttrs sees no groups instead of the pre groups. + rep := s.cfg.ReplaceAttr + + if s.withTimestamp && !r.Time.IsZero() { + if rep == nil { + state.appendKey(slog.TimeKey) + state.appendTime(r.Time.Round(0)) + } else { + state.appendAttr(slog.Time(slog.TimeKey, r.Time.Round(0))) + } + } + + // 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 + // 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) + } + + if rep == nil { + state.appendKey(slog.LevelKey) + // Write the level directly to stat to avoid quoting + // color formatting that exists. + state.buf.WriteString(level) + } else { + state.appendAttr(slog.String(slog.LevelKey, level)) + } + case ComponentField: + // If a component is provided with the attributes, it should be used instead of + // the component set on the handler. Note that if there are multiple components + // specified in the arguments, the one with the lowest index is used and the others are ignored. + // In the example below, the resulting component in the message output would be "alpaca". + // + // logger := logger.With(teleport.ComponentKey, "fish") + // logger.InfoContext(ctx, "llama llama llama", teleport.ComponentKey, "alpaca", "foo", 123, teleport.ComponentKey, "shark") + component := s.component + r.Attrs(func(attr slog.Attr) bool { + 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] + "]" + } + + return false + }) + + if rep == nil { + state.appendKey(teleport.ComponentKey) + state.appendString(component) + } else { + state.appendAttr(slog.String(teleport.ComponentKey, component)) + } + default: + if _, ok := knownFormatFields[field]; !ok { + return trace.BadParameter("invalid log format key: %v", field) + } + } + } + + if rep == nil { + state.appendKey(slog.MessageKey) + state.appendString(r.Message) + } else { + state.appendAttr(slog.String(slog.MessageKey, r.Message)) + } + + state.groups = stateGroups // Restore groups passed to ReplaceAttrs. + state.appendNonBuiltIns(r) + + if r.PC != 0 && s.withCaller { + fs := runtime.CallersFrames([]uintptr{r.PC}) + f, _ := fs.Next() + + src := slog.Source{ + Function: f.Function, + File: f.File, + Line: f.Line, + } + src.File, src.Line = getCaller(&src) + + if rep == nil { + state.appendKey(slog.SourceKey) + state.appendString(fmt.Sprintf("%s:%d", src.File, src.Line)) + } else { + state.appendAttr(slog.Any(slog.SourceKey, &src)) + } + + } + + state.buf.WriteByte('\n') + + s.mu.Lock() + defer s.mu.Unlock() + _, err := s.out.Write(*state.buf) + return err +} + +func (s *SlogTextHandler) clone() *SlogTextHandler { + // We can't use assignment because we can't copy the mutex. + return &SlogTextHandler{ + cfg: s.cfg, + withCaller: s.withCaller, + withTimestamp: s.withTimestamp, + component: s.component, + preformatted: slices.Clip(s.preformatted), + groupPrefix: s.groupPrefix, + groups: slices.Clip(s.groups), + nOpenGroups: s.nOpenGroups, + out: s.out, + mu: s.mu, // mutex shared among all clones of this handler + } +} + +// WithAttrs clones the current handler with the provided attributes +// added to any existing attributes. The values are preformatted here +// so that they do not need to be formatted per call to Handle. +func (s *SlogTextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return s + } + + s2 := s.clone() + // Pre-format the attributes as an optimization. + state := s2.newHandleState((*buffer)(&s2.preformatted), false) + defer state.free() + state.prefix.WriteString(s.groupPrefix) + + // Remember the position in the buffer, in case all attrs are empty. + pos := state.buf.Len() + state.openGroups() + + nonEmpty := false + for _, a := range attrs { + switch a.Key { + case teleport.ComponentKey: + component := fmt.Sprintf("[%v]", a.Value.String()) + component = strings.ToUpper(padMax(component, s.cfg.Padding)) + if component[len(component)-1] != ' ' { + component = component[:len(component)-1] + "]" + } + s2.component = component + case teleport.ComponentFields: + switch fields := a.Value.Any().(type) { + case map[string]any: + for k, v := range fields { + if state.appendAttr(slog.Any(k, v)) { + nonEmpty = true + } + } + case logrus.Fields: + for k, v := range fields { + if state.appendAttr(slog.Any(k, v)) { + nonEmpty = true + } + } + } + default: + if state.appendAttr(a) { + nonEmpty = true + } + } + } + + if !nonEmpty { + state.buf.SetLen(pos) + } else { + // Remember the new prefix for later keys. + s2.groupPrefix = state.prefix.String() + // Remember how many opened groups are in preformattedAttrs, + // so we don't open them again when we handle a Record. + s2.nOpenGroups = len(s2.groups) + } + + return s2 +} + +// WithGroup opens a new group. +func (s *SlogTextHandler) WithGroup(name string) slog.Handler { + s2 := s.clone() + s2.groups = append(s2.groups, name) + return s2 +}