Files
teleport/lib/utils/log/slog_json_handler.go
T
rosstimothy 6061a8887b Fix: prevent race in slog text handler group handling (#50451)
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

```
2024-12-20 17:31:06 +00:00

168 lines
5.4 KiB
Go

// 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 <http://www.gnu.org/licenses/>.
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)
}