Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix: prevent race in slog text handler group handling #50451

Merged
merged 1 commit into from
Dec 20, 2024

Conversation

rosstimothy
Copy link
Contributor

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The contents of this file are not new, they were moved from slog_handler.go which was deleted.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The contents of this file are not new, they were moved from slog_handler.go which was deleted.

Copy link

This pull request is automatically being deployed by Amplify Hosting (learn more).

Access this pull request here: https://pr-50451.d3pp5qlev8mo18.amplifyapp.com

@rosstimothy rosstimothy force-pushed the tross/slog_text_handler_groups branch 6 times, most recently from 91de9a4 to 74d744d Compare December 19, 2024 21:33
@rosstimothy rosstimothy marked this pull request as ready for review December 19, 2024 21:54
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

```
@rosstimothy rosstimothy force-pushed the tross/slog_text_handler_groups branch from 74d744d to fffd058 Compare December 19, 2024 21:57
@rosstimothy rosstimothy added no-changelog Indicates that a PR does not require a changelog entry backport/branch/v15 backport/branch/v16 backport/branch/v17 labels Dec 19, 2024
@strideynet strideynet self-requested a review December 20, 2024 15:26
Copy link
Contributor

@strideynet strideynet left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice. I prefer the way this has been organised as well. Thanks Tim!

Copy link
Contributor

@marcoandredinis marcoandredinis left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm just a bit sad that we need to write so much code to have proper logging

@public-teleport-github-review-bot public-teleport-github-review-bot bot removed the request for review from zmb3 December 20, 2024 17:27
@rosstimothy rosstimothy added this pull request to the merge queue Dec 20, 2024
Merged via the queue into master with commit 6061a88 Dec 20, 2024
42 of 44 checks passed
@rosstimothy rosstimothy deleted the tross/slog_text_handler_groups branch December 20, 2024 17:50
@public-teleport-github-review-bot

@rosstimothy See the table below for backport results.

Branch Result
branch/v15 Failed
branch/v16 Failed
branch/v17 Failed

rosstimothy added a commit that referenced this pull request Dec 20, 2024
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

```
rosstimothy added a commit that referenced this pull request Dec 20, 2024
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

```
rosstimothy added a commit that referenced this pull request Dec 20, 2024
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

```
rosstimothy added a commit that referenced this pull request Dec 20, 2024
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

```
github-merge-queue bot pushed a commit that referenced this pull request Dec 26, 2024
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

```
github-merge-queue bot pushed a commit that referenced this pull request Dec 26, 2024
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

```
github-merge-queue bot pushed a commit that referenced this pull request Dec 26, 2024
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

```
@GavinFrazar
Copy link
Contributor

@rosstimothy this change broke debug level text format error logging, for example:

before

2025-01-03T11:19:35-08:00 DEBU [PROXY:AGE] Failed to connect agent target_cluster:gavin-leaf.cloud.gravitational.io local_cluster: error:[
ERROR REPORT:
Original Error: *fmt.wrapError ssh: handshake failed: proxy already claimed
Stack Trace:
        github.com/gravitational/teleport/api/observability/tracing/ssh/ssh.go:158 github.com/gravitational/teleport/api/observability/tracing/ssh.NewClientConn
        github.com/gravitational/teleport/lib/reversetunnel/agent_dialer.go:97 github.com/gravitational/teleport/lib/reversetunnel.(*agentDialer).DialContext
        github.com/gravitational/teleport/lib/reversetunnel/agent.go:369 github.com/gravitational/teleport/lib/reversetunnel.(*agent).connect
        github.com/gravitational/teleport/lib/reversetunnel/agent.go:324 github.com/gravitational/teleport/lib/reversetunnel.(*agent).Start
        github.com/gravitational/teleport/lib/reversetunnel/agentpool.go:322 github.com/gravitational/teleport/lib/reversetunnel.(*AgentPool).connectAgent
        github.com/gravitational/teleport/lib/reversetunnel/agentpool.go:271 github.com/gravitational/teleport/lib/reversetunnel.(*AgentPool).run
        github.com/gravitational/teleport/lib/reversetunnel/agentpool.go:258 github.com/gravitational/teleport/lib/reversetunnel.(*AgentPool).Start.func1
        runtime/asm_arm64.s:1223 runtime.goexit
User Message: ssh: handshake failed: proxy already claimed] reversetunnel/agentpool.go:278

after

2025-01-03T11:09:36.784-08:00 DEBU [PROXY:AGE] Failed to connect agent target_cluster:gavin-leaf.cloud.gravitational.io local_cluster: error:"[\nERROR REPORT:\nOriginal Error: *fmt.wrapError s
sh: handshake failed: proxy already claimed\nStack Trace:\n\tgithub.com/gravitational/teleport/api/observability/tracing/ssh/ssh.go:158 github.com/gravitational/teleport/api/observability/trac
ing/ssh.NewClientConn\n\tgithub.com/gravitational/teleport/lib/reversetunnel/agent_dialer.go:97 github.com/gravitational/teleport/lib/reversetunnel.(*agentDialer).DialContext\n\tgithub.com/gra
vitational/teleport/lib/reversetunnel/agent.go:369 github.com/gravitational/teleport/lib/reversetunnel.(*agent).connect\n\tgithub.com/gravitational/teleport/lib/reversetunnel/agent.go:324 gith
ub.com/gravitational/teleport/lib/reversetunnel.(*agent).Start\n\tgithub.com/gravitational/teleport/lib/reversetunnel/agentpool.go:322 github.com/gravitational/teleport/lib/reversetunnel.(*Age
ntPool).connectAgent\n\tgithub.com/gravitational/teleport/lib/reversetunnel/agentpool.go:271 github.com/gravitational/teleport/lib/reversetunnel.(*AgentPool).run\n\tgithub.com/gravitational/te
leport/lib/reversetunnel/agentpool.go:258 github.com/gravitational/teleport/lib/reversetunnel.(*AgentPool).Start.func1\n\truntime/asm_arm64.s:1223 runtime.goexit\nUser Message: ssh: handshake 
failed: proxy already claimed]" reversetunnel/agentpool.go:278

rosstimothy added a commit that referenced this pull request Jan 6, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-merge-queue bot pushed a commit that referenced this pull request Jan 7, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-actions bot pushed a commit that referenced this pull request Jan 7, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-actions bot pushed a commit that referenced this pull request Jan 7, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-actions bot pushed a commit that referenced this pull request Jan 7, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-merge-queue bot pushed a commit that referenced this pull request Jan 8, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-merge-queue bot pushed a commit that referenced this pull request Jan 8, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
github-merge-queue bot pushed a commit that referenced this pull request Jan 8, 2025
The refactoring done in #50451 caused the trace.Error debug report
to be quoted in log output. This updates the quoting bypass used
for log level to also consider trace.Errors in order to restore
the previous output.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Race in slog text handler
4 participants