Skip to content

Commit

Permalink
Fix: prevent race in slog text handler group handling (#50451) (#50502)
Browse files Browse the repository at this point in the history
Closes #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

```
  • Loading branch information
rosstimothy authored Dec 26, 2024
1 parent d9a6cd5 commit b3bb909
Show file tree
Hide file tree
Showing 9 changed files with 1,034 additions and 724 deletions.
37 changes: 8 additions & 29 deletions lib/utils/log/buffer.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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)
}
17 changes: 11 additions & 6 deletions lib/utils/log/formatter_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
},
Expand Down Expand Up @@ -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])
Expand Down Expand Up @@ -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()
Expand Down
Loading

0 comments on commit b3bb909

Please sign in to comment.