Skip to content

Commit

Permalink
Fix: prevent race in slog text handler group handling
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 committed Dec 19, 2024
1 parent 3e3daec commit c6ed156
Show file tree
Hide file tree
Showing 8 changed files with 991 additions and 726 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)
}
13 changes: 9 additions & 4 deletions lib/utils/log/formatter_test.go
Original file line number Diff line number Diff line change
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 @@ -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",
"component", i,
slog.Group("group",
slog.String("test", "123"),
slog.String("animal", "llama"),
),
)
}(i)
}
wg.Wait()
Expand Down
Loading

0 comments on commit c6ed156

Please sign in to comment.