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 14363bca8584e..0000000000000 --- a/lib/utils/log/slog_handler.go +++ /dev/null @@ -1,692 +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" - -// 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 } - -// 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 +}