From aaaaf85286e56c58f0cb4badec25ef2d9b8347d8 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 15:01:17 -0400 Subject: [PATCH 01/20] feat(logging): add rate_limiting config options (slog-sampling variant) Co-Authored-By: Claude Opus 4.8 --- internal/runtime/logging/options.go | 54 ++++++++++++++++++++++-- internal/runtime/logging/options_test.go | 29 +++++++++++++ 2 files changed, 79 insertions(+), 4 deletions(-) diff --git a/internal/runtime/logging/options.go b/internal/runtime/logging/options.go index 1b2102734cc..3cda1938cfc 100644 --- a/internal/runtime/logging/options.go +++ b/internal/runtime/logging/options.go @@ -5,6 +5,7 @@ import ( "fmt" "log/slog" "math" + "time" "github.com/grafana/alloy/internal/component/common/loki" "github.com/grafana/alloy/syntax" @@ -16,7 +17,8 @@ type Options struct { Format Format `alloy:"format,attr,optional"` Destination LogDestination `alloy:"destination,attr,optional"` - WriteTo []loki.LogsReceiver `alloy:"write_to,attr,optional"` + WriteTo []loki.LogsReceiver `alloy:"write_to,attr,optional"` + RateLimiting *RateLimitingOptions `alloy:"rate_limiting,block,optional"` } // LogDestination is where to send the primary log output. @@ -49,13 +51,20 @@ func defaultDestination() LogDestination { return LogDestinationStderr } +// defaultRateLimitingOptions returns the default rate limiting configuration. +func defaultRateLimitingOptions() RateLimitingOptions { + return RateLimitingOptions{Enabled: true, Tick: time.Second, Threshold: 10, Rate: 0, MaxSignatures: 1000} +} + // defaultOptions builds a fresh set of Logger defaults, evaluating the // platform-appropriate destination at call time. func defaultOptions() Options { + rl := defaultRateLimitingOptions() return Options{ - Level: LevelDefault, - Format: FormatDefault, - Destination: defaultDestination(), + Level: LevelDefault, + Format: FormatDefault, + Destination: defaultDestination(), + RateLimiting: &rl, } } @@ -158,3 +167,40 @@ func (ll *Format) UnmarshalText(text []byte) error { } return nil } + +// RateLimitingOptions configures per-(component, message) log rate limiting, +// backed by github.com/samber/slog-sampling. Enabled by default. +type RateLimitingOptions struct { + Enabled bool `alloy:"enabled,attr,optional"` + Tick time.Duration `alloy:"tick,attr,optional"` + Threshold uint64 `alloy:"threshold,attr,optional"` + Rate float64 `alloy:"rate,attr,optional"` + MaxSignatures int `alloy:"max_signatures,attr,optional"` +} + +var _ syntax.Defaulter = (*RateLimitingOptions)(nil) + +// SetToDefault implements syntax.Defaulter. +func (o *RateLimitingOptions) SetToDefault() { + *o = defaultRateLimitingOptions() +} + +var _ syntax.Validator = (*RateLimitingOptions)(nil) + +// Validate implements syntax.Validator. +func (o RateLimitingOptions) Validate() error { + if !o.Enabled { + return nil + } + switch { + case o.Tick <= 0: + return fmt.Errorf("logging rate_limiting.tick must be > 0, got %v", o.Tick) + case o.Threshold == 0: + return fmt.Errorf("logging rate_limiting.threshold must be > 0") + case o.Rate < 0 || o.Rate > 1: + return fmt.Errorf("logging rate_limiting.rate must be in [0,1], got %v", o.Rate) + case o.MaxSignatures <= 0: + return fmt.Errorf("logging rate_limiting.max_signatures must be > 0, got %d", o.MaxSignatures) + } + return nil +} diff --git a/internal/runtime/logging/options_test.go b/internal/runtime/logging/options_test.go index 3d1482a5dd6..acd73111cfb 100644 --- a/internal/runtime/logging/options_test.go +++ b/internal/runtime/logging/options_test.go @@ -2,6 +2,7 @@ package logging import ( "testing" + "time" "github.com/grafana/alloy/syntax" "github.com/stretchr/testify/require" @@ -88,3 +89,31 @@ func TestOptions_EndToEnd(t *testing.T) { }) } } + +func TestOptionsDefaultEnablesRateLimiting(t *testing.T) { + var o Options + o.SetToDefault() + require.NotNil(t, o.RateLimiting) + require.True(t, o.RateLimiting.Enabled) + require.Equal(t, time.Second, o.RateLimiting.Tick) + require.Equal(t, uint64(10), o.RateLimiting.Threshold) + require.Equal(t, 0.0, o.RateLimiting.Rate) + require.Equal(t, 1000, o.RateLimiting.MaxSignatures) +} + +func TestRateLimitingValidate(t *testing.T) { + valid := RateLimitingOptions{Enabled: true, Tick: time.Second, Threshold: 10, Rate: 0, MaxSignatures: 1000} + require.NoError(t, valid.Validate()) + require.NoError(t, RateLimitingOptions{Enabled: false}.Validate()) + for _, m := range []func(*RateLimitingOptions){ + func(o *RateLimitingOptions) { o.Tick = 0 }, + func(o *RateLimitingOptions) { o.Threshold = 0 }, + func(o *RateLimitingOptions) { o.Rate = -0.1 }, + func(o *RateLimitingOptions) { o.Rate = 1.1 }, + func(o *RateLimitingOptions) { o.MaxSignatures = 0 }, + } { + bad := valid + m(&bad) + require.Error(t, bad.Validate()) + } +} From 0223df07485a2508b97c434551e46d5b26cf0d27 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 15:10:02 -0400 Subject: [PATCH 02/20] feat(logging): slog-sampling dependency, matcher, metric, buildRoot --- collector/go.mod | 5 + collector/go.sum | 10 ++ go.mod | 5 + go.sum | 10 ++ internal/runtime/logging/sampling.go | 142 ++++++++++++++++++++++ internal/runtime/logging/sampling_test.go | 88 ++++++++++++++ 6 files changed, 260 insertions(+) create mode 100644 internal/runtime/logging/sampling.go create mode 100644 internal/runtime/logging/sampling_test.go diff --git a/collector/go.mod b/collector/go.mod index 216a5e1cc4a..2370c6eb2ff 100644 --- a/collector/go.mod +++ b/collector/go.mod @@ -352,6 +352,7 @@ require ( github.com/beorn7/perks v1.0.1 // indirect github.com/bitfield/gotestdox v0.2.2 // indirect github.com/blang/semver/v4 v4.0.0 // indirect + github.com/bluele/gcache v0.0.2 // indirect github.com/bmatcuk/doublestar/v4 v4.10.0 // indirect github.com/bodgit/plumbing v1.3.0 // indirect github.com/bodgit/sevenzip v1.6.1 // indirect @@ -386,6 +387,7 @@ require ( github.com/coreos/go-oidc/v3 v3.18.0 // indirect github.com/coreos/go-semver v0.3.1 // indirect github.com/coreos/go-systemd/v22 v22.7.0 // indirect + github.com/cornelk/hashmap v1.0.8 // indirect github.com/cyphar/filepath-securejoin v0.6.1 // indirect github.com/danieljoos/wincred v1.2.3 // indirect github.com/databricks/databricks-sql-go v1.11.0 // indirect @@ -845,6 +847,9 @@ require ( github.com/safchain/ethtool v0.7.0 // indirect github.com/sagikazarmark/locafero v0.11.0 // indirect github.com/samber/lo v1.53.0 // indirect + github.com/samber/slog-common v0.21.0 // indirect + github.com/samber/slog-multi v1.8.0 // indirect + github.com/samber/slog-sampling v1.6.0 // indirect github.com/samuel/go-zookeeper v0.0.0-20190923202752-2cc03de413da // indirect github.com/scaleway/scaleway-sdk-go v1.0.0-beta.36 // indirect github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529 // indirect diff --git a/collector/go.sum b/collector/go.sum index 8b112610a52..9c81c112578 100644 --- a/collector/go.sum +++ b/collector/go.sum @@ -633,6 +633,8 @@ github.com/bitfield/gotestdox v0.2.2 h1:x6RcPAbBbErKLnapz1QeAlf3ospg8efBsedU93CD github.com/bitfield/gotestdox v0.2.2/go.mod h1:D+gwtS0urjBrzguAkTM2wodsTQYFHdpx8eqRJ3N+9pY= github.com/blang/semver/v4 v4.0.0 h1:1PFHFE6yCCTv8C1TeyNNarDzntLi7wMI5i/pzqYIsAM= github.com/blang/semver/v4 v4.0.0/go.mod h1:IbckMUScFkM3pff0VJDNKRiT6TG/YpiHIM2yvyW5YoQ= +github.com/bluele/gcache v0.0.2 h1:WcbfdXICg7G/DGBh1PFfcirkWOQV+v077yF1pSy3DGw= +github.com/bluele/gcache v0.0.2/go.mod h1:m15KV+ECjptwSPxKhOhQoAFQVtUFjTVkc3H8o0t/fp0= github.com/bmatcuk/doublestar v1.1.1/go.mod h1:UD6OnuiIn0yFxxA2le/rnRU1G4RaI4UvFv1sNto9p6w= github.com/bmatcuk/doublestar/v4 v4.10.0 h1:zU9WiOla1YA122oLM6i4EXvGW62DvKZVxIe6TYWexEs= github.com/bmatcuk/doublestar/v4 v4.10.0/go.mod h1:xBQ8jztBU6kakFMg+8WGxn0c6z1fTSPVIjEY1Wr7jzc= @@ -737,6 +739,8 @@ github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e/go.mod h1:F5haX7 github.com/coreos/go-systemd/v22 v22.7.0 h1:LAEzFkke61DFROc7zNLX/WA2i5J8gYqe0rSj9KI28KA= github.com/coreos/go-systemd/v22 v22.7.0/go.mod h1:xNUYtjHu2EDXbsxz1i41wouACIwT7Ybq9o0BQhMwD0w= github.com/coreos/pkg v0.0.0-20180928190104-399ea9e2e55f/go.mod h1:E3G3o1h8I7cfcXa63jLwjI0eiQQMgzzUDFVpN/nH/eA= +github.com/cornelk/hashmap v1.0.8 h1:nv0AWgw02n+iDcawr5It4CjQIAcdMMKRrs10HOJYlrc= +github.com/cornelk/hashmap v1.0.8/go.mod h1:RfZb7JO3RviW/rT6emczVuC/oxpdz4UsSB2LJSclR1k= github.com/cpuguy83/dockercfg v0.3.2 h1:DlJTyZGBDlXqUZ2Dk2Q3xHs/FtnooJJVaad2S9GKorA= github.com/cpuguy83/dockercfg v0.3.2/go.mod h1:sugsbF4//dDlL/i+S+rtpIWp+5h0BHJHfjj5/jFyUJc= github.com/cpuguy83/go-md2man v1.0.10/go.mod h1:SmD6nW6nTyfqj6ABTjUi3V3JVMnlJmwcJI5acqYI6dE= @@ -2237,6 +2241,12 @@ github.com/sagikazarmark/locafero v0.11.0 h1:1iurJgmM9G3PA/I+wWYIOw/5SyBtxapeHDc github.com/sagikazarmark/locafero v0.11.0/go.mod h1:nVIGvgyzw595SUSUE6tvCp3YYTeHs15MvlmU87WwIik= github.com/samber/lo v1.53.0 h1:t975lj2py4kJPQ6haz1QMgtId2gtmfktACxIXArw3HM= github.com/samber/lo v1.53.0/go.mod h1:4+MXEGsJzbKGaUEQFKBq2xtfuznW9oz/WrgyzMzRoM0= +github.com/samber/slog-common v0.21.0 h1:Wo2hTly1Br5RjYqX/BTWJJeDnTE85oWk/7vqlpZuAUc= +github.com/samber/slog-common v0.21.0/go.mod h1:d/6OaSlzdkl9PFpfRLgn8FwY1OW6EFmPtBpsHX4MrU0= +github.com/samber/slog-multi v1.8.0 h1:E05c1wnQ+8M58oQDBABlJ4TEIJWssNgtckso3zlaLlI= +github.com/samber/slog-multi v1.8.0/go.mod h1:6+3j/ILxDvAcLD75YdQAm6iKWu6AmwlohLgQxL/2aiI= +github.com/samber/slog-sampling v1.6.0 h1:ODK16Wse1139eo25P+APfYKQqLYE79LMnnTBcUe+OCA= +github.com/samber/slog-sampling v1.6.0/go.mod h1:2vMB0an9YwqxtBdzmcBOpO5ZoL6LI74ghC3jC4sJuk4= github.com/samuel/go-zookeeper v0.0.0-20190923202752-2cc03de413da h1:p3Vo3i64TCLY7gIfzeQaUJ+kppEO5WQG3cL8iE8tGHU= github.com/samuel/go-zookeeper v0.0.0-20190923202752-2cc03de413da/go.mod h1:gi+0XIa01GRL2eRQVjQkKGqKF3SF9vZR/HnPullcV2E= github.com/santhosh-tekuri/jsonschema/v6 v6.0.2 h1:KRzFb2m7YtdldCEkzs6KqmJw4nqEVZGK7IN2kJkjTuQ= diff --git a/go.mod b/go.mod index e26ceba1372..c3de486de40 100644 --- a/go.mod +++ b/go.mod @@ -969,6 +969,7 @@ require ( github.com/open-telemetry/opentelemetry-collector-contrib/pkg/translator/splunk v0.153.0 github.com/open-telemetry/opentelemetry-collector-contrib/processor/redactionprocessor v0.153.0 github.com/open-telemetry/opentelemetry-collector-contrib/receiver/nginxreceiver v0.153.0 + github.com/samber/slog-sampling v1.6.0 github.com/spf13/viper v1.21.0 github.com/vektah/gqlparser/v2 v2.5.36 github.com/zricethezav/gitleaks/v8 v8.30.1 @@ -1027,6 +1028,7 @@ require ( github.com/aws/aws-sdk-go-v2/service/rds v1.118.2 // indirect github.com/aws/aws-sdk-go-v2/service/signin v1.2.2 // indirect github.com/aymanbagabas/go-osc52/v2 v2.0.1 // indirect + github.com/bluele/gcache v0.0.2 // indirect github.com/bodgit/plumbing v1.3.0 // indirect github.com/bodgit/sevenzip v1.6.1 // indirect github.com/bodgit/windows v1.0.1 // indirect @@ -1045,6 +1047,7 @@ require ( github.com/coder/websocket v1.8.14 // indirect github.com/containerd/containerd/api v1.9.0 // indirect github.com/containerd/typeurl/v2 v2.2.3 // indirect + github.com/cornelk/hashmap v1.0.8 // indirect github.com/dsnet/compress v0.0.2-0.20230904184137-39efe44ab707 // indirect github.com/erikgeiser/coninput v0.0.0-20211004153227-1c3628e74d0f // indirect github.com/fatih/semgroup v1.2.0 // indirect @@ -1079,6 +1082,8 @@ require ( github.com/puzpuzpuz/xsync/v4 v4.5.0 // indirect github.com/rs/xid v1.6.0 // indirect github.com/sagikazarmark/locafero v0.11.0 // indirect + github.com/samber/slog-common v0.21.0 // indirect + github.com/samber/slog-multi v1.8.0 // indirect github.com/sijms/go-ora/v2 v2.9.0 // indirect github.com/sorairolake/lzip-go v0.3.8 // indirect github.com/sosodev/duration v1.4.0 // indirect diff --git a/go.sum b/go.sum index 814e33aef76..3a7aaede107 100644 --- a/go.sum +++ b/go.sum @@ -653,6 +653,8 @@ github.com/bitfield/gotestdox v0.2.2 h1:x6RcPAbBbErKLnapz1QeAlf3ospg8efBsedU93CD github.com/bitfield/gotestdox v0.2.2/go.mod h1:D+gwtS0urjBrzguAkTM2wodsTQYFHdpx8eqRJ3N+9pY= github.com/blang/semver/v4 v4.0.0 h1:1PFHFE6yCCTv8C1TeyNNarDzntLi7wMI5i/pzqYIsAM= github.com/blang/semver/v4 v4.0.0/go.mod h1:IbckMUScFkM3pff0VJDNKRiT6TG/YpiHIM2yvyW5YoQ= +github.com/bluele/gcache v0.0.2 h1:WcbfdXICg7G/DGBh1PFfcirkWOQV+v077yF1pSy3DGw= +github.com/bluele/gcache v0.0.2/go.mod h1:m15KV+ECjptwSPxKhOhQoAFQVtUFjTVkc3H8o0t/fp0= github.com/bmatcuk/doublestar v1.1.1/go.mod h1:UD6OnuiIn0yFxxA2le/rnRU1G4RaI4UvFv1sNto9p6w= github.com/bmatcuk/doublestar/v4 v4.10.0 h1:zU9WiOla1YA122oLM6i4EXvGW62DvKZVxIe6TYWexEs= github.com/bmatcuk/doublestar/v4 v4.10.0/go.mod h1:xBQ8jztBU6kakFMg+8WGxn0c6z1fTSPVIjEY1Wr7jzc= @@ -775,6 +777,8 @@ github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSV github.com/coreos/go-systemd/v22 v22.7.0 h1:LAEzFkke61DFROc7zNLX/WA2i5J8gYqe0rSj9KI28KA= github.com/coreos/go-systemd/v22 v22.7.0/go.mod h1:xNUYtjHu2EDXbsxz1i41wouACIwT7Ybq9o0BQhMwD0w= github.com/coreos/pkg v0.0.0-20180928190104-399ea9e2e55f/go.mod h1:E3G3o1h8I7cfcXa63jLwjI0eiQQMgzzUDFVpN/nH/eA= +github.com/cornelk/hashmap v1.0.8 h1:nv0AWgw02n+iDcawr5It4CjQIAcdMMKRrs10HOJYlrc= +github.com/cornelk/hashmap v1.0.8/go.mod h1:RfZb7JO3RviW/rT6emczVuC/oxpdz4UsSB2LJSclR1k= github.com/cpuguy83/dockercfg v0.3.2 h1:DlJTyZGBDlXqUZ2Dk2Q3xHs/FtnooJJVaad2S9GKorA= github.com/cpuguy83/dockercfg v0.3.2/go.mod h1:sugsbF4//dDlL/i+S+rtpIWp+5h0BHJHfjj5/jFyUJc= github.com/cpuguy83/go-md2man v1.0.10/go.mod h1:SmD6nW6nTyfqj6ABTjUi3V3JVMnlJmwcJI5acqYI6dE= @@ -2259,6 +2263,12 @@ github.com/sagikazarmark/locafero v0.11.0 h1:1iurJgmM9G3PA/I+wWYIOw/5SyBtxapeHDc github.com/sagikazarmark/locafero v0.11.0/go.mod h1:nVIGvgyzw595SUSUE6tvCp3YYTeHs15MvlmU87WwIik= github.com/samber/lo v1.53.0 h1:t975lj2py4kJPQ6haz1QMgtId2gtmfktACxIXArw3HM= github.com/samber/lo v1.53.0/go.mod h1:4+MXEGsJzbKGaUEQFKBq2xtfuznW9oz/WrgyzMzRoM0= +github.com/samber/slog-common v0.21.0 h1:Wo2hTly1Br5RjYqX/BTWJJeDnTE85oWk/7vqlpZuAUc= +github.com/samber/slog-common v0.21.0/go.mod h1:d/6OaSlzdkl9PFpfRLgn8FwY1OW6EFmPtBpsHX4MrU0= +github.com/samber/slog-multi v1.8.0 h1:E05c1wnQ+8M58oQDBABlJ4TEIJWssNgtckso3zlaLlI= +github.com/samber/slog-multi v1.8.0/go.mod h1:6+3j/ILxDvAcLD75YdQAm6iKWu6AmwlohLgQxL/2aiI= +github.com/samber/slog-sampling v1.6.0 h1:ODK16Wse1139eo25P+APfYKQqLYE79LMnnTBcUe+OCA= +github.com/samber/slog-sampling v1.6.0/go.mod h1:2vMB0an9YwqxtBdzmcBOpO5ZoL6LI74ghC3jC4sJuk4= github.com/samuel/go-zookeeper v0.0.0-20190923202752-2cc03de413da h1:p3Vo3i64TCLY7gIfzeQaUJ+kppEO5WQG3cL8iE8tGHU= github.com/samuel/go-zookeeper v0.0.0-20190923202752-2cc03de413da/go.mod h1:gi+0XIa01GRL2eRQVjQkKGqKF3SF9vZR/HnPullcV2E= github.com/satori/go.uuid v1.2.0/go.mod h1:dA0hQrYB0VpLJoorglMZABFdXlWrHn1NEOzdhQKdks0= diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go new file mode 100644 index 00000000000..92cd8097667 --- /dev/null +++ b/internal/runtime/logging/sampling.go @@ -0,0 +1,142 @@ +package logging + +import ( + "context" + "log/slog" + + "github.com/prometheus/client_golang/prometheus" + slogsampling "github.com/samber/slog-sampling" + "github.com/samber/slog-sampling/buffer" +) + +type componentInfo struct{ id, path string } + +// sniffComponent inspects the attrs of a log record for component/controller +// identifying attributes and merges them onto base, returning the result. +// component_id wins over controller_id; component_path is captured verbatim. +func sniffComponent(base componentInfo, attrs []slog.Attr) componentInfo { + c := base + for _, a := range attrs { + switch a.Key { + case "component_id": + c.id = a.Value.String() + case "controller_id": + if c.id == "" { + c.id = a.Value.String() + } + case "component_path": + c.path = a.Value.String() + } + } + return c +} + +type ctxKey struct{} + +// withComponent stores componentInfo on ctx so that a downstream Matcher can +// read it back without threading it through every log call site. +func withComponent(ctx context.Context, c componentInfo) context.Context { + return context.WithValue(ctx, ctxKey{}, c) +} + +// componentFromCtx returns the componentInfo previously stored by +// withComponent, or the zero value if none was stored. +func componentFromCtx(ctx context.Context) componentInfo { + c, _ := ctx.Value(ctxKey{}).(componentInfo) + return c +} + +// compMatcher is the slog-sampling Matcher used to key the rate limiter's +// per-signature counters. Two records are considered the same "signature" +// (and thus share a rate-limit budget) when they share the same component +// path, level, and message. +func compMatcher(ctx context.Context, r *slog.Record) string { + c := componentFromCtx(ctx) + return c.path + "\x00" + r.Level.String() + "\x00" + r.Message +} + +// levelString maps a slog.Level to the lowercase level label used on the +// suppressed-lines metric. +func levelString(l slog.Level) string { + switch { + case l < slog.LevelInfo: + return "debug" + case l < slog.LevelWarn: + return "info" + case l < slog.LevelError: + return "warn" + default: + return "error" + } +} + +// rateLimitMetrics tracks how many log lines the rate limiter has dropped, +// broken down by level and component. A nil *rateLimitMetrics is valid and +// its methods are no-ops, so callers need not special-case a missing +// registerer. +type rateLimitMetrics struct { + suppressed *prometheus.CounterVec +} + +// newRateLimitMetrics registers the alloy_logging_suppressed_lines_total +// counter vector against reg. It returns nil if reg is nil, so that callers +// who don't want metrics (e.g. tests) can pass a nil registerer safely. +func newRateLimitMetrics(reg prometheus.Registerer) *rateLimitMetrics { + if reg == nil { + return nil + } + cv := prometheus.NewCounterVec(prometheus.CounterOpts{ + Name: "alloy_logging_suppressed_lines_total", + Help: "Total log lines dropped by the logger's rate limiter, by level and component.", + }, []string{"level", "component_id"}) + if existing := mustRegisterOrReturnExisting(reg, cv); existing != nil { + cvExisting, ok := existing.(*prometheus.CounterVec) + if !ok { + return nil + } + cv = cvExisting + } + return &rateLimitMetrics{suppressed: cv} +} + +// onDropped is the slog-sampling OnDropped hook: it increments the +// suppressed-lines counter for the record's level and component. +func (m *rateLimitMetrics) onDropped(ctx context.Context, r slog.Record) { + if m == nil { + return + } + m.suppressed.WithLabelValues(levelString(r.Level), componentFromCtx(ctx).id).Inc() +} + +// mustRegisterOrReturnExisting registers c against reg. If c is already +// registered (e.g. because multiple Logger instances share a registerer), +// it returns the previously registered collector instead of panicking. +// This is a local copy rather than a dependency on internal/util, which +// would create an import cycle. +func mustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collector) prometheus.Collector { + if err := reg.Register(c); err != nil { + if are, ok := err.(prometheus.AlreadyRegisteredError); ok { + return are.ExistingCollector + } + panic(err) + } + return nil +} + +// buildRoot returns the sampling-wrapped terminal handler when rate limiting +// is enabled, else it returns terminal unchanged. +func buildRoot(o RateLimitingOptions, terminal slog.Handler, m *rateLimitMetrics) slog.Handler { + if !o.Enabled { + return terminal + } + opt := slogsampling.ThresholdSamplingOption{ + Tick: o.Tick, + Threshold: o.Threshold, + Rate: o.Rate, + Matcher: compMatcher, + Buffer: buffer.NewLRUBuffer[string](o.MaxSignatures), + OnDropped: m.onDropped, + IncludeDroppedCount: true, + } + return opt.NewMiddleware()(terminal) +} diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go new file mode 100644 index 00000000000..a19ab22670e --- /dev/null +++ b/internal/runtime/logging/sampling_test.go @@ -0,0 +1,88 @@ +package logging + +import ( + "bytes" + "context" + "log/slog" + "strings" + "testing" + "time" + + slogsampling "github.com/samber/slog-sampling" + "github.com/samber/slog-sampling/buffer" + "github.com/stretchr/testify/require" +) + +// TestSpikeThresholdAdmitsThenDrops confirms the Threshold middleware wraps a +// terminal handler, keys via our Matcher, and admits `Threshold` per tick then +// drops (rate=0). This validates the exact library wiring the design relies on. +func TestSpikeThresholdAdmitsThenDrops(t *testing.T) { + var buf bytes.Buffer + terminal := slog.NewTextHandler(&buf, nil) + + opt := slogsampling.ThresholdSamplingOption{ + Tick: time.Hour, // one window for the whole test + Threshold: 3, + Rate: 0, + Matcher: func(ctx context.Context, r *slog.Record) string { return r.Message }, + Buffer: buffer.NewLRUBuffer[string](100), + } + h := opt.NewMiddleware()(terminal) + logger := slog.New(h) + for i := 0; i < 10; i++ { + logger.Info("spam") + } + require.Equal(t, 3, strings.Count(buf.String(), "spam"), "expected exactly Threshold admitted") +} + +func TestSniffComponent(t *testing.T) { + t.Run("component_id wins over controller_id", func(t *testing.T) { + c := sniffComponent(componentInfo{}, []slog.Attr{ + slog.String("controller_id", "ctrl-1"), + slog.String("component_id", "comp-1"), + }) + require.Equal(t, "comp-1", c.id) + }) + + t.Run("controller_id used when component_id absent", func(t *testing.T) { + c := sniffComponent(componentInfo{}, []slog.Attr{ + slog.String("controller_id", "ctrl-1"), + }) + require.Equal(t, "ctrl-1", c.id) + }) + + t.Run("component_id already set on base is not overridden by controller_id", func(t *testing.T) { + c := sniffComponent(componentInfo{id: "existing"}, []slog.Attr{ + slog.String("controller_id", "ctrl-1"), + }) + require.Equal(t, "existing", c.id) + }) + + t.Run("component_path captured", func(t *testing.T) { + c := sniffComponent(componentInfo{}, []slog.Attr{ + slog.String("component_path", "/foo/bar"), + }) + require.Equal(t, "/foo/bar", c.path) + }) +} + +func TestCompMatcherKeysOnPathLevelMessage(t *testing.T) { + mk := func(path string, level slog.Level, msg string) string { + ctx := withComponent(context.Background(), componentInfo{path: path}) + r := slog.NewRecord(time.Time{}, level, msg, 0) + return compMatcher(ctx, &r) + } + + base := mk("/a", slog.LevelInfo, "hello") + + require.Equal(t, base, mk("/a", slog.LevelInfo, "hello"), "identical path/level/message should produce the same key") + require.NotEqual(t, base, mk("/b", slog.LevelInfo, "hello"), "different path should produce a different key") + require.NotEqual(t, base, mk("/a", slog.LevelWarn, "hello"), "different level should produce a different key") + require.NotEqual(t, base, mk("/a", slog.LevelInfo, "goodbye"), "different message should produce a different key") +} + +func TestBuildRootDisabledReturnsTerminal(t *testing.T) { + terminal := slog.NewTextHandler(&bytes.Buffer{}, nil) + got := buildRoot(RateLimitingOptions{Enabled: false}, terminal, nil) + require.Same(t, terminal, got) +} From 519ea7f6be9d84aabbad3a5eaaae807ee1fad840 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 15:18:24 -0400 Subject: [PATCH 03/20] feat(logging): samplingInjector with versioned replay and empty-message bypass --- internal/runtime/logging/sampling.go | 134 ++++++++++++++++++++++ internal/runtime/logging/sampling_test.go | 57 +++++++++ 2 files changed, 191 insertions(+) diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index 92cd8097667..296279427a6 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -3,6 +3,7 @@ package logging import ( "context" "log/slog" + "sync/atomic" "github.com/prometheus/client_golang/prometheus" slogsampling "github.com/samber/slog-sampling" @@ -140,3 +141,136 @@ func buildRoot(o RateLimitingOptions, terminal slog.Handler, m *rateLimitMetrics } return opt.NewMiddleware()(terminal) } + +// replayOp captures a single WithAttrs or WithGroup call so that it can be +// replayed onto a freshly (re-)derived terminal handler. Exactly one of +// attrs or group is set. +type replayOp struct { + attrs []slog.Attr + group string +} + +// versionedHandler pairs the current sampling-wrapped root handler with a +// version number that's bumped whenever rate-limiting configuration changes +// (see Task 4). samplingInjector uses the version to know when its cached +// derived handler is stale and must be re-derived. +type versionedHandler struct { + version uint64 + h slog.Handler +} + +// cachedHandler is a samplingInjector's memoized replay of its ops onto a +// particular version of the root handler. +type cachedHandler struct { + version uint64 + h slog.Handler +} + +// samplingInjector is a slog.Handler that sits between component loggers and +// the shared, possibly rate-limited, root handler. It: +// +// - Tracks component identity (comp) sniffed from WithAttrs calls, so the +// rate limiter's Matcher can key on component path via the context. +// - Records every WithAttrs/WithGroup call as a replayOp, so that when the +// root handler is swapped out (e.g. rate-limiting config changes) or +// bypassed (empty-message records), those calls can be replayed onto the +// new/bare terminal handler to reproduce the same rendering. +// - Bypasses the rate limiter entirely for empty-message records, which +// would otherwise all collapse onto the same signature. +type samplingInjector struct { + comp componentInfo + ops []replayOp + + holder *atomic.Pointer[versionedHandler] + bare slog.Handler // root terminal (no per-component attrs), for empty-message bypass + + cache atomic.Pointer[cachedHandler] + bareCache atomic.Pointer[slog.Handler] +} + +// newSamplingInjector creates a samplingInjector rooted at holder (the +// current, possibly sampling-wrapped, root handler) with bare as the +// terminal handler used to bypass sampling for empty-message records. +func newSamplingInjector(holder *atomic.Pointer[versionedHandler], bare slog.Handler) *samplingInjector { + return &samplingInjector{holder: holder, bare: bare} +} + +// replay re-applies a recorded sequence of WithAttrs/WithGroup calls onto h, +// in order, reproducing the derived handler that would have resulted from +// making those calls directly against h. +func replay(h slog.Handler, ops []replayOp) slog.Handler { + for _, op := range ops { + if op.group != "" { + h = h.WithGroup(op.group) + } else { + h = h.WithAttrs(op.attrs) + } + } + return h +} + +// clone returns a new samplingInjector sharing this injector's holder and +// bare terminal, with an independent copy of ops and freshly reset caches +// (since a fresh ops slice means any previously cached replay is stale). +func (s *samplingInjector) clone() *samplingInjector { + // New injector shares holder/bare; caches reset (ops differ). + ns := &samplingInjector{comp: s.comp, holder: s.holder, bare: s.bare} + ns.ops = make([]replayOp, len(s.ops), len(s.ops)+1) + copy(ns.ops, s.ops) + return ns +} + +// WithAttrs returns a new handler with attrs bound. It also sniffs attrs for +// component identity so the rate limiter can key by component, and records +// the call as a replayOp so it still reaches the terminal handler for +// rendering. +func (s *samplingInjector) WithAttrs(attrs []slog.Attr) slog.Handler { + ns := s.clone() + ns.comp = sniffComponent(s.comp, attrs) + ns.ops = append(ns.ops, replayOp{attrs: attrs}) + return ns +} + +// WithGroup returns a new handler with name pushed as an open group, +// recording the call as a replayOp so it still reaches the terminal handler +// for rendering. +func (s *samplingInjector) WithGroup(name string) slog.Handler { + if name == "" { + return s + } + ns := s.clone() + ns.ops = append(ns.ops, replayOp{group: name}) + return ns +} + +// Enabled delegates to the current root handler. +func (s *samplingInjector) Enabled(ctx context.Context, l slog.Level) bool { + return s.holder.Load().h.Enabled(ctx, l) +} + +// Handle routes empty-message records directly to the bare terminal handler +// (bypassing the rate limiter, since blank-message records from different +// call sites would otherwise share a signature), and all other records +// through the current, possibly rate-limited, root handler with the +// component identity injected into ctx for the Matcher to read. +func (s *samplingInjector) Handle(ctx context.Context, r slog.Record) error { + if r.Message == "" { + // Bypass sampler: unrelated no-msg events must not collapse into one signature. + bh := s.bareCache.Load() + if bh == nil { + h := replay(s.bare, s.ops) + bh = &h + s.bareCache.Store(bh) + } + return (*bh).Handle(ctx, r) + } + vh := s.holder.Load() + c := s.cache.Load() + if c == nil || c.version != vh.version { + c = &cachedHandler{version: vh.version, h: replay(vh.h, s.ops)} + s.cache.Store(c) + } + return c.h.Handle(withComponent(ctx, s.comp), r) +} + +var _ slog.Handler = (*samplingInjector)(nil) diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go index a19ab22670e..021e649a9bc 100644 --- a/internal/runtime/logging/sampling_test.go +++ b/internal/runtime/logging/sampling_test.go @@ -5,6 +5,7 @@ import ( "context" "log/slog" "strings" + "sync/atomic" "testing" "time" @@ -86,3 +87,59 @@ func TestBuildRootDisabledReturnsTerminal(t *testing.T) { got := buildRoot(RateLimitingOptions{Enabled: false}, terminal, nil) require.Same(t, terminal, got) } + +func newTestInjector(t *testing.T, root slog.Handler, bare slog.Handler) *samplingInjector { + t.Helper() + var holder atomic.Pointer[versionedHandler] + holder.Store(&versionedHandler{version: 1, h: root}) + return newSamplingInjector(&holder, bare) +} + +func TestInjectorRendersAttrsAndGroups(t *testing.T) { + var buf bytes.Buffer + term := slog.NewTextHandler(&buf, nil) + inj := newTestInjector(t, term, term) // no sampling, just render + h := inj.WithAttrs([]slog.Attr{slog.String("component_id", "x")}).WithGroup("g").WithAttrs([]slog.Attr{slog.String("k", "v")}).(*samplingInjector) + require.Equal(t, "x", h.comp.id) + rec := slog.NewRecord(time.Unix(0, 0), slog.LevelInfo, "hi", 0) + require.NoError(t, h.Handle(context.Background(), rec)) + out := buf.String() + require.Contains(t, out, "component_id=x") + require.Contains(t, out, "g.k=v") // group-nested attr rendered natively +} + +func TestInjectorEmptyMessageBypassesSampler(t *testing.T) { + var termBuf bytes.Buffer + term := slog.NewTextHandler(&termBuf, nil) + // A root that drops everything, to prove empty-message goes to `bare` (term) not root. + // AbsoluteSamplingOption panics when Max == 0, so we build the drop-all root + // with ThresholdSamplingOption{Threshold: 0, Rate: 0} instead, which admits + // nothing (confirmed against slog-sampling v1.6.0 in Task 2's spike). + dropAll := slogsampling.ThresholdSamplingOption{ + Tick: time.Hour, + Threshold: 0, + Rate: 0, + Matcher: func(ctx context.Context, r *slog.Record) string { return "" }, + Buffer: buffer.NewLRUBuffer[string](10), + }.NewMiddleware()(slog.NewTextHandler(&bytes.Buffer{}, nil)) + inj := newTestInjector(t, dropAll, term) + rec := slog.NewRecord(time.Unix(0, 0), slog.LevelInfo, "", 0) + rec.AddAttrs(slog.String("k", "v")) + require.NoError(t, inj.Handle(context.Background(), rec)) + require.Contains(t, termBuf.String(), "k=v") // empty-msg reached bare terminal +} + +func TestInjectorReDerivesOnVersionBump(t *testing.T) { + var bufA, bufB bytes.Buffer + termA := slog.NewTextHandler(&bufA, nil) + termB := slog.NewTextHandler(&bufB, nil) + var holder atomic.Pointer[versionedHandler] + holder.Store(&versionedHandler{version: 1, h: termA}) + inj := newSamplingInjector(&holder, termA) + rec := slog.NewRecord(time.Unix(0, 0), slog.LevelInfo, "m", 0) + require.NoError(t, inj.Handle(context.Background(), rec)) + require.Contains(t, bufA.String(), "m") + holder.Store(&versionedHandler{version: 2, h: termB}) // reload + require.NoError(t, inj.Handle(context.Background(), rec)) + require.Contains(t, bufB.String(), "m") // now routed to the new root +} From 50cbc4d6e16664a4aec4c5afeccea9ed73fb84b4 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 15:34:54 -0400 Subject: [PATCH 04/20] feat(logging): wire slog-sampling rate limiter into Logger (live-reconfigurable, no goroutine) --- .../controller/node_config_logging.go | 2 + internal/runtime/logging/deferred_handler.go | 6 +- internal/runtime/logging/logger.go | 34 ++++++++ .../runtime/logging/logger_event_log_test.go | 19 +++-- internal/runtime/logging/logger_rl_test.go | 78 +++++++++++++++++++ 5 files changed, 131 insertions(+), 8 deletions(-) create mode 100644 internal/runtime/logging/logger_rl_test.go diff --git a/internal/runtime/internal/controller/node_config_logging.go b/internal/runtime/internal/controller/node_config_logging.go index 8dc588cb45a..3771e371cfa 100644 --- a/internal/runtime/internal/controller/node_config_logging.go +++ b/internal/runtime/internal/controller/node_config_logging.go @@ -25,6 +25,7 @@ type LoggingConfigNode struct { // NewLoggingConfigNode creates a new LoggingConfigNode from an initial ast.BlockStmt. // The underlying config isn't applied until Evaluate is called. func NewLoggingConfigNode(block *ast.BlockStmt, globals ComponentGlobals) *LoggingConfigNode { + globals.Logger.SetRateLimitMetrics(globals.Registerer) return &LoggingConfigNode{ nodeID: BlockComponentID(block).String(), componentName: block.GetBlockName(), @@ -38,6 +39,7 @@ func NewLoggingConfigNode(block *ast.BlockStmt, globals ComponentGlobals) *Loggi // NewDefaultLoggingConfigNode creates a new LoggingConfigNode with nil block and eval. // This will force evaluate to use the default logging options for this node. func NewDefaultLoggingConfigNode(globals ComponentGlobals) *LoggingConfigNode { + globals.Logger.SetRateLimitMetrics(globals.Registerer) return &LoggingConfigNode{ nodeID: loggingBlockID, componentName: loggingBlockID, diff --git a/internal/runtime/logging/deferred_handler.go b/internal/runtime/logging/deferred_handler.go index 1e3f29679b7..21d79e55a34 100644 --- a/internal/runtime/logging/deferred_handler.go +++ b/internal/runtime/logging/deferred_handler.go @@ -88,9 +88,11 @@ func (d *deferredSlogHandler) buildHandlers(parent slog.Handler) { d.mut.Lock() defer d.mut.Unlock() - // Root node will not have attrs or groups. + // Root node will not have attrs or groups. Route it through the + // samplingInjector so the shared, possibly rate-limited, root handler + // (l.rlHolder) sits between component loggers and the terminal handler. if parent == nil { - d.handle = d.l.handler + d.handle = newSamplingInjector(&d.l.rlHolder, d.l.handler) } else { if d.group != "" { d.handle = parent.WithGroup(d.group) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 80d9f6e503e..5e2c335c1f6 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -6,8 +6,10 @@ import ( "io" "log/slog" "sync" + "sync/atomic" "time" + "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" "github.com/grafana/alloy/internal/component/common/loki" @@ -36,6 +38,16 @@ type Logger struct { // the optional Windows Event Log. handler *handler deferredSlog *deferredSlogHandler // Buffers slog output until config is loaded, then delegates to handler. + + // rlHolder holds the current, possibly rate-limit-sampling-wrapped, root + // handler used by the samplingInjector rooted at the deferred handler + // tree. It starts pointing at the bare terminal handler (rate limiting + // disabled) and is swapped atomically by Update. rlVersion is bumped on + // every swap so samplingInjector instances know to re-derive their + // cached, per-component replay of the root handler. + rlHolder atomic.Pointer[versionedHandler] + rlVersion atomic.Uint64 + rlMetrics *rateLimitMetrics } var _ EnabledAware = (*Logger)(nil) @@ -94,6 +106,10 @@ func NewDeferred(w io.Writer) (*Logger, error) { writer: writer, handler: bh, } + // Disabled until the first Update: the injector's root is the bare + // terminal handler, so logging behaves exactly as it did before rate + // limiting existed until a config Update explicitly enables it. + l.rlHolder.Store(&versionedHandler{version: 0, h: bh}) l.deferredSlog = newDeferredHandler(l) return l, nil @@ -125,6 +141,17 @@ func (l *Logger) Update(o Options) error { l.writer.SetLokiWriter(o.WriteTo) l.bufferMut.Unlock() + rlOpts := defaultRateLimitingOptions() + if o.RateLimiting != nil { + rlOpts = *o.RateLimiting + } + if err := rlOpts.Validate(); err != nil { + return err + } + root := buildRoot(rlOpts, l.handler, l.rlMetrics) + v := l.rlVersion.Add(1) + l.rlHolder.Store(&versionedHandler{version: v, h: root}) + // Rebuild deferred slog handlers outside bufferMut to avoid a deadlock // with concurrent Handle() calls (they hold a child handler's RLock // while waiting for bufferMut via addRecord). @@ -157,6 +184,13 @@ func (l *Logger) flushBuffer() { } } +// SetRateLimitMetrics wires the suppressed-lines metric. Call once before the logger is shared. +func (l *Logger) SetRateLimitMetrics(reg prometheus.Registerer) { + if l.rlMetrics == nil { + l.rlMetrics = newRateLimitMetrics(reg) + } +} + func (l *Logger) SetTemporaryWriter(w io.Writer) { l.writer.SetTemporaryWriter(w) } diff --git a/internal/runtime/logging/logger_event_log_test.go b/internal/runtime/logging/logger_event_log_test.go index 59356406445..75966b8258c 100644 --- a/internal/runtime/logging/logger_event_log_test.go +++ b/internal/runtime/logging/logger_event_log_test.go @@ -229,6 +229,11 @@ func TestUpdate_NoLossDuringConcurrentDestinationFlips(t *testing.T) { Level: LevelInfo, Format: FormatLogfmt, Destination: LogDestinationStderr, + // This test hammers an identical "hammer" message ~8000 times and + // asserts an exact delivery count; rate limiting (on by default) + // would suppress most of them under the same signature. Disable it + // so this remains a pure destination-flip delivery test. + RateLimiting: &RateLimitingOptions{Enabled: false}, })) sl := l.Slog() @@ -265,9 +270,10 @@ func TestUpdate_NoLossDuringConcurrentDestinationFlips(t *testing.T) { dest = LogDestinationWindowsEventLog } err := l.Update(Options{ - Level: LevelInfo, - Format: FormatLogfmt, - Destination: dest, + Level: LevelInfo, + Format: FormatLogfmt, + Destination: dest, + RateLimiting: &RateLimitingOptions{Enabled: false}, }) if err != nil { t.Errorf("Update failed: %v", err) @@ -294,9 +300,10 @@ func TestUpdate_NoLossDuringConcurrentDestinationFlips(t *testing.T) { // End the test in the default destination so the final accounting is // stable. require.NoError(t, l.Update(Options{ - Level: LevelInfo, - Format: FormatLogfmt, - Destination: LogDestinationStderr, + Level: LevelInfo, + Format: FormatLogfmt, + Destination: LogDestinationStderr, + RateLimiting: &RateLimitingOptions{Enabled: false}, })) innerLines := inner.Lines() diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go new file mode 100644 index 00000000000..1901796007e --- /dev/null +++ b/internal/runtime/logging/logger_rl_test.go @@ -0,0 +1,78 @@ +package logging + +import ( + "bytes" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/require" + "go.uber.org/goleak" +) + +func TestLoggerRateLimitEndToEnd(t *testing.T) { + defer goleak.VerifyNone(t) // PROOF: no goroutine leaked by this feature + var buf bytes.Buffer + // Tick is short (but long enough that the initial burst of 10 calls + // lands in a single window even under -race) so the test can also + // observe the dropped-count annotation, which slog-sampling only + // attaches to the first admitted record of a *new* tick window (see + // samber/slog-sampling middleware_threshold.go); it never appears + // within the window that produced the drops. + l, err := New(&buf, Options{ + Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: 100 * time.Millisecond, Threshold: 2, Rate: 0, MaxSignatures: 100}, + }) + require.NoError(t, err) + log := l.Slog() + for i := 0; i < 10; i++ { + log.Info("floody") + } + require.Equal(t, 2, strings.Count(buf.String(), "floody")) // Threshold admitted within the window + + time.Sleep(300 * time.Millisecond) // let the tick window roll over + log.Info("floody") + require.Equal(t, 3, strings.Count(buf.String(), "floody")) + require.Contains(t, buf.String(), "slog_sampling.dropped_count") // first admission of new window annotated with prior drops +} + +func TestLoggerDistinctComponentsNoCrossSuppress(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + a := l.Slog().With("component_id", "a", "component_path", "/a") + b := l.Slog().With("component_id", "b", "component_path", "/b") + a.Info("same") + a.Info("same") // 2nd dropped + b.Info("same") // different component ⇒ own bucket ⇒ admitted + require.Equal(t, 2, strings.Count(buf.String(), "msg=same")) +} + +func TestLoggerDisabledByConfig(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, RateLimiting: &RateLimitingOptions{Enabled: false}}) + require.NoError(t, err) + log := l.Slog() + for i := 0; i < 10; i++ { + log.Info("noisy") + } + require.Equal(t, 10, strings.Count(buf.String(), "noisy")) +} + +func TestLoggerLiveRetune(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 100, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + log := l.Slog() // logger captured BEFORE reload + require.NoError(t, l.Update(Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}})) + for i := 0; i < 5; i++ { + log.Info("retuned") + } + require.Equal(t, 1, strings.Count(buf.String(), "retuned")) // new threshold applied live to pre-existing logger +} From 9e8f147974db2f3ee9951636deb9f46c95110d74 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 15:43:07 -0400 Subject: [PATCH 05/20] docs(logging): document rate_limiting block (slog-sampling variant) --- .../reference/config-blocks/logging.md | 33 +++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index 0a29453f154..75da9d2f304 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -65,6 +65,39 @@ Otherwise, `destination` defaults to `"stderr"`. {{< param "PRODUCT_NAME" >}} fails to start if `destination` is set to `"windows_event_log"` and {{< param "PRODUCT_NAME" >}} is not running on Windows. +## Blocks + +You can use the following blocks with `logging`: + +| Block | Description | Required | +| ----------------- | ---------------------------------------------- | -------- | +| [`rate_limiting`][rate_limiting] | Configure per-message rate limiting and sampling. | no | + +### `rate_limiting` + +The `rate_limiting` block enables per-message rate limiting and sampling of repeated log lines. + +| Name | Type | Description | Default | Required | +|------|------|-------------|---------|----------| +| `enabled` | `bool` | Enable per-message rate limiting. | `true` | no | +| `tick` | `duration` | Sampling window. | `"1s"` | no | +| `threshold` | `number` | Identical lines admitted per (component, level, message) per tick before sampling. | `10` | no | +| `rate` | `number` | Fraction (0–1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | +| `max_signatures` | `number` | Distinct signatures tracked; least-recently-used is evicted when full. | `1000` | no | + +Rate limiting keys on the component, the log level, and the log message text (not attributes/fields). +Only identical repeated lines from the same component at the same level are throttled; distinct components/messages are independent (LRU-bounded by `max_signatures`). + +Because keying is on the message TEXT, log lines that share a constant message but differ only in attributes are treated as the same signature and throttled together — use distinct message text when you need lines rate-limited independently. + +After suppression begins, the first admitted line of each new window carries a `slog_sampling.dropped_count` attribute. + +Dropped lines are counted by the `alloy_logging_suppressed_lines_total` metric (labeled by `level` and `component_id`). + +Set `enabled = false` to disable. Omitting the `rate_limiting` block leaves limiting enabled with defaults. + +[rate_limiting]: #rate_limiting + ## Retrieve logs You can retrieve the logs in different ways depending on your platform and installation method: From 19bc4178ad1b1f3bb21b42e6320c67f84bd342dc Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 16:55:14 -0400 Subject: [PATCH 06/20] Minor changes --- docs/sources/reference/config-blocks/logging.md | 2 +- internal/runtime/logging/logger.go | 15 ++++++++------- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index 75da9d2f304..9b52492aebc 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -88,7 +88,7 @@ The `rate_limiting` block enables per-message rate limiting and sampling of repe Rate limiting keys on the component, the log level, and the log message text (not attributes/fields). Only identical repeated lines from the same component at the same level are throttled; distinct components/messages are independent (LRU-bounded by `max_signatures`). -Because keying is on the message TEXT, log lines that share a constant message but differ only in attributes are treated as the same signature and throttled together — use distinct message text when you need lines rate-limited independently. +Because keying is on the message text, log lines that share a constant message but differ only in attributes are treated as the same signature and throttled together. After suppression begins, the first admitted line of each new window carries a `slog_sampling.dropped_count` attribute. diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 5e2c335c1f6..42357228ab1 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -131,6 +131,14 @@ func (l *Logger) Update(o Options) error { return fmt.Errorf("unrecognized log format %q", o.Format) } + rlOpts := defaultRateLimitingOptions() + if o.RateLimiting != nil { + rlOpts = *o.RateLimiting + } + if err := rlOpts.Validate(); err != nil { + return err + } + l.bufferMut.Lock() l.level.Set(slogLevel(o.Level).Level()) l.format.Set(o.Format) @@ -141,13 +149,6 @@ func (l *Logger) Update(o Options) error { l.writer.SetLokiWriter(o.WriteTo) l.bufferMut.Unlock() - rlOpts := defaultRateLimitingOptions() - if o.RateLimiting != nil { - rlOpts = *o.RateLimiting - } - if err := rlOpts.Validate(); err != nil { - return err - } root := buildRoot(rlOpts, l.handler, l.rlMetrics) v := l.rlVersion.Add(1) l.rlHolder.Store(&versionedHandler{version: v, h: root}) From 00eee0d084f546db736cc54165153ca2fc99e3c8 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Wed, 29 Jul 2026 23:55:43 -0400 Subject: [PATCH 07/20] fix(logging): key rate limiter on component_id+path; validate before applying Update; document empty-message bypass --- .../reference/config-blocks/logging.md | 2 + internal/runtime/logging/logger_rl_test.go | 42 +++++++++++++++++++ internal/runtime/logging/sampling.go | 10 ++++- internal/runtime/logging/sampling_test.go | 17 ++++---- 4 files changed, 61 insertions(+), 10 deletions(-) diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index 9b52492aebc..1e2777c8852 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -90,6 +90,8 @@ Only identical repeated lines from the same component at the same level are thro Because keying is on the message text, log lines that share a constant message but differ only in attributes are treated as the same signature and throttled together. +Log lines with an empty message, such as some `go-kit`-style logs emitted without a `msg` or `message` field, bypass rate limiting entirely and are always written. + After suppression begins, the first admitted line of each new window carries a `slog_sampling.dropped_count` attribute. Dropped lines are counted by the `alloy_logging_suppressed_lines_total` metric (labeled by `level` and `component_id`). diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go index 1901796007e..b002fb029fc 100644 --- a/internal/runtime/logging/logger_rl_test.go +++ b/internal/runtime/logging/logger_rl_test.go @@ -2,6 +2,8 @@ package logging import ( "bytes" + "context" + "log/slog" "strings" "testing" "time" @@ -50,6 +52,25 @@ func TestLoggerDistinctComponentsNoCrossSuppress(t *testing.T) { require.Equal(t, 2, strings.Count(buf.String(), "msg=same")) } +// TestLoggerSamePathDistinctComponentIDNoCrossSuppress guards against the +// bug where compMatcher keyed only on component_path (the parent/module +// path, e.g. "/" for every top-level component) and message/level. Two +// distinct top-level components sharing the same parent path but different +// component_id must not share a rate-limit bucket. +func TestLoggerSamePathDistinctComponentIDNoCrossSuppress(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + a := l.Slog().With("component_path", "/", "component_id", "comp.a") + b := l.Slog().With("component_path", "/", "component_id", "comp.b") + a.Info("same") + a.Info("same") // 2nd dropped: same component, same signature + b.Info("same") // different component_id, same path ⇒ own bucket ⇒ admitted + require.Equal(t, 2, strings.Count(buf.String(), "msg=same")) +} + func TestLoggerDisabledByConfig(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer @@ -62,6 +83,27 @@ func TestLoggerDisabledByConfig(t *testing.T) { require.Equal(t, 10, strings.Count(buf.String(), "noisy")) } +func TestUpdateInvalidRateLimitingLeavesStateUnchanged(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, RateLimiting: &RateLimitingOptions{Enabled: false}}) + require.NoError(t, err) + + err = l.Update(Options{ + Level: LevelError, + Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: 0}, + }) + require.Error(t, err) + + // The level must not have been mutated: an Info record should still pass, + // proving the invalid RateLimiting config was rejected before any other + // state (level, format, writer) was applied. + require.True(t, l.Enabled(context.Background(), slog.LevelInfo)) + l.Slog().Info("still-info") + require.Contains(t, buf.String(), "still-info") +} + func TestLoggerLiveRetune(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index 296279427a6..701b019e5cf 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -50,10 +50,16 @@ func componentFromCtx(ctx context.Context) componentInfo { // compMatcher is the slog-sampling Matcher used to key the rate limiter's // per-signature counters. Two records are considered the same "signature" // (and thus share a rate-limit budget) when they share the same component -// path, level, and message. +// path, component id, level, and message. +// +// component_path alone is not enough: it identifies the parent/module path +// (e.g. "/" for every top-level component), so distinct top-level components +// emitting the same message at the same level would otherwise collapse onto +// one signature and cross-suppress each other. component_id disambiguates +// them. func compMatcher(ctx context.Context, r *slog.Record) string { c := componentFromCtx(ctx) - return c.path + "\x00" + r.Level.String() + "\x00" + r.Message + return c.path + "\x00" + c.id + "\x00" + r.Level.String() + "\x00" + r.Message } // levelString maps a slog.Level to the lowercase level label used on the diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go index 021e649a9bc..52729722301 100644 --- a/internal/runtime/logging/sampling_test.go +++ b/internal/runtime/logging/sampling_test.go @@ -67,19 +67,20 @@ func TestSniffComponent(t *testing.T) { }) } -func TestCompMatcherKeysOnPathLevelMessage(t *testing.T) { - mk := func(path string, level slog.Level, msg string) string { - ctx := withComponent(context.Background(), componentInfo{path: path}) +func TestCompMatcherKeysOnPathIDLevelMessage(t *testing.T) { + mk := func(path, id string, level slog.Level, msg string) string { + ctx := withComponent(context.Background(), componentInfo{path: path, id: id}) r := slog.NewRecord(time.Time{}, level, msg, 0) return compMatcher(ctx, &r) } - base := mk("/a", slog.LevelInfo, "hello") + base := mk("/a", "comp.a", slog.LevelInfo, "hello") - require.Equal(t, base, mk("/a", slog.LevelInfo, "hello"), "identical path/level/message should produce the same key") - require.NotEqual(t, base, mk("/b", slog.LevelInfo, "hello"), "different path should produce a different key") - require.NotEqual(t, base, mk("/a", slog.LevelWarn, "hello"), "different level should produce a different key") - require.NotEqual(t, base, mk("/a", slog.LevelInfo, "goodbye"), "different message should produce a different key") + require.Equal(t, base, mk("/a", "comp.a", slog.LevelInfo, "hello"), "identical path/id/level/message should produce the same key") + require.NotEqual(t, base, mk("/b", "comp.a", slog.LevelInfo, "hello"), "different path should produce a different key") + require.NotEqual(t, base, mk("/a", "comp.b", slog.LevelInfo, "hello"), "different component id (same path) should produce a different key") + require.NotEqual(t, base, mk("/a", "comp.a", slog.LevelWarn, "hello"), "different level should produce a different key") + require.NotEqual(t, base, mk("/a", "comp.a", slog.LevelInfo, "goodbye"), "different message should produce a different key") } func TestBuildRootDisabledReturnsTerminal(t *testing.T) { From 0aebe02df232d8fde52f16fe543185e2d91891af Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Thu, 30 Jul 2026 00:27:31 -0400 Subject: [PATCH 08/20] fix(logging): rebuild sampler only on rate_limiting change; guard Update with a mutex --- internal/runtime/logging/logger.go | 28 +++++++- internal/runtime/logging/logger_rl_test.go | 80 ++++++++++++++++++++++ 2 files changed, 105 insertions(+), 3 deletions(-) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 42357228ab1..7de3993118a 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -48,6 +48,20 @@ type Logger struct { rlHolder atomic.Pointer[versionedHandler] rlVersion atomic.Uint64 rlMetrics *rateLimitMetrics + + // rlMut guards the rate-limiting apply block in Update (the + // rlApplied comparison, buildRoot, rlVersion bump, and rlHolder + // store must happen as one atomic unit) as well as writes/reads of + // rlMetrics, which is otherwise read in Update without + // synchronization against SetRateLimitMetrics. + rlMut sync.Mutex + // rlApplied is the RateLimitingOptions last used to build the + // current rlHolder root. nil means no Update has applied rate + // limiting yet. Update only rebuilds the sampler (and bumps + // rlVersion) when the incoming options differ from rlApplied, so + // unrelated config reloads don't reset in-flight rate-limit + // budgets. + rlApplied *RateLimitingOptions } var _ EnabledAware = (*Logger)(nil) @@ -149,9 +163,15 @@ func (l *Logger) Update(o Options) error { l.writer.SetLokiWriter(o.WriteTo) l.bufferMut.Unlock() - root := buildRoot(rlOpts, l.handler, l.rlMetrics) - v := l.rlVersion.Add(1) - l.rlHolder.Store(&versionedHandler{version: v, h: root}) + l.rlMut.Lock() + if l.rlApplied == nil || *l.rlApplied != rlOpts { + root := buildRoot(rlOpts, l.handler, l.rlMetrics) + v := l.rlVersion.Add(1) + l.rlHolder.Store(&versionedHandler{version: v, h: root}) + applied := rlOpts + l.rlApplied = &applied + } + l.rlMut.Unlock() // Rebuild deferred slog handlers outside bufferMut to avoid a deadlock // with concurrent Handle() calls (they hold a child handler's RLock @@ -187,6 +207,8 @@ func (l *Logger) flushBuffer() { // SetRateLimitMetrics wires the suppressed-lines metric. Call once before the logger is shared. func (l *Logger) SetRateLimitMetrics(reg prometheus.Registerer) { + l.rlMut.Lock() + defer l.rlMut.Unlock() if l.rlMetrics == nil { l.rlMetrics = newRateLimitMetrics(reg) } diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go index b002fb029fc..fe04711b6b3 100644 --- a/internal/runtime/logging/logger_rl_test.go +++ b/internal/runtime/logging/logger_rl_test.go @@ -5,6 +5,7 @@ import ( "context" "log/slog" "strings" + "sync" "testing" "time" @@ -104,6 +105,85 @@ func TestUpdateInvalidRateLimitingLeavesStateUnchanged(t *testing.T) { require.Contains(t, buf.String(), "still-info") } +// TestUpdateSameOptionsPreservesBudget guards against re-applying an +// unchanged RateLimitingOptions on every Update (e.g. from an unrelated +// config reload) resetting the sampler's per-signature counters. Before the +// fix, Update unconditionally rebuilt the sampler (fresh LRU/counters) on +// every call, so the repeated call below would spuriously re-admit the +// already-throttled line. +func TestUpdateSameOptionsPreservesBudget(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + opts := Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 2, Rate: 0, MaxSignatures: 100}} + l, err := New(&buf, opts) + require.NoError(t, err) + log := l.Slog() + + log.Info("steady") + log.Info("steady") + log.Info("steady") // 3rd: over threshold, dropped + require.Equal(t, 2, strings.Count(buf.String(), "msg=steady")) + + // Re-apply the identical options (simulating an unrelated config + // reload triggering LoggingConfigNode.Evaluate -> Update again). + require.NoError(t, l.Update(opts)) + + log.Info("steady") // still over the ORIGINAL window's budget: must stay dropped + require.Equal(t, 2, strings.Count(buf.String(), "msg=steady")) +} + +// TestUpdateChangedOptionsRebuilds confirms that when rate_limiting options +// actually change across Update, the new configuration takes effect for a +// pre-existing logger. This overlaps with TestLoggerLiveRetune but pins down +// the specific contract exercised by the conditional-rebuild fix: a change +// must still trigger a rebuild (not just "same options are a no-op"). +func TestUpdateChangedOptionsRebuilds(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 2, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + log := l.Slog() + + require.NoError(t, l.Update(Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}})) + + log.Info("changed") + log.Info("changed") // 2nd: over the NEW threshold of 1, dropped + require.Equal(t, 1, strings.Count(buf.String(), "msg=changed")) +} + +// TestConcurrentUpdatesNoRace exercises many goroutines calling Update +// concurrently with valid (possibly differing) options. It asserts -race +// stays clean, nothing panics, and the logger is still functional +// afterward. +func TestConcurrentUpdatesNoRace(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 10, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + + var wg sync.WaitGroup + for g := 0; g < 8; g++ { + wg.Add(1) + go func(g int) { + defer wg.Done() + for i := 0; i < 5; i++ { + threshold := uint64(1 + (g+i)%5) + err := l.Update(Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: threshold, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + } + }(g) + } + wg.Wait() + + l.Slog().Info("post-concurrent-update") + require.Contains(t, buf.String(), "post-concurrent-update") +} + func TestLoggerLiveRetune(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer From 955bc0de0870c4aa4274cc8d4ff38aeb72e2a473 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Thu, 30 Jul 2026 00:37:40 -0400 Subject: [PATCH 09/20] test(logging): add rate limiter benchmarks (slog-sampling variant) --- internal/runtime/logging/rl_bench_test.go | 121 ++++++++++++++++++++++ 1 file changed, 121 insertions(+) create mode 100644 internal/runtime/logging/rl_bench_test.go diff --git a/internal/runtime/logging/rl_bench_test.go b/internal/runtime/logging/rl_bench_test.go new file mode 100644 index 00000000000..218465322b2 --- /dev/null +++ b/internal/runtime/logging/rl_bench_test.go @@ -0,0 +1,121 @@ +package logging + +import ( + "io" + "strconv" + "testing" + "time" + + "github.com/prometheus/client_golang/prometheus" +) + +// newRLBenchLogger builds a real *Logger writing to io.Discard, configured +// with the given RateLimitingOptions, and wires a fresh metrics registry so +// the drop path exercises the alloy_logging_suppressed_lines_total counter +// (matching production wiring). +func newRLBenchLogger(b *testing.B, rl RateLimitingOptions) *Logger { + b.Helper() + l, err := New(io.Discard, Options{ + Level: LevelInfo, + Format: FormatLogfmt, + RateLimiting: &rl, + }) + if err != nil { + b.Fatalf("failed to create logger: %v", err) + } + l.SetRateLimitMetrics(prometheus.NewRegistry()) + return l +} + +// BenchmarkRL_Disabled measures the baseline passthrough path with rate +// limiting disabled entirely. +func BenchmarkRL_Disabled(b *testing.B) { + l := newRLBenchLogger(b, RateLimitingOptions{Enabled: false}) + log := l.Slog() + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("bench message") + } +} + +// BenchmarkRL_AdmitHot measures the steady-state admit path: threshold is +// effectively unbounded, so every call is admitted (matcher key build + +// counter Inc + terminal write). +func BenchmarkRL_AdmitHot(b *testing.B) { + l := newRLBenchLogger(b, RateLimitingOptions{ + Enabled: true, + Tick: time.Hour, + Threshold: 1 << 62, + Rate: 0, + MaxSignatures: 1000, + }) + log := l.Slog() + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("bench message") + } +} + +// BenchmarkRL_DropHot measures the drop path: after the first call, every +// identical call is dropped (matcher + counter + OnDropped metric, no +// terminal write). +func BenchmarkRL_DropHot(b *testing.B) { + l := newRLBenchLogger(b, RateLimitingOptions{ + Enabled: true, + Tick: time.Hour, + Threshold: 1, + Rate: 0, + MaxSignatures: 1000, + }) + log := l.Slog() + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("bench message") + } +} + +// BenchmarkRL_Churn logs a different message each iteration so every call +// is a new signature, exercising the LRU insert path. +func BenchmarkRL_Churn(b *testing.B) { + l := newRLBenchLogger(b, RateLimitingOptions{ + Enabled: true, + Tick: time.Hour, + Threshold: 1 << 62, + Rate: 0, + MaxSignatures: 1000, + }) + log := l.Slog() + + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + log.Info("msg " + strconv.Itoa(i&0xffff)) + } +} + +// BenchmarkRL_Parallel measures lock/contention on the shared buffer when N +// goroutines log the same admit-hot line concurrently. +func BenchmarkRL_Parallel(b *testing.B) { + l := newRLBenchLogger(b, RateLimitingOptions{ + Enabled: true, + Tick: time.Hour, + Threshold: 1 << 62, + Rate: 0, + MaxSignatures: 1000, + }) + log := l.Slog() + + b.ReportAllocs() + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log.Info("bench message") + } + }) +} From 43549275c8e06a772de49c0c26654cae6693d53f Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Thu, 30 Jul 2026 00:55:38 -0400 Subject: [PATCH 10/20] perf(logging): route Enabled to bare terminal and cache component context on the admit path --- internal/runtime/logging/logger_rl_test.go | 29 +++++++++++++++ internal/runtime/logging/sampling.go | 41 ++++++++++++++++++---- internal/runtime/logging/sampling_test.go | 16 +++++++++ 3 files changed, 80 insertions(+), 6 deletions(-) diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go index fe04711b6b3..6b692335b04 100644 --- a/internal/runtime/logging/logger_rl_test.go +++ b/internal/runtime/logging/logger_rl_test.go @@ -72,6 +72,35 @@ func TestLoggerSamePathDistinctComponentIDNoCrossSuppress(t *testing.T) { require.Equal(t, 2, strings.Count(buf.String(), "msg=same")) } +// ctxVariantKey is an unexported context key used solely to build a non- +// context.Background() ctx for TestInjectorComponentKeyingViaContextVariant. +type ctxVariantKey struct{} + +// TestInjectorComponentKeyingViaContextVariant guards optimization B's +// fallback path: when Handle is reached via a NON-Background ctx (e.g. +// slog's *Context logging variants), component identity must still be +// threaded through withComponent(ctx, s.comp) rather than the precomputed +// bgCtx, so distinct components sharing a signature don't cross-suppress. +func TestInjectorComponentKeyingViaContextVariant(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + a := l.Slog().With("component_path", "/", "component_id", "comp.a") + b := l.Slog().With("component_path", "/", "component_id", "comp.b") + + // Deliberately not context.Background(), to exercise Handle's + // withComponent(ctx, s.comp) fallback rather than the cached bgCtx. + ctx := context.WithValue(context.Background(), ctxVariantKey{}, 1) + require.NotEqual(t, context.Background(), ctx) + + a.Log(ctx, slog.LevelInfo, "same") + a.Log(ctx, slog.LevelInfo, "same") // 2nd dropped: same component, same signature + b.Log(ctx, slog.LevelInfo, "same") // different component_id ⇒ own bucket ⇒ admitted despite the shared non-Background ctx + require.Equal(t, 2, strings.Count(buf.String(), "msg=same")) +} + func TestLoggerDisabledByConfig(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index 701b019e5cf..515fb09a7c7 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -190,6 +190,13 @@ type samplingInjector struct { holder *atomic.Pointer[versionedHandler] bare slog.Handler // root terminal (no per-component attrs), for empty-message bypass + // bgCtx is context.Background() with comp already injected via + // withComponent. It's precomputed per injector (rather than on every + // Handle call) because slog.Logger.Info/Warn/Error always pass + // context.Background(), making this the overwhelmingly common case on + // the admit path; see Handle. + bgCtx context.Context + cache atomic.Pointer[cachedHandler] bareCache atomic.Pointer[slog.Handler] } @@ -198,7 +205,9 @@ type samplingInjector struct { // current, possibly sampling-wrapped, root handler) with bare as the // terminal handler used to bypass sampling for empty-message records. func newSamplingInjector(holder *atomic.Pointer[versionedHandler], bare slog.Handler) *samplingInjector { - return &samplingInjector{holder: holder, bare: bare} + s := &samplingInjector{holder: holder, bare: bare} + s.bgCtx = withComponent(context.Background(), s.comp) + return s } // replay re-applies a recorded sequence of WithAttrs/WithGroup calls onto h, @@ -219,8 +228,10 @@ func replay(h slog.Handler, ops []replayOp) slog.Handler { // bare terminal, with an independent copy of ops and freshly reset caches // (since a fresh ops slice means any previously cached replay is stale). func (s *samplingInjector) clone() *samplingInjector { - // New injector shares holder/bare; caches reset (ops differ). - ns := &samplingInjector{comp: s.comp, holder: s.holder, bare: s.bare} + // New injector shares holder/bare; caches reset (ops differ). comp is + // unchanged by clone itself (WithAttrs mutates it on the returned + // injector below), so bgCtx carries over from the parent unchanged too. + ns := &samplingInjector{comp: s.comp, holder: s.holder, bare: s.bare, bgCtx: s.bgCtx} ns.ops = make([]replayOp, len(s.ops), len(s.ops)+1) copy(ns.ops, s.ops) return ns @@ -233,6 +244,7 @@ func (s *samplingInjector) clone() *samplingInjector { func (s *samplingInjector) WithAttrs(attrs []slog.Attr) slog.Handler { ns := s.clone() ns.comp = sniffComponent(s.comp, attrs) + ns.bgCtx = withComponent(context.Background(), ns.comp) ns.ops = append(ns.ops, replayOp{attrs: attrs}) return ns } @@ -249,9 +261,15 @@ func (s *samplingInjector) WithGroup(name string) slog.Handler { return ns } -// Enabled delegates to the current root handler. +// Enabled delegates to the bare terminal handler rather than the (possibly +// sampling-wrapped) root: sampling only ever drops in Handle, never changes +// level-enabled-ness, so routing here avoids paying the sampling middleware's +// per-call Enabled cost on every slog.Info/Warn/Error call site. s.bare's +// leveler is the shared LevelVar mutated by Update, and level-gating is +// component-independent, so this is correct for every derived injector, not +// just the root one. func (s *samplingInjector) Enabled(ctx context.Context, l slog.Level) bool { - return s.holder.Load().h.Enabled(ctx, l) + return s.bare.Enabled(ctx, l) } // Handle routes empty-message records directly to the bare terminal handler @@ -276,7 +294,18 @@ func (s *samplingInjector) Handle(ctx context.Context, r slog.Record) error { c = &cachedHandler{version: vh.version, h: replay(vh.h, s.ops)} s.cache.Store(c) } - return c.h.Handle(withComponent(ctx, s.comp), r) + // slog.Logger.Info/Warn/Error always pass context.Background(); reuse + // the precomputed component ctx for that common case instead of paying + // context.WithValue's allocation on every admitted line. Any other ctx + // (e.g. via InfoContext) falls back to injecting fresh, since it may + // carry values or a Done channel we must not clobber. + var cctx context.Context + if ctx == context.Background() { + cctx = s.bgCtx + } else { + cctx = withComponent(ctx, s.comp) + } + return c.h.Handle(cctx, r) } var _ slog.Handler = (*samplingInjector)(nil) diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go index 52729722301..00c1fbecf60 100644 --- a/internal/runtime/logging/sampling_test.go +++ b/internal/runtime/logging/sampling_test.go @@ -3,6 +3,7 @@ package logging import ( "bytes" "context" + "io" "log/slog" "strings" "sync/atomic" @@ -130,6 +131,21 @@ func TestInjectorEmptyMessageBypassesSampler(t *testing.T) { require.Contains(t, termBuf.String(), "k=v") // empty-msg reached bare terminal } +// TestInjectorEnabledMatchesTerminalLevel guards optimization A: Enabled must +// delegate to the bare terminal handler (whose leveler reflects the current, +// live-updatable level), not to the sampling-wrapped root. Here root reports +// everything enabled (LevelDebug) while bare is gated at Info, so if Enabled +// mistakenly consulted root instead of bare, the LevelDebug assertion below +// would fail. +func TestInjectorEnabledMatchesTerminalLevel(t *testing.T) { + root := slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug}) + bare := slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelInfo}) + inj := newTestInjector(t, root, bare) + + require.False(t, inj.Enabled(context.Background(), slog.LevelDebug), "Enabled must reflect the terminal's level, not the sampling root's") + require.True(t, inj.Enabled(context.Background(), slog.LevelInfo)) +} + func TestInjectorReDerivesOnVersionBump(t *testing.T) { var bufA, bufB bytes.Buffer termA := slog.NewTextHandler(&bufA, nil) From f42803ebda95bfa98a2a95ca5d9d27ae75ce38d7 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 10:30:34 -0400 Subject: [PATCH 11/20] docs(logging): simplify code comments to ASD-STE100 Comment-only pass over the v2 logger rate-limiting feature code (sampling.go and the branch-added comments in logger.go, deferred_handler.go, options.go, and their tests), rewriting comments in Simplified Technical English while preserving the essential rationale (versioned-cache replay, empty-message bypass, the ctx==context.Background() fast path, Enabled routing to the bare handler, and Update's lock ordering / rebuild-on-change logic). Co-Authored-By: Claude Opus 4.8 --- internal/runtime/logging/deferred_handler.go | 7 +- internal/runtime/logging/logger.go | 41 +++-- internal/runtime/logging/logger_rl_test.go | 54 +++--- internal/runtime/logging/options.go | 7 +- internal/runtime/logging/rl_bench_test.go | 20 +-- internal/runtime/logging/sampling.go | 180 +++++++++---------- internal/runtime/logging/sampling_test.go | 23 ++- 7 files changed, 163 insertions(+), 169 deletions(-) diff --git a/internal/runtime/logging/deferred_handler.go b/internal/runtime/logging/deferred_handler.go index 21d79e55a34..a85e2d09630 100644 --- a/internal/runtime/logging/deferred_handler.go +++ b/internal/runtime/logging/deferred_handler.go @@ -88,9 +88,10 @@ func (d *deferredSlogHandler) buildHandlers(parent slog.Handler) { d.mut.Lock() defer d.mut.Unlock() - // Root node will not have attrs or groups. Route it through the - // samplingInjector so the shared, possibly rate-limited, root handler - // (l.rlHolder) sits between component loggers and the terminal handler. + // The root node has no attrs or groups. Route it through the + // samplingInjector, so the shared root handler (l.rlHolder), which may + // be rate-limited, sits between component loggers and the terminal + // handler. if parent == nil { d.handle = newSamplingInjector(&d.l.rlHolder, d.l.handler) } else { diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 7de3993118a..d2badf0f9ea 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -39,28 +39,27 @@ type Logger struct { handler *handler deferredSlog *deferredSlogHandler // Buffers slog output until config is loaded, then delegates to handler. - // rlHolder holds the current, possibly rate-limit-sampling-wrapped, root - // handler used by the samplingInjector rooted at the deferred handler - // tree. It starts pointing at the bare terminal handler (rate limiting - // disabled) and is swapped atomically by Update. rlVersion is bumped on - // every swap so samplingInjector instances know to re-derive their - // cached, per-component replay of the root handler. + // rlHolder holds the current root handler used by the samplingInjector + // in the deferred handler tree. This handler may be wrapped for + // rate-limit sampling. It starts as the bare terminal handler (rate + // limiting off), and Update swaps it atomically. rlVersion increases on + // each swap, so samplingInjector instances know to rebuild their cached, + // per-component replay of the root handler. rlHolder atomic.Pointer[versionedHandler] rlVersion atomic.Uint64 rlMetrics *rateLimitMetrics - // rlMut guards the rate-limiting apply block in Update (the - // rlApplied comparison, buildRoot, rlVersion bump, and rlHolder - // store must happen as one atomic unit) as well as writes/reads of - // rlMetrics, which is otherwise read in Update without - // synchronization against SetRateLimitMetrics. + // rlMut guards the rate-limiting block in Update: the rlApplied check, + // buildRoot call, rlVersion increase, and rlHolder store must happen as + // one unit. rlMut also guards rlMetrics, which Update reads without any + // other synchronization against SetRateLimitMetrics. rlMut sync.Mutex - // rlApplied is the RateLimitingOptions last used to build the - // current rlHolder root. nil means no Update has applied rate - // limiting yet. Update only rebuilds the sampler (and bumps - // rlVersion) when the incoming options differ from rlApplied, so - // unrelated config reloads don't reset in-flight rate-limit - // budgets. + // rlApplied is the RateLimitingOptions last used to build the current + // rlHolder root. nil means no Update has applied rate limiting yet. + // Update rebuilds the sampler, and increases rlVersion, only when the + // new options differ from rlApplied. This way, a config reload that + // does not change rate limiting does not reset rate-limit budgets that + // are already in use. rlApplied *RateLimitingOptions } @@ -120,9 +119,9 @@ func NewDeferred(w io.Writer) (*Logger, error) { writer: writer, handler: bh, } - // Disabled until the first Update: the injector's root is the bare - // terminal handler, so logging behaves exactly as it did before rate - // limiting existed until a config Update explicitly enables it. + // Rate limiting starts disabled: the injector's root is the bare + // terminal handler, so logging works as it did before rate limiting + // existed, until the first config Update enables it. l.rlHolder.Store(&versionedHandler{version: 0, h: bh}) l.deferredSlog = newDeferredHandler(l) @@ -205,7 +204,7 @@ func (l *Logger) flushBuffer() { } } -// SetRateLimitMetrics wires the suppressed-lines metric. Call once before the logger is shared. +// SetRateLimitMetrics sets up the suppressed-lines metric. Call this once, before the logger is shared. func (l *Logger) SetRateLimitMetrics(reg prometheus.Registerer) { l.rlMut.Lock() defer l.rlMut.Unlock() diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go index 6b692335b04..df5b1d79c6c 100644 --- a/internal/runtime/logging/logger_rl_test.go +++ b/internal/runtime/logging/logger_rl_test.go @@ -16,12 +16,11 @@ import ( func TestLoggerRateLimitEndToEnd(t *testing.T) { defer goleak.VerifyNone(t) // PROOF: no goroutine leaked by this feature var buf bytes.Buffer - // Tick is short (but long enough that the initial burst of 10 calls - // lands in a single window even under -race) so the test can also - // observe the dropped-count annotation, which slog-sampling only - // attaches to the first admitted record of a *new* tick window (see - // samber/slog-sampling middleware_threshold.go); it never appears - // within the window that produced the drops. + // Tick is short, but long enough that the first burst of 10 calls lands + // in one window, even under -race. This lets the test also see the + // dropped-count annotation. slog-sampling adds this annotation only to + // the first admitted record of a new tick window, never to the window + // that produced the drops. l, err := New(&buf, Options{ Level: LevelInfo, Format: FormatLogfmt, RateLimiting: &RateLimitingOptions{Enabled: true, Tick: 100 * time.Millisecond, Threshold: 2, Rate: 0, MaxSignatures: 100}, @@ -53,10 +52,10 @@ func TestLoggerDistinctComponentsNoCrossSuppress(t *testing.T) { require.Equal(t, 2, strings.Count(buf.String(), "msg=same")) } -// TestLoggerSamePathDistinctComponentIDNoCrossSuppress guards against the -// bug where compMatcher keyed only on component_path (the parent/module -// path, e.g. "/" for every top-level component) and message/level. Two -// distinct top-level components sharing the same parent path but different +// TestLoggerSamePathDistinctComponentIDNoCrossSuppress checks a past bug, +// where compMatcher keyed only on component_path (the parent path, for +// example "/" for every top-level component), message, and level. Two +// top-level components with the same parent path but different // component_id must not share a rate-limit bucket. func TestLoggerSamePathDistinctComponentIDNoCrossSuppress(t *testing.T) { defer goleak.VerifyNone(t) @@ -76,11 +75,12 @@ func TestLoggerSamePathDistinctComponentIDNoCrossSuppress(t *testing.T) { // context.Background() ctx for TestInjectorComponentKeyingViaContextVariant. type ctxVariantKey struct{} -// TestInjectorComponentKeyingViaContextVariant guards optimization B's -// fallback path: when Handle is reached via a NON-Background ctx (e.g. -// slog's *Context logging variants), component identity must still be -// threaded through withComponent(ctx, s.comp) rather than the precomputed -// bgCtx, so distinct components sharing a signature don't cross-suppress. +// TestInjectorComponentKeyingViaContextVariant checks Handle's fallback +// path: when Handle gets a ctx other than context.Background(), for example +// from slog's *Context logging methods, it must still add component +// identity through withComponent(ctx, s.comp), not the cached bgCtx. This +// keeps distinct components with the same signature from suppressing each +// other. func TestInjectorComponentKeyingViaContextVariant(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer @@ -134,11 +134,11 @@ func TestUpdateInvalidRateLimitingLeavesStateUnchanged(t *testing.T) { require.Contains(t, buf.String(), "still-info") } -// TestUpdateSameOptionsPreservesBudget guards against re-applying an -// unchanged RateLimitingOptions on every Update (e.g. from an unrelated -// config reload) resetting the sampler's per-signature counters. Before the -// fix, Update unconditionally rebuilt the sampler (fresh LRU/counters) on -// every call, so the repeated call below would spuriously re-admit the +// TestUpdateSameOptionsPreservesBudget checks that re-applying the same +// RateLimitingOptions on every Update, for example from an unrelated config +// reload, does not reset the sampler's per-signature counters. Before this +// fix, Update always rebuilt the sampler with a fresh LRU and counters on +// every call, so the repeated call below would wrongly re-admit the // already-throttled line. func TestUpdateSameOptionsPreservesBudget(t *testing.T) { defer goleak.VerifyNone(t) @@ -163,10 +163,9 @@ func TestUpdateSameOptionsPreservesBudget(t *testing.T) { } // TestUpdateChangedOptionsRebuilds confirms that when rate_limiting options -// actually change across Update, the new configuration takes effect for a -// pre-existing logger. This overlaps with TestLoggerLiveRetune but pins down -// the specific contract exercised by the conditional-rebuild fix: a change -// must still trigger a rebuild (not just "same options are a no-op"). +// change across an Update call, the new configuration takes effect for an +// existing logger. A change must still trigger a rebuild, not just skip it +// like unchanged options do. func TestUpdateChangedOptionsRebuilds(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer @@ -183,10 +182,9 @@ func TestUpdateChangedOptionsRebuilds(t *testing.T) { require.Equal(t, 1, strings.Count(buf.String(), "msg=changed")) } -// TestConcurrentUpdatesNoRace exercises many goroutines calling Update -// concurrently with valid (possibly differing) options. It asserts -race -// stays clean, nothing panics, and the logger is still functional -// afterward. +// TestConcurrentUpdatesNoRace calls Update from many goroutines at once, +// with valid options that may differ. It checks that -race stays clean, +// nothing panics, and the logger still works afterward. func TestConcurrentUpdatesNoRace(t *testing.T) { defer goleak.VerifyNone(t) var buf bytes.Buffer diff --git a/internal/runtime/logging/options.go b/internal/runtime/logging/options.go index 3cda1938cfc..11ada740dd5 100644 --- a/internal/runtime/logging/options.go +++ b/internal/runtime/logging/options.go @@ -51,7 +51,7 @@ func defaultDestination() LogDestination { return LogDestinationStderr } -// defaultRateLimitingOptions returns the default rate limiting configuration. +// defaultRateLimitingOptions returns the default rate-limiting configuration. func defaultRateLimitingOptions() RateLimitingOptions { return RateLimitingOptions{Enabled: true, Tick: time.Second, Threshold: 10, Rate: 0, MaxSignatures: 1000} } @@ -168,8 +168,9 @@ func (ll *Format) UnmarshalText(text []byte) error { return nil } -// RateLimitingOptions configures per-(component, message) log rate limiting, -// backed by github.com/samber/slog-sampling. Enabled by default. +// RateLimitingOptions configures log rate limiting per component and +// message. It is backed by github.com/samber/slog-sampling and is enabled +// by default. type RateLimitingOptions struct { Enabled bool `alloy:"enabled,attr,optional"` Tick time.Duration `alloy:"tick,attr,optional"` diff --git a/internal/runtime/logging/rl_bench_test.go b/internal/runtime/logging/rl_bench_test.go index 218465322b2..84ff476342a 100644 --- a/internal/runtime/logging/rl_bench_test.go +++ b/internal/runtime/logging/rl_bench_test.go @@ -9,10 +9,10 @@ import ( "github.com/prometheus/client_golang/prometheus" ) -// newRLBenchLogger builds a real *Logger writing to io.Discard, configured -// with the given RateLimitingOptions, and wires a fresh metrics registry so -// the drop path exercises the alloy_logging_suppressed_lines_total counter -// (matching production wiring). +// newRLBenchLogger builds a real *Logger that writes to io.Discard, using +// the given RateLimitingOptions. It sets up a fresh metrics registry, so the +// drop path exercises the alloy_logging_suppressed_lines_total counter, the +// same as in production. func newRLBenchLogger(b *testing.B, rl RateLimitingOptions) *Logger { b.Helper() l, err := New(io.Discard, Options{ @@ -40,9 +40,9 @@ func BenchmarkRL_Disabled(b *testing.B) { } } -// BenchmarkRL_AdmitHot measures the steady-state admit path: threshold is -// effectively unbounded, so every call is admitted (matcher key build + -// counter Inc + terminal write). +// BenchmarkRL_AdmitHot measures the steady-state admit path. The threshold +// is effectively unbounded, so every call is admitted: build the matcher +// key, increase the counter, and write to the terminal. func BenchmarkRL_AdmitHot(b *testing.B) { l := newRLBenchLogger(b, RateLimitingOptions{ Enabled: true, @@ -60,9 +60,9 @@ func BenchmarkRL_AdmitHot(b *testing.B) { } } -// BenchmarkRL_DropHot measures the drop path: after the first call, every -// identical call is dropped (matcher + counter + OnDropped metric, no -// terminal write). +// BenchmarkRL_DropHot measures the drop path. After the first call, every +// identical call is dropped: matcher, counter, and OnDropped metric, but no +// terminal write. func BenchmarkRL_DropHot(b *testing.B) { l := newRLBenchLogger(b, RateLimitingOptions{ Enabled: true, diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index 515fb09a7c7..ac354e47bdd 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -12,9 +12,9 @@ import ( type componentInfo struct{ id, path string } -// sniffComponent inspects the attrs of a log record for component/controller -// identifying attributes and merges them onto base, returning the result. -// component_id wins over controller_id; component_path is captured verbatim. +// sniffComponent reads component_id, controller_id, and component_path from +// attrs and merges them onto base. It returns the result. +// If component_id is set, it wins over controller_id. func sniffComponent(base componentInfo, attrs []slog.Attr) componentInfo { c := base for _, a := range attrs { @@ -34,35 +34,34 @@ func sniffComponent(base componentInfo, attrs []slog.Attr) componentInfo { type ctxKey struct{} -// withComponent stores componentInfo on ctx so that a downstream Matcher can -// read it back without threading it through every log call site. +// withComponent stores c in ctx. A Matcher can read it back later. This +// avoids passing c through every log call site. func withComponent(ctx context.Context, c componentInfo) context.Context { return context.WithValue(ctx, ctxKey{}, c) } -// componentFromCtx returns the componentInfo previously stored by -// withComponent, or the zero value if none was stored. +// componentFromCtx returns the componentInfo stored by withComponent. It +// returns the zero value if none was stored. func componentFromCtx(ctx context.Context) componentInfo { c, _ := ctx.Value(ctxKey{}).(componentInfo) return c } -// compMatcher is the slog-sampling Matcher used to key the rate limiter's -// per-signature counters. Two records are considered the same "signature" -// (and thus share a rate-limit budget) when they share the same component -// path, component id, level, and message. +// compMatcher is the slog-sampling Matcher used to build the rate limiter's +// signature key. Two records share one signature, and so share one +// rate-limit budget, when they have the same component path, component ID, +// level, and message. // -// component_path alone is not enough: it identifies the parent/module path -// (e.g. "/" for every top-level component), so distinct top-level components -// emitting the same message at the same level would otherwise collapse onto -// one signature and cross-suppress each other. component_id disambiguates -// them. +// component_path alone is not enough. It is the parent path (for example, +// "/" for every top-level component), so many components share it. Without +// component_id, different top-level components that log the same message at +// the same level would share one signature and suppress each other. func compMatcher(ctx context.Context, r *slog.Record) string { c := componentFromCtx(ctx) return c.path + "\x00" + c.id + "\x00" + r.Level.String() + "\x00" + r.Message } -// levelString maps a slog.Level to the lowercase level label used on the +// levelString converts a slog.Level to the lowercase label used in the // suppressed-lines metric. func levelString(l slog.Level) string { switch { @@ -77,17 +76,16 @@ func levelString(l slog.Level) string { } } -// rateLimitMetrics tracks how many log lines the rate limiter has dropped, -// broken down by level and component. A nil *rateLimitMetrics is valid and -// its methods are no-ops, so callers need not special-case a missing -// registerer. +// rateLimitMetrics counts log lines dropped by the rate limiter, by level +// and component. A nil *rateLimitMetrics is valid: its methods do nothing. +// Callers do not need to check for a missing registerer. type rateLimitMetrics struct { suppressed *prometheus.CounterVec } // newRateLimitMetrics registers the alloy_logging_suppressed_lines_total -// counter vector against reg. It returns nil if reg is nil, so that callers -// who don't want metrics (e.g. tests) can pass a nil registerer safely. +// counter vector on reg. It returns nil if reg is nil, so callers that do +// not want metrics, such as tests, can safely pass a nil registerer. func newRateLimitMetrics(reg prometheus.Registerer) *rateLimitMetrics { if reg == nil { return nil @@ -106,7 +104,7 @@ func newRateLimitMetrics(reg prometheus.Registerer) *rateLimitMetrics { return &rateLimitMetrics{suppressed: cv} } -// onDropped is the slog-sampling OnDropped hook: it increments the +// onDropped is the OnDropped hook for slog-sampling. It increments the // suppressed-lines counter for the record's level and component. func (m *rateLimitMetrics) onDropped(ctx context.Context, r slog.Record) { if m == nil { @@ -115,11 +113,11 @@ func (m *rateLimitMetrics) onDropped(ctx context.Context, r slog.Record) { m.suppressed.WithLabelValues(levelString(r.Level), componentFromCtx(ctx).id).Inc() } -// mustRegisterOrReturnExisting registers c against reg. If c is already -// registered (e.g. because multiple Logger instances share a registerer), -// it returns the previously registered collector instead of panicking. -// This is a local copy rather than a dependency on internal/util, which -// would create an import cycle. +// mustRegisterOrReturnExisting registers c on reg. If c is already +// registered, for example because multiple Logger instances share one +// registerer, it returns the existing collector instead of a panic. +// This is a local copy rather than a call to internal/util, which would +// create an import cycle. func mustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collector) prometheus.Collector { if err := reg.Register(c); err != nil { if are, ok := err.(prometheus.AlreadyRegisteredError); ok { @@ -130,8 +128,8 @@ func mustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collec return nil } -// buildRoot returns the sampling-wrapped terminal handler when rate limiting -// is enabled, else it returns terminal unchanged. +// buildRoot wraps terminal with sampling when rate limiting is enabled. +// Otherwise it returns terminal unchanged. func buildRoot(o RateLimitingOptions, terminal slog.Handler, m *rateLimitMetrics) slog.Handler { if !o.Enabled { return terminal @@ -148,61 +146,61 @@ func buildRoot(o RateLimitingOptions, terminal slog.Handler, m *rateLimitMetrics return opt.NewMiddleware()(terminal) } -// replayOp captures a single WithAttrs or WithGroup call so that it can be -// replayed onto a freshly (re-)derived terminal handler. Exactly one of -// attrs or group is set. +// replayOp records one WithAttrs or WithGroup call, so it can be replayed +// later on a new terminal handler. Only one of attrs or group is set. type replayOp struct { attrs []slog.Attr group string } -// versionedHandler pairs the current sampling-wrapped root handler with a -// version number that's bumped whenever rate-limiting configuration changes -// (see Task 4). samplingInjector uses the version to know when its cached -// derived handler is stale and must be re-derived. +// versionedHandler pairs the current root handler with a version number. +// Update increases the version each time the rate-limiting config changes. +// samplingInjector compares versions to know when its cached handler is +// stale and must be rebuilt. type versionedHandler struct { version uint64 h slog.Handler } -// cachedHandler is a samplingInjector's memoized replay of its ops onto a -// particular version of the root handler. +// cachedHandler is a samplingInjector's saved replay of its ops onto one +// version of the root handler. type cachedHandler struct { version uint64 h slog.Handler } -// samplingInjector is a slog.Handler that sits between component loggers and -// the shared, possibly rate-limited, root handler. It: +// samplingInjector is a slog.Handler between component loggers and the +// shared root handler, which may be rate-limited. It does three things: // -// - Tracks component identity (comp) sniffed from WithAttrs calls, so the -// rate limiter's Matcher can key on component path via the context. -// - Records every WithAttrs/WithGroup call as a replayOp, so that when the -// root handler is swapped out (e.g. rate-limiting config changes) or -// bypassed (empty-message records), those calls can be replayed onto the -// new/bare terminal handler to reproduce the same rendering. -// - Bypasses the rate limiter entirely for empty-message records, which -// would otherwise all collapse onto the same signature. +// - It tracks component identity (comp) read from WithAttrs calls. The +// rate limiter's Matcher reads comp from the context to key by +// component. +// - It records every WithAttrs/WithGroup call as a replayOp. When the root +// handler changes (for example, a rate-limiting config change) or is +// bypassed (an empty-message record), it replays these calls on the new +// or bare terminal handler. This keeps the rendered output the same. +// - It bypasses the rate limiter for empty-message records. Without this, +// all empty-message records would share one signature. type samplingInjector struct { comp componentInfo ops []replayOp holder *atomic.Pointer[versionedHandler] - bare slog.Handler // root terminal (no per-component attrs), for empty-message bypass + bare slog.Handler // bare terminal handler (no per-component attrs), used to bypass sampling for empty-message records - // bgCtx is context.Background() with comp already injected via - // withComponent. It's precomputed per injector (rather than on every - // Handle call) because slog.Logger.Info/Warn/Error always pass - // context.Background(), making this the overwhelmingly common case on - // the admit path; see Handle. + // bgCtx is context.Background() with comp already added by + // withComponent. It is computed once per injector, not on every Handle + // call, because slog.Logger.Info/Warn/Error always pass + // context.Background(). This is by far the most common case on the + // admit path; see Handle. bgCtx context.Context cache atomic.Pointer[cachedHandler] bareCache atomic.Pointer[slog.Handler] } -// newSamplingInjector creates a samplingInjector rooted at holder (the -// current, possibly sampling-wrapped, root handler) with bare as the +// newSamplingInjector creates a samplingInjector. holder points to the +// current root handler, which may be wrapped for sampling. bare is the // terminal handler used to bypass sampling for empty-message records. func newSamplingInjector(holder *atomic.Pointer[versionedHandler], bare slog.Handler) *samplingInjector { s := &samplingInjector{holder: holder, bare: bare} @@ -210,9 +208,8 @@ func newSamplingInjector(holder *atomic.Pointer[versionedHandler], bare slog.Han return s } -// replay re-applies a recorded sequence of WithAttrs/WithGroup calls onto h, -// in order, reproducing the derived handler that would have resulted from -// making those calls directly against h. +// replay applies a recorded sequence of WithAttrs/WithGroup calls to h, in +// order. The result is the same handler as calling them directly on h. func replay(h slog.Handler, ops []replayOp) slog.Handler { for _, op := range ops { if op.group != "" { @@ -224,23 +221,23 @@ func replay(h slog.Handler, ops []replayOp) slog.Handler { return h } -// clone returns a new samplingInjector sharing this injector's holder and -// bare terminal, with an independent copy of ops and freshly reset caches -// (since a fresh ops slice means any previously cached replay is stale). +// clone returns a new samplingInjector. It shares this injector's holder and +// bare terminal, but gets its own copy of ops and fresh, empty caches: a new +// ops slice means any old cached replay is stale. func (s *samplingInjector) clone() *samplingInjector { - // New injector shares holder/bare; caches reset (ops differ). comp is - // unchanged by clone itself (WithAttrs mutates it on the returned - // injector below), so bgCtx carries over from the parent unchanged too. + // The new injector shares holder and bare, and starts with empty caches + // because ops will differ. clone itself does not change comp (WithAttrs + // changes it on the returned injector below), so bgCtx also carries over + // unchanged from the parent. ns := &samplingInjector{comp: s.comp, holder: s.holder, bare: s.bare, bgCtx: s.bgCtx} ns.ops = make([]replayOp, len(s.ops), len(s.ops)+1) copy(ns.ops, s.ops) return ns } -// WithAttrs returns a new handler with attrs bound. It also sniffs attrs for -// component identity so the rate limiter can key by component, and records -// the call as a replayOp so it still reaches the terminal handler for -// rendering. +// WithAttrs returns a new handler with attrs bound. It also reads attrs for +// component identity, so the rate limiter can key by component, and records +// the call as a replayOp, so the terminal handler still renders it. func (s *samplingInjector) WithAttrs(attrs []slog.Attr) slog.Handler { ns := s.clone() ns.comp = sniffComponent(s.comp, attrs) @@ -249,9 +246,8 @@ func (s *samplingInjector) WithAttrs(attrs []slog.Attr) slog.Handler { return ns } -// WithGroup returns a new handler with name pushed as an open group, -// recording the call as a replayOp so it still reaches the terminal handler -// for rendering. +// WithGroup returns a new handler with name added as an open group. It +// records the call as a replayOp, so the terminal handler still renders it. func (s *samplingInjector) WithGroup(name string) slog.Handler { if name == "" { return s @@ -261,25 +257,25 @@ func (s *samplingInjector) WithGroup(name string) slog.Handler { return ns } -// Enabled delegates to the bare terminal handler rather than the (possibly -// sampling-wrapped) root: sampling only ever drops in Handle, never changes -// level-enabled-ness, so routing here avoids paying the sampling middleware's -// per-call Enabled cost on every slog.Info/Warn/Error call site. s.bare's -// leveler is the shared LevelVar mutated by Update, and level-gating is -// component-independent, so this is correct for every derived injector, not -// just the root one. +// Enabled calls the bare terminal handler, not the root handler, which may +// be wrapped for sampling. Sampling only drops records in Handle; it never +// changes whether a level is enabled. Calling the bare handler here skips +// the sampling wrapper's per-call cost on every slog.Info/Warn/Error call. +// s.bare uses the shared LevelVar that Update changes, and level gating does +// not depend on component, so this is correct for every derived injector, +// not just the root one. func (s *samplingInjector) Enabled(ctx context.Context, l slog.Level) bool { return s.bare.Enabled(ctx, l) } -// Handle routes empty-message records directly to the bare terminal handler -// (bypassing the rate limiter, since blank-message records from different -// call sites would otherwise share a signature), and all other records -// through the current, possibly rate-limited, root handler with the -// component identity injected into ctx for the Matcher to read. +// Handle sends empty-message records straight to the bare terminal handler. +// This skips the rate limiter, because blank-message records from different +// call sites would otherwise share one signature. All other records go +// through the current root handler, which may be rate-limited. Handle adds +// the component identity to ctx so the Matcher can read it. func (s *samplingInjector) Handle(ctx context.Context, r slog.Record) error { if r.Message == "" { - // Bypass sampler: unrelated no-msg events must not collapse into one signature. + // Skip the sampler: unrelated no-message records must not share one signature. bh := s.bareCache.Load() if bh == nil { h := replay(s.bare, s.ops) @@ -294,11 +290,11 @@ func (s *samplingInjector) Handle(ctx context.Context, r slog.Record) error { c = &cachedHandler{version: vh.version, h: replay(vh.h, s.ops)} s.cache.Store(c) } - // slog.Logger.Info/Warn/Error always pass context.Background(); reuse - // the precomputed component ctx for that common case instead of paying - // context.WithValue's allocation on every admitted line. Any other ctx - // (e.g. via InfoContext) falls back to injecting fresh, since it may - // carry values or a Done channel we must not clobber. + // slog.Logger.Info/Warn/Error always pass context.Background(). Reuse + // the precomputed component ctx for this common case, instead of an + // allocation from context.WithValue on every admitted line. For any + // other ctx, for example from InfoContext, inject fresh instead: it + // may carry values or a Done channel that must not be lost. var cctx context.Context if ctx == context.Background() { cctx = s.bgCtx diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go index 00c1fbecf60..9616afd99b7 100644 --- a/internal/runtime/logging/sampling_test.go +++ b/internal/runtime/logging/sampling_test.go @@ -16,8 +16,8 @@ import ( ) // TestSpikeThresholdAdmitsThenDrops confirms the Threshold middleware wraps a -// terminal handler, keys via our Matcher, and admits `Threshold` per tick then -// drops (rate=0). This validates the exact library wiring the design relies on. +// terminal handler, keys records with our Matcher, and admits `Threshold` +// records per tick, then drops the rest (rate=0). func TestSpikeThresholdAdmitsThenDrops(t *testing.T) { var buf bytes.Buffer terminal := slog.NewTextHandler(&buf, nil) @@ -113,10 +113,10 @@ func TestInjectorRendersAttrsAndGroups(t *testing.T) { func TestInjectorEmptyMessageBypassesSampler(t *testing.T) { var termBuf bytes.Buffer term := slog.NewTextHandler(&termBuf, nil) - // A root that drops everything, to prove empty-message goes to `bare` (term) not root. - // AbsoluteSamplingOption panics when Max == 0, so we build the drop-all root - // with ThresholdSamplingOption{Threshold: 0, Rate: 0} instead, which admits - // nothing (confirmed against slog-sampling v1.6.0 in Task 2's spike). + // A root that drops everything, to prove empty-message records go to + // `bare` (term), not root. AbsoluteSamplingOption panics when Max == 0, + // so we build the drop-all root with ThresholdSamplingOption{Threshold: + // 0, Rate: 0} instead, which admits nothing. dropAll := slogsampling.ThresholdSamplingOption{ Tick: time.Hour, Threshold: 0, @@ -131,12 +131,11 @@ func TestInjectorEmptyMessageBypassesSampler(t *testing.T) { require.Contains(t, termBuf.String(), "k=v") // empty-msg reached bare terminal } -// TestInjectorEnabledMatchesTerminalLevel guards optimization A: Enabled must -// delegate to the bare terminal handler (whose leveler reflects the current, -// live-updatable level), not to the sampling-wrapped root. Here root reports -// everything enabled (LevelDebug) while bare is gated at Info, so if Enabled -// mistakenly consulted root instead of bare, the LevelDebug assertion below -// would fail. +// TestInjectorEnabledMatchesTerminalLevel checks that Enabled calls the bare +// terminal handler, whose leveler reflects the current, live-updatable +// level, not the sampling-wrapped root. Root reports everything enabled +// (LevelDebug), while bare is gated at Info. If Enabled called root instead +// of bare, the LevelDebug assertion below would fail. func TestInjectorEnabledMatchesTerminalLevel(t *testing.T) { root := slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug}) bare := slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelInfo}) From fd655d394fb0dfcbda422743f3bffd33d598fb69 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 11:06:06 -0400 Subject: [PATCH 12/20] =?UTF-8?q?fix(logging):=20address=20review=20?= =?UTF-8?q?=E2=80=94=20drop=20rlVersion,=20rename=20InitRateLimitMetrics,?= =?UTF-8?q?=20extract=20metricsutil,=20dedupe=20test,=20docs?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-Authored-By: Claude Code --- .../reference/config-blocks/logging.md | 6 +++--- .../runtime/internal/controller/loader.go | 6 +++--- .../controller/node_config_logging.go | 4 ++-- internal/runtime/logging/logger.go | 21 ++++++++++--------- internal/runtime/logging/logger_rl_test.go | 15 ------------- internal/runtime/logging/rl_bench_test.go | 2 +- internal/runtime/logging/sampling.go | 19 +++-------------- internal/util/metrics.go | 13 ------------ internal/util/metricsutil/metricsutil.go | 21 +++++++++++++++++++ 9 files changed, 44 insertions(+), 63 deletions(-) create mode 100644 internal/util/metricsutil/metricsutil.go diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index 1e2777c8852..30d26e9b6b5 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -80,15 +80,15 @@ The `rate_limiting` block enables per-message rate limiting and sampling of repe | Name | Type | Description | Default | Required | |------|------|-------------|---------|----------| | `enabled` | `bool` | Enable per-message rate limiting. | `true` | no | +| `max_signatures` | `number` | Distinct signatures tracked; least-recently-used is evicted when full. | `1000` | no | +| `rate` | `number` | Fraction (0–1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | | `tick` | `duration` | Sampling window. | `"1s"` | no | | `threshold` | `number` | Identical lines admitted per (component, level, message) per tick before sampling. | `10` | no | -| `rate` | `number` | Fraction (0–1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | -| `max_signatures` | `number` | Distinct signatures tracked; least-recently-used is evicted when full. | `1000` | no | Rate limiting keys on the component, the log level, and the log message text (not attributes/fields). Only identical repeated lines from the same component at the same level are throttled; distinct components/messages are independent (LRU-bounded by `max_signatures`). -Because keying is on the message text, log lines that share a constant message but differ only in attributes are treated as the same signature and throttled together. +Log lines that share a constant message but differ only in attributes are treated as the same signature and throttled together. Log lines with an empty message, such as some `go-kit`-style logs emitted without a `msg` or `message` field, bypass rate limiting entirely and are always written. diff --git a/internal/runtime/internal/controller/loader.go b/internal/runtime/internal/controller/loader.go index a118408832f..8c937e7f14a 100644 --- a/internal/runtime/internal/controller/loader.go +++ b/internal/runtime/internal/controller/loader.go @@ -29,8 +29,8 @@ import ( "github.com/grafana/alloy/internal/runtime/internal/worker" "github.com/grafana/alloy/internal/runtime/tracing" "github.com/grafana/alloy/internal/service" - "github.com/grafana/alloy/internal/util" astutil "github.com/grafana/alloy/internal/util/ast" + "github.com/grafana/alloy/internal/util/metricsutil" "github.com/grafana/alloy/syntax/ast" "github.com/grafana/alloy/syntax/diag" "github.com/grafana/alloy/syntax/vm" @@ -120,12 +120,12 @@ func NewLoader(opts LoaderOptions) (*Loader, error) { // These metrics already being registered indicates there's already a loader which exists for this controller. // Creating duplicate loaders should only happen in error states where we should not proceed further. One know // case of this is when remotecfg loads an invalid config and attempts to reload the prior config. - existing := util.MustRegisterOrReturnExisting(globals.Registerer, l.cc) + existing := metricsutil.MustRegisterOrReturnExisting(globals.Registerer, l.cc) if existing != nil { return nil, fmt.Errorf("a loader exists already exists for %q", globals.ControllerID) } - existing = util.MustRegisterOrReturnExisting(globals.Registerer, l.cm) + existing = metricsutil.MustRegisterOrReturnExisting(globals.Registerer, l.cm) if existing != nil { return nil, fmt.Errorf("a loader exists already exists for %q", globals.ControllerID) } diff --git a/internal/runtime/internal/controller/node_config_logging.go b/internal/runtime/internal/controller/node_config_logging.go index 3771e371cfa..bfcd4779a03 100644 --- a/internal/runtime/internal/controller/node_config_logging.go +++ b/internal/runtime/internal/controller/node_config_logging.go @@ -25,7 +25,7 @@ type LoggingConfigNode struct { // NewLoggingConfigNode creates a new LoggingConfigNode from an initial ast.BlockStmt. // The underlying config isn't applied until Evaluate is called. func NewLoggingConfigNode(block *ast.BlockStmt, globals ComponentGlobals) *LoggingConfigNode { - globals.Logger.SetRateLimitMetrics(globals.Registerer) + globals.Logger.InitRateLimitMetrics(globals.Registerer) return &LoggingConfigNode{ nodeID: BlockComponentID(block).String(), componentName: block.GetBlockName(), @@ -39,7 +39,7 @@ func NewLoggingConfigNode(block *ast.BlockStmt, globals ComponentGlobals) *Loggi // NewDefaultLoggingConfigNode creates a new LoggingConfigNode with nil block and eval. // This will force evaluate to use the default logging options for this node. func NewDefaultLoggingConfigNode(globals ComponentGlobals) *LoggingConfigNode { - globals.Logger.SetRateLimitMetrics(globals.Registerer) + globals.Logger.InitRateLimitMetrics(globals.Registerer) return &LoggingConfigNode{ nodeID: loggingBlockID, componentName: loggingBlockID, diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index d2badf0f9ea..58dcc3f6d19 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -42,17 +42,18 @@ type Logger struct { // rlHolder holds the current root handler used by the samplingInjector // in the deferred handler tree. This handler may be wrapped for // rate-limit sampling. It starts as the bare terminal handler (rate - // limiting off), and Update swaps it atomically. rlVersion increases on - // each swap, so samplingInjector instances know to rebuild their cached, - // per-component replay of the root handler. + // limiting off), and Update swaps it atomically. The stored version + // increases on each swap, so samplingInjector instances know to rebuild + // their cached, per-component replay of the root handler. rlHolder is + // only ever stored while rlMut is held, so reading its version and + // storing version+1 is race-free even though the load itself is atomic. rlHolder atomic.Pointer[versionedHandler] - rlVersion atomic.Uint64 rlMetrics *rateLimitMetrics // rlMut guards the rate-limiting block in Update: the rlApplied check, - // buildRoot call, rlVersion increase, and rlHolder store must happen as + // buildRoot call, version increase, and rlHolder store must happen as // one unit. rlMut also guards rlMetrics, which Update reads without any - // other synchronization against SetRateLimitMetrics. + // other synchronization against InitRateLimitMetrics. rlMut sync.Mutex // rlApplied is the RateLimitingOptions last used to build the current // rlHolder root. nil means no Update has applied rate limiting yet. @@ -165,8 +166,8 @@ func (l *Logger) Update(o Options) error { l.rlMut.Lock() if l.rlApplied == nil || *l.rlApplied != rlOpts { root := buildRoot(rlOpts, l.handler, l.rlMetrics) - v := l.rlVersion.Add(1) - l.rlHolder.Store(&versionedHandler{version: v, h: root}) + next := l.rlHolder.Load().version + 1 + l.rlHolder.Store(&versionedHandler{version: next, h: root}) applied := rlOpts l.rlApplied = &applied } @@ -204,8 +205,8 @@ func (l *Logger) flushBuffer() { } } -// SetRateLimitMetrics sets up the suppressed-lines metric. Call this once, before the logger is shared. -func (l *Logger) SetRateLimitMetrics(reg prometheus.Registerer) { +// InitRateLimitMetrics sets up the suppressed-lines metric. Call this once, before the logger is shared. +func (l *Logger) InitRateLimitMetrics(reg prometheus.Registerer) { l.rlMut.Lock() defer l.rlMut.Unlock() if l.rlMetrics == nil { diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go index df5b1d79c6c..1233517af75 100644 --- a/internal/runtime/logging/logger_rl_test.go +++ b/internal/runtime/logging/logger_rl_test.go @@ -210,18 +210,3 @@ func TestConcurrentUpdatesNoRace(t *testing.T) { l.Slog().Info("post-concurrent-update") require.Contains(t, buf.String(), "post-concurrent-update") } - -func TestLoggerLiveRetune(t *testing.T) { - defer goleak.VerifyNone(t) - var buf bytes.Buffer - l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, - RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 100, Rate: 0, MaxSignatures: 100}}) - require.NoError(t, err) - log := l.Slog() // logger captured BEFORE reload - require.NoError(t, l.Update(Options{Level: LevelInfo, Format: FormatLogfmt, - RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}})) - for i := 0; i < 5; i++ { - log.Info("retuned") - } - require.Equal(t, 1, strings.Count(buf.String(), "retuned")) // new threshold applied live to pre-existing logger -} diff --git a/internal/runtime/logging/rl_bench_test.go b/internal/runtime/logging/rl_bench_test.go index 84ff476342a..b404c425662 100644 --- a/internal/runtime/logging/rl_bench_test.go +++ b/internal/runtime/logging/rl_bench_test.go @@ -23,7 +23,7 @@ func newRLBenchLogger(b *testing.B, rl RateLimitingOptions) *Logger { if err != nil { b.Fatalf("failed to create logger: %v", err) } - l.SetRateLimitMetrics(prometheus.NewRegistry()) + l.InitRateLimitMetrics(prometheus.NewRegistry()) return l } diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index ac354e47bdd..fe8c0f4393c 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -8,6 +8,8 @@ import ( "github.com/prometheus/client_golang/prometheus" slogsampling "github.com/samber/slog-sampling" "github.com/samber/slog-sampling/buffer" + + "github.com/grafana/alloy/internal/util/metricsutil" ) type componentInfo struct{ id, path string } @@ -94,7 +96,7 @@ func newRateLimitMetrics(reg prometheus.Registerer) *rateLimitMetrics { Name: "alloy_logging_suppressed_lines_total", Help: "Total log lines dropped by the logger's rate limiter, by level and component.", }, []string{"level", "component_id"}) - if existing := mustRegisterOrReturnExisting(reg, cv); existing != nil { + if existing := metricsutil.MustRegisterOrReturnExisting(reg, cv); existing != nil { cvExisting, ok := existing.(*prometheus.CounterVec) if !ok { return nil @@ -113,21 +115,6 @@ func (m *rateLimitMetrics) onDropped(ctx context.Context, r slog.Record) { m.suppressed.WithLabelValues(levelString(r.Level), componentFromCtx(ctx).id).Inc() } -// mustRegisterOrReturnExisting registers c on reg. If c is already -// registered, for example because multiple Logger instances share one -// registerer, it returns the existing collector instead of a panic. -// This is a local copy rather than a call to internal/util, which would -// create an import cycle. -func mustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collector) prometheus.Collector { - if err := reg.Register(c); err != nil { - if are, ok := err.(prometheus.AlreadyRegisteredError); ok { - return are.ExistingCollector - } - panic(err) - } - return nil -} - // buildRoot wraps terminal with sampling when rate limiting is enabled. // Otherwise it returns terminal unchanged. func buildRoot(o RateLimitingOptions, terminal slog.Handler, m *rateLimitMetrics) slog.Handler { diff --git a/internal/util/metrics.go b/internal/util/metrics.go index 653f97c954a..850b535fe8f 100644 --- a/internal/util/metrics.go +++ b/internal/util/metrics.go @@ -14,16 +14,3 @@ func MustRegisterOrGet(reg prometheus.Registerer, c prometheus.Collector) promet } return c } - -// MustRegisterOrReturnExisting will attempt to register the supplied collector into the register. If it's already -// registered, it will return that one otherwise nil. -// In case that the register procedure fails with something other than already registered, this will panic. -func MustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collector) prometheus.Collector { - if err := reg.Register(c); err != nil { - if are, ok := err.(prometheus.AlreadyRegisteredError); ok { - return are.ExistingCollector - } - panic(err) - } - return nil -} diff --git a/internal/util/metricsutil/metricsutil.go b/internal/util/metricsutil/metricsutil.go new file mode 100644 index 00000000000..fd392f391a4 --- /dev/null +++ b/internal/util/metricsutil/metricsutil.go @@ -0,0 +1,21 @@ +// Package metricsutil holds small Prometheus helpers with no dependencies +// beyond the Prometheus client. Packages that cannot import internal/util, +// for example because internal/util already imports them, can still use +// these helpers by depending on this leaf package instead. +package metricsutil + +import "github.com/prometheus/client_golang/prometheus" + +// MustRegisterOrReturnExisting registers c on reg. If c is already +// registered, for example because multiple callers share one registerer, it +// returns the existing collector instead of panicking. +// If registration fails for any other reason, it panics. +func MustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collector) prometheus.Collector { + if err := reg.Register(c); err != nil { + if are, ok := err.(prometheus.AlreadyRegisteredError); ok { + return are.ExistingCollector + } + panic(err) + } + return nil +} From ac70e41c3489dbaaf4f833fdaa493511928c8e93 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 11:08:15 -0400 Subject: [PATCH 13/20] docs(logging): fix stale rlVersion reference in comment Co-Authored-By: Claude Opus 4.8 (1M context) --- internal/runtime/logging/logger.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 58dcc3f6d19..64f37be0375 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -57,8 +57,8 @@ type Logger struct { rlMut sync.Mutex // rlApplied is the RateLimitingOptions last used to build the current // rlHolder root. nil means no Update has applied rate limiting yet. - // Update rebuilds the sampler, and increases rlVersion, only when the - // new options differ from rlApplied. This way, a config reload that + // Update rebuilds the sampler, and bumps the stored version, only when + // the new options differ from rlApplied. This way, a config reload that // does not change rate limiting does not reset rate-limit budgets that // are already in use. rlApplied *RateLimitingOptions From ed65cdd4562a0ba44fe04f27730b081d8fded017 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 11:18:10 -0400 Subject: [PATCH 14/20] docs(logging): fix rate_limiting arg table alphabetical order (threshold before tick) Co-Authored-By: Claude Opus 4.8 (1M context) --- docs/sources/reference/config-blocks/logging.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index 30d26e9b6b5..b722ef88a46 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -82,8 +82,8 @@ The `rate_limiting` block enables per-message rate limiting and sampling of repe | `enabled` | `bool` | Enable per-message rate limiting. | `true` | no | | `max_signatures` | `number` | Distinct signatures tracked; least-recently-used is evicted when full. | `1000` | no | | `rate` | `number` | Fraction (0–1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | -| `tick` | `duration` | Sampling window. | `"1s"` | no | | `threshold` | `number` | Identical lines admitted per (component, level, message) per tick before sampling. | `10` | no | +| `tick` | `duration` | Sampling window. | `"1s"` | no | Rate limiting keys on the component, the log level, and the log message text (not attributes/fields). Only identical repeated lines from the same component at the same level are throttled; distinct components/messages are independent (LRU-bounded by `max_signatures`). From f2ade663ef5f1521bf7647a3f11b0a595a3892a1 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 11:38:33 -0400 Subject: [PATCH 15/20] docs(logging): trim rlHolder comment per review Co-Authored-By: Claude Opus 4.8 (1M context) --- internal/runtime/logging/logger.go | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 64f37be0375..83d930b844d 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -44,9 +44,7 @@ type Logger struct { // rate-limit sampling. It starts as the bare terminal handler (rate // limiting off), and Update swaps it atomically. The stored version // increases on each swap, so samplingInjector instances know to rebuild - // their cached, per-component replay of the root handler. rlHolder is - // only ever stored while rlMut is held, so reading its version and - // storing version+1 is race-free even though the load itself is atomic. + // their cached, per-component replay of the root handler. rlHolder atomic.Pointer[versionedHandler] rlMetrics *rateLimitMetrics From 82bef6910ac5776ee818bbe06521a0d3aac832e6 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 11:51:39 -0400 Subject: [PATCH 16/20] =?UTF-8?q?refactor(logging):=20simplify=20rate=20li?= =?UTF-8?q?miter=20=E2=80=94=20merge=20handler-tag=20type,=20value=20rlApp?= =?UTF-8?q?lied,=20reuse=20root=20injector?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- internal/runtime/logging/deferred_handler.go | 12 ++++---- internal/runtime/logging/logger.go | 29 ++++++++++++------ internal/runtime/logging/sampling.go | 31 ++++++++++---------- 3 files changed, 43 insertions(+), 29 deletions(-) diff --git a/internal/runtime/logging/deferred_handler.go b/internal/runtime/logging/deferred_handler.go index a85e2d09630..a1e9f7ec24e 100644 --- a/internal/runtime/logging/deferred_handler.go +++ b/internal/runtime/logging/deferred_handler.go @@ -88,12 +88,14 @@ func (d *deferredSlogHandler) buildHandlers(parent slog.Handler) { d.mut.Lock() defer d.mut.Unlock() - // The root node has no attrs or groups. Route it through the - // samplingInjector, so the shared root handler (l.rlHolder), which may - // be rate-limited, sits between component loggers and the terminal - // handler. + // The root node has no attrs or groups. Route it through the Logger's + // persistent rootInjector, so the shared root handler (l.rlHolder), + // which may be rate-limited, sits between component loggers and the + // terminal handler. Reusing rootInjector, instead of building a new + // samplingInjector on every Update, avoids an allocation on config + // reloads that do not touch rate limiting. if parent == nil { - d.handle = newSamplingInjector(&d.l.rlHolder, d.l.handler) + d.handle = d.l.rootInjector } else { if d.group != "" { d.handle = parent.WithGroup(d.group) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 83d930b844d..c26167373d8 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -39,6 +39,14 @@ type Logger struct { handler *handler deferredSlog *deferredSlogHandler // Buffers slog output until config is loaded, then delegates to handler. + // rootInjector is the samplingInjector at the root of the deferred + // handler tree. buildHandlers reuses this single instance on every + // Update, instead of building a fresh one, because the root injector + // needs only rlHolder and handler, both stable for the life of the + // Logger. Config changes reach it through rlHolder's version, not + // through rebuilding the injector itself. + rootInjector *samplingInjector + // rlHolder holds the current root handler used by the samplingInjector // in the deferred handler tree. This handler may be wrapped for // rate-limit sampling. It starts as the bare terminal handler (rate @@ -54,12 +62,14 @@ type Logger struct { // other synchronization against InitRateLimitMetrics. rlMut sync.Mutex // rlApplied is the RateLimitingOptions last used to build the current - // rlHolder root. nil means no Update has applied rate limiting yet. - // Update rebuilds the sampler, and bumps the stored version, only when - // the new options differ from rlApplied. This way, a config reload that - // does not change rate limiting does not reset rate-limit budgets that - // are already in use. - rlApplied *RateLimitingOptions + // rlHolder root. rlAppliedSet is false until the first Update runs; after + // that, rlApplied always holds the last-applied options. Update rebuilds + // the sampler, and bumps the stored version, only when rlAppliedSet is + // false or the new options differ from rlApplied. This way, a config + // reload that does not change rate limiting does not reset rate-limit + // budgets that are already in use. + rlApplied RateLimitingOptions + rlAppliedSet bool } var _ EnabledAware = (*Logger)(nil) @@ -122,6 +132,7 @@ func NewDeferred(w io.Writer) (*Logger, error) { // terminal handler, so logging works as it did before rate limiting // existed, until the first config Update enables it. l.rlHolder.Store(&versionedHandler{version: 0, h: bh}) + l.rootInjector = newSamplingInjector(&l.rlHolder, l.handler) l.deferredSlog = newDeferredHandler(l) return l, nil @@ -162,12 +173,12 @@ func (l *Logger) Update(o Options) error { l.bufferMut.Unlock() l.rlMut.Lock() - if l.rlApplied == nil || *l.rlApplied != rlOpts { + if !l.rlAppliedSet || l.rlApplied != rlOpts { root := buildRoot(rlOpts, l.handler, l.rlMetrics) next := l.rlHolder.Load().version + 1 l.rlHolder.Store(&versionedHandler{version: next, h: root}) - applied := rlOpts - l.rlApplied = &applied + l.rlApplied = rlOpts + l.rlAppliedSet = true } l.rlMut.Unlock() diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index fe8c0f4393c..dc6aea9bf93 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -140,20 +140,22 @@ type replayOp struct { group string } -// versionedHandler pairs the current root handler with a version number. -// Update increases the version each time the rate-limiting config changes. -// samplingInjector compares versions to know when its cached handler is -// stale and must be rebuilt. +// versionedHandler pairs a handler with a version number. Logger's rlHolder +// uses it to hold the current root handler; Update increases the version +// each time the rate-limiting config changes. samplingInjector's cache uses +// the same type to hold its replay of that root handler, keyed by the same +// version, so it can compare versions to know when the replay is stale and +// must be rebuilt. type versionedHandler struct { version uint64 h slog.Handler } -// cachedHandler is a samplingInjector's saved replay of its ops onto one -// version of the root handler. -type cachedHandler struct { - version uint64 - h slog.Handler +// handlerBox wraps a slog.Handler so bareCache can store it in an +// atomic.Pointer. atomic.Pointer needs a concrete type, and slog.Handler is +// an interface, so the box supplies that concrete type. +type handlerBox struct { + h slog.Handler } // samplingInjector is a slog.Handler between component loggers and the @@ -182,8 +184,8 @@ type samplingInjector struct { // admit path; see Handle. bgCtx context.Context - cache atomic.Pointer[cachedHandler] - bareCache atomic.Pointer[slog.Handler] + cache atomic.Pointer[versionedHandler] + bareCache atomic.Pointer[handlerBox] } // newSamplingInjector creates a samplingInjector. holder points to the @@ -265,16 +267,15 @@ func (s *samplingInjector) Handle(ctx context.Context, r slog.Record) error { // Skip the sampler: unrelated no-message records must not share one signature. bh := s.bareCache.Load() if bh == nil { - h := replay(s.bare, s.ops) - bh = &h + bh = &handlerBox{h: replay(s.bare, s.ops)} s.bareCache.Store(bh) } - return (*bh).Handle(ctx, r) + return bh.h.Handle(ctx, r) } vh := s.holder.Load() c := s.cache.Load() if c == nil || c.version != vh.version { - c = &cachedHandler{version: vh.version, h: replay(vh.h, s.ops)} + c = &versionedHandler{version: vh.version, h: replay(vh.h, s.ops)} s.cache.Store(c) } // slog.Logger.Info/Warn/Error always pass context.Background(). Reuse From 30ad419852df0c138971208f5740e61c88e95176 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 12:06:38 -0400 Subject: [PATCH 17/20] refactor(logging): revert rlApplied to nilable pointer per review Co-Authored-By: Claude Opus 4.8 (1M context) --- internal/runtime/logging/logger.go | 19 ++++++++----------- 1 file changed, 8 insertions(+), 11 deletions(-) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index c26167373d8..7a426ed34b6 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -62,14 +62,11 @@ type Logger struct { // other synchronization against InitRateLimitMetrics. rlMut sync.Mutex // rlApplied is the RateLimitingOptions last used to build the current - // rlHolder root. rlAppliedSet is false until the first Update runs; after - // that, rlApplied always holds the last-applied options. Update rebuilds - // the sampler, and bumps the stored version, only when rlAppliedSet is - // false or the new options differ from rlApplied. This way, a config - // reload that does not change rate limiting does not reset rate-limit - // budgets that are already in use. - rlApplied RateLimitingOptions - rlAppliedSet bool + // rlHolder root. It is nil until the first Update runs. Update rebuilds + // the sampler, and bumps the stored version, only when rlApplied is nil + // or the new options differ from it. This way, a config reload that does + // not change rate limiting does not reset rate-limit budgets already in use. + rlApplied *RateLimitingOptions } var _ EnabledAware = (*Logger)(nil) @@ -173,12 +170,12 @@ func (l *Logger) Update(o Options) error { l.bufferMut.Unlock() l.rlMut.Lock() - if !l.rlAppliedSet || l.rlApplied != rlOpts { + if l.rlApplied == nil || *l.rlApplied != rlOpts { root := buildRoot(rlOpts, l.handler, l.rlMetrics) next := l.rlHolder.Load().version + 1 l.rlHolder.Store(&versionedHandler{version: next, h: root}) - l.rlApplied = rlOpts - l.rlAppliedSet = true + applied := rlOpts + l.rlApplied = &applied } l.rlMut.Unlock() From d9b3c8feba9c6a67faeaeee6a362ee61027842d4 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 12:31:30 -0400 Subject: [PATCH 18/20] feat(logging): default rate_limiting tick to 10s to catch sustained repeats Co-Authored-By: Claude Opus 4.8 (1M context) --- docs/sources/reference/config-blocks/logging.md | 2 +- internal/runtime/logging/options.go | 2 +- internal/runtime/logging/options_test.go | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index b722ef88a46..17f1df39a4c 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -83,7 +83,7 @@ The `rate_limiting` block enables per-message rate limiting and sampling of repe | `max_signatures` | `number` | Distinct signatures tracked; least-recently-used is evicted when full. | `1000` | no | | `rate` | `number` | Fraction (0–1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | | `threshold` | `number` | Identical lines admitted per (component, level, message) per tick before sampling. | `10` | no | -| `tick` | `duration` | Sampling window. | `"1s"` | no | +| `tick` | `duration` | Sampling window. | `"10s"` | no | Rate limiting keys on the component, the log level, and the log message text (not attributes/fields). Only identical repeated lines from the same component at the same level are throttled; distinct components/messages are independent (LRU-bounded by `max_signatures`). diff --git a/internal/runtime/logging/options.go b/internal/runtime/logging/options.go index 11ada740dd5..0e900ffce6e 100644 --- a/internal/runtime/logging/options.go +++ b/internal/runtime/logging/options.go @@ -53,7 +53,7 @@ func defaultDestination() LogDestination { // defaultRateLimitingOptions returns the default rate-limiting configuration. func defaultRateLimitingOptions() RateLimitingOptions { - return RateLimitingOptions{Enabled: true, Tick: time.Second, Threshold: 10, Rate: 0, MaxSignatures: 1000} + return RateLimitingOptions{Enabled: true, Tick: 10 * time.Second, Threshold: 10, Rate: 0, MaxSignatures: 1000} } // defaultOptions builds a fresh set of Logger defaults, evaluating the diff --git a/internal/runtime/logging/options_test.go b/internal/runtime/logging/options_test.go index acd73111cfb..f2c1bf8258a 100644 --- a/internal/runtime/logging/options_test.go +++ b/internal/runtime/logging/options_test.go @@ -95,7 +95,7 @@ func TestOptionsDefaultEnablesRateLimiting(t *testing.T) { o.SetToDefault() require.NotNil(t, o.RateLimiting) require.True(t, o.RateLimiting.Enabled) - require.Equal(t, time.Second, o.RateLimiting.Tick) + require.Equal(t, 10*time.Second, o.RateLimiting.Tick) require.Equal(t, uint64(10), o.RateLimiting.Threshold) require.Equal(t, 0.0, o.RateLimiting.Rate) require.Equal(t, 1000, o.RateLimiting.MaxSignatures) From 0a79b30fcca32e53434876f7b93a3d2f7a6bcd04 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 14:21:17 -0400 Subject: [PATCH 19/20] fix(logging): live-publish suppressed metric, key controller_path, reject NaN rate --- internal/runtime/logging/logger.go | 32 ++++++++++++------- internal/runtime/logging/logger_rl_test.go | 37 ++++++++++++++++++++++ internal/runtime/logging/options.go | 2 +- internal/runtime/logging/options_test.go | 2 ++ internal/runtime/logging/rl_bench_test.go | 7 ++-- internal/runtime/logging/sampling.go | 37 ++++++++++++++++------ internal/runtime/logging/sampling_test.go | 32 +++++++++++++++++++ 7 files changed, 124 insertions(+), 25 deletions(-) diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 7a426ed34b6..22a75e74919 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -53,13 +53,20 @@ type Logger struct { // limiting off), and Update swaps it atomically. The stored version // increases on each swap, so samplingInjector instances know to rebuild // their cached, per-component replay of the root handler. - rlHolder atomic.Pointer[versionedHandler] - rlMetrics *rateLimitMetrics - - // rlMut guards the rate-limiting block in Update: the rlApplied check, - // buildRoot call, version increase, and rlHolder store must happen as - // one unit. rlMut also guards rlMetrics, which Update reads without any - // other synchronization against InitRateLimitMetrics. + rlHolder atomic.Pointer[versionedHandler] + // rlMetrics holds the suppressed-lines metric, or nil before + // InitRateLimitMetrics runs. buildRoot's OnDropped closure reads this + // pointer live on every drop, so it is an atomic.Pointer rather than a + // plain field: InitRateLimitMetrics can set it at any time, even after + // an earlier Update already built the root handler, and drops that + // follow will still be counted. + rlMetrics atomic.Pointer[rateLimitMetrics] + + // rlMut guards the rate-limiting block in Update (the rlApplied check, + // buildRoot call, version increase, and rlHolder store, which must + // happen as one unit) and InitRateLimitMetrics's one-time set of + // rlMetrics. Reading rlMetrics is lock-free (atomic); rlMut is not + // needed for that. rlMut sync.Mutex // rlApplied is the RateLimitingOptions last used to build the current // rlHolder root. It is nil until the first Update runs. Update rebuilds @@ -171,7 +178,7 @@ func (l *Logger) Update(o Options) error { l.rlMut.Lock() if l.rlApplied == nil || *l.rlApplied != rlOpts { - root := buildRoot(rlOpts, l.handler, l.rlMetrics) + root := buildRoot(rlOpts, l.handler, &l.rlMetrics) next := l.rlHolder.Load().version + 1 l.rlHolder.Store(&versionedHandler{version: next, h: root}) applied := rlOpts @@ -211,12 +218,15 @@ func (l *Logger) flushBuffer() { } } -// InitRateLimitMetrics sets up the suppressed-lines metric. Call this once, before the logger is shared. +// InitRateLimitMetrics sets up the suppressed-lines metric. Call this once. +// It takes effect right away, including for a logger that already has an +// Update call behind it: buildRoot's OnDropped closure reads rlMetrics live, +// so InitRateLimitMetrics does not need to run before the first Update. func (l *Logger) InitRateLimitMetrics(reg prometheus.Registerer) { l.rlMut.Lock() defer l.rlMut.Unlock() - if l.rlMetrics == nil { - l.rlMetrics = newRateLimitMetrics(reg) + if l.rlMetrics.Load() == nil { + l.rlMetrics.Store(newRateLimitMetrics(reg)) } } diff --git a/internal/runtime/logging/logger_rl_test.go b/internal/runtime/logging/logger_rl_test.go index 1233517af75..ac29648ce98 100644 --- a/internal/runtime/logging/logger_rl_test.go +++ b/internal/runtime/logging/logger_rl_test.go @@ -9,6 +9,7 @@ import ( "testing" "time" + "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/require" "go.uber.org/goleak" ) @@ -182,6 +183,42 @@ func TestUpdateChangedOptionsRebuilds(t *testing.T) { require.Equal(t, 1, strings.Count(buf.String(), "msg=changed")) } +// TestMetricInitAfterUpdateStillCounts checks that InitRateLimitMetrics +// takes effect even when it runs after the first Update already built the +// root handler. Before the fix, buildRoot closed over the *rateLimitMetrics +// value at build time; a nil value at that point (metrics not yet +// initialized) meant the counter stayed silently disabled forever, no +// matter when InitRateLimitMetrics ran afterward. +func TestMetricInitAfterUpdateStillCounts(t *testing.T) { + defer goleak.VerifyNone(t) + var buf bytes.Buffer + // New runs the first Update with no metrics registered yet. + l, err := New(&buf, Options{Level: LevelInfo, Format: FormatLogfmt, + RateLimiting: &RateLimitingOptions{Enabled: true, Tick: time.Hour, Threshold: 1, Rate: 0, MaxSignatures: 100}}) + require.NoError(t, err) + + // Metrics are initialized only now, after the root handler already exists. + reg := prometheus.NewRegistry() + l.InitRateLimitMetrics(reg) + + log := l.Slog() + log.Info("late-metric") + log.Info("late-metric") // 2nd dropped: over threshold + + mfs, err := reg.Gather() + require.NoError(t, err) + var total float64 + for _, mf := range mfs { + if mf.GetName() != "alloy_logging_suppressed_lines_total" { + continue + } + for _, m := range mf.GetMetric() { + total += m.GetCounter().GetValue() + } + } + require.GreaterOrEqual(t, total, float64(1), "suppressed-lines counter must increment even when InitRateLimitMetrics runs after the first Update") +} + // TestConcurrentUpdatesNoRace calls Update from many goroutines at once, // with valid options that may differ. It checks that -race stays clean, // nothing panics, and the logger still works afterward. diff --git a/internal/runtime/logging/options.go b/internal/runtime/logging/options.go index 0e900ffce6e..71286056fa9 100644 --- a/internal/runtime/logging/options.go +++ b/internal/runtime/logging/options.go @@ -198,7 +198,7 @@ func (o RateLimitingOptions) Validate() error { return fmt.Errorf("logging rate_limiting.tick must be > 0, got %v", o.Tick) case o.Threshold == 0: return fmt.Errorf("logging rate_limiting.threshold must be > 0") - case o.Rate < 0 || o.Rate > 1: + case math.IsNaN(o.Rate) || o.Rate < 0 || o.Rate > 1: return fmt.Errorf("logging rate_limiting.rate must be in [0,1], got %v", o.Rate) case o.MaxSignatures <= 0: return fmt.Errorf("logging rate_limiting.max_signatures must be > 0, got %d", o.MaxSignatures) diff --git a/internal/runtime/logging/options_test.go b/internal/runtime/logging/options_test.go index f2c1bf8258a..b02cd5d65da 100644 --- a/internal/runtime/logging/options_test.go +++ b/internal/runtime/logging/options_test.go @@ -1,6 +1,7 @@ package logging import ( + "math" "testing" "time" @@ -110,6 +111,7 @@ func TestRateLimitingValidate(t *testing.T) { func(o *RateLimitingOptions) { o.Threshold = 0 }, func(o *RateLimitingOptions) { o.Rate = -0.1 }, func(o *RateLimitingOptions) { o.Rate = 1.1 }, + func(o *RateLimitingOptions) { o.Rate = math.NaN() }, func(o *RateLimitingOptions) { o.MaxSignatures = 0 }, } { bad := valid diff --git a/internal/runtime/logging/rl_bench_test.go b/internal/runtime/logging/rl_bench_test.go index b404c425662..36ad97f002a 100644 --- a/internal/runtime/logging/rl_bench_test.go +++ b/internal/runtime/logging/rl_bench_test.go @@ -10,9 +10,10 @@ import ( ) // newRLBenchLogger builds a real *Logger that writes to io.Discard, using -// the given RateLimitingOptions. It sets up a fresh metrics registry, so the -// drop path exercises the alloy_logging_suppressed_lines_total counter, the -// same as in production. +// the given RateLimitingOptions. New builds the root handler first, and +// InitRateLimitMetrics runs after, the same order production code uses. The +// drop path exercises the live alloy_logging_suppressed_lines_total counter, +// the same as in production. func newRLBenchLogger(b *testing.B, rl RateLimitingOptions) *Logger { b.Helper() l, err := New(io.Discard, Options{ diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index dc6aea9bf93..1922251c34a 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -14,9 +14,10 @@ import ( type componentInfo struct{ id, path string } -// sniffComponent reads component_id, controller_id, and component_path from -// attrs and merges them onto base. It returns the result. -// If component_id is set, it wins over controller_id. +// sniffComponent reads component_id, controller_id, component_path, and +// controller_path from attrs and merges them onto base. It returns the +// result. If component_id is set, it wins over controller_id; the same +// precedence applies to component_path over controller_path. func sniffComponent(base componentInfo, attrs []slog.Attr) componentInfo { c := base for _, a := range attrs { @@ -29,6 +30,10 @@ func sniffComponent(base componentInfo, attrs []slog.Attr) componentInfo { } case "component_path": c.path = a.Value.String() + case "controller_path": + if c.path == "" { + c.path = a.Value.String() + } } } return c @@ -117,17 +122,29 @@ func (m *rateLimitMetrics) onDropped(ctx context.Context, r slog.Record) { // buildRoot wraps terminal with sampling when rate limiting is enabled. // Otherwise it returns terminal unchanged. -func buildRoot(o RateLimitingOptions, terminal slog.Handler, m *rateLimitMetrics) slog.Handler { +// +// metrics is a live pointer, not a captured value: OnDropped reads +// metrics.Load() on every drop, instead of closing over one +// *rateLimitMetrics snapshot at build time. This lets InitRateLimitMetrics +// take effect even when it runs after the root handler was already built by +// an earlier Update call. +func buildRoot(o RateLimitingOptions, terminal slog.Handler, metrics *atomic.Pointer[rateLimitMetrics]) slog.Handler { if !o.Enabled { return terminal } opt := slogsampling.ThresholdSamplingOption{ - Tick: o.Tick, - Threshold: o.Threshold, - Rate: o.Rate, - Matcher: compMatcher, - Buffer: buffer.NewLRUBuffer[string](o.MaxSignatures), - OnDropped: m.onDropped, + Tick: o.Tick, + Threshold: o.Threshold, + Rate: o.Rate, + Matcher: compMatcher, + Buffer: buffer.NewLRUBuffer[string](o.MaxSignatures), + OnDropped: func(ctx context.Context, r slog.Record) { + if metrics != nil { + if m := metrics.Load(); m != nil { + m.onDropped(ctx, r) + } + } + }, IncludeDroppedCount: true, } return opt.NewMiddleware()(terminal) diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go index 9616afd99b7..ab7c6405722 100644 --- a/internal/runtime/logging/sampling_test.go +++ b/internal/runtime/logging/sampling_test.go @@ -68,6 +68,38 @@ func TestSniffComponent(t *testing.T) { }) } +// TestSniffComponentControllerPath checks a past bug, where sniffComponent +// ignored controller_path. Controller log lines carry controller_id and +// controller_path, not component_id and component_path. Without this case, +// every controller log line got path="", so two nested controllers with the +// same leaf controller_id under different parents shared one rate-limit +// bucket and cross-suppressed each other. +func TestSniffComponentControllerPath(t *testing.T) { + t.Run("controller_path used when component_path absent", func(t *testing.T) { + c := sniffComponent(componentInfo{}, []slog.Attr{ + slog.String("controller_id", "controller_id"), + slog.String("controller_path", "controller_path"), + }) + require.Equal(t, componentInfo{id: "controller_id", path: "controller_path"}, c) + }) + + t.Run("component_path wins over controller_path", func(t *testing.T) { + c := sniffComponent(componentInfo{}, []slog.Attr{ + slog.String("controller_path", "/ctrl"), + slog.String("component_path", "/comp"), + }) + require.Equal(t, "/comp", c.path) + }) + + t.Run("component_path wins over controller_path regardless of attr order", func(t *testing.T) { + c := sniffComponent(componentInfo{}, []slog.Attr{ + slog.String("component_path", "/comp"), + slog.String("controller_path", "/ctrl"), + }) + require.Equal(t, "/comp", c.path) + }) +} + func TestCompMatcherKeysOnPathIDLevelMessage(t *testing.T) { mk := func(path, id string, level slog.Level, msg string) string { ctx := withComponent(context.Background(), componentInfo{path: path, id: id}) From 5b4e653514b5b6c6a90d7eba240a518e3792d385 Mon Sep 17 00:00:00 2001 From: Sam DeHaan Date: Mon, 3 Aug 2026 15:07:48 -0400 Subject: [PATCH 20/20] PR feedback --- docs/sources/reference/config-blocks/logging.md | 4 ++-- internal/runtime/logging/logger.go | 3 ++- internal/runtime/logging/sampling.go | 5 +++-- internal/runtime/logging/sampling_test.go | 3 ++- internal/util/metricsutil/metricsutil.go | 4 ++-- 5 files changed, 11 insertions(+), 8 deletions(-) diff --git a/docs/sources/reference/config-blocks/logging.md b/docs/sources/reference/config-blocks/logging.md index 17f1df39a4c..64474e874a2 100644 --- a/docs/sources/reference/config-blocks/logging.md +++ b/docs/sources/reference/config-blocks/logging.md @@ -80,8 +80,8 @@ The `rate_limiting` block enables per-message rate limiting and sampling of repe | Name | Type | Description | Default | Required | |------|------|-------------|---------|----------| | `enabled` | `bool` | Enable per-message rate limiting. | `true` | no | -| `max_signatures` | `number` | Distinct signatures tracked; least-recently-used is evicted when full. | `1000` | no | -| `rate` | `number` | Fraction (0–1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | +| `max_signatures` | `number` | Distinct signatures tracked; least recently used is evicted when full. | `1000` | no | +| `rate` | `number` | Fraction (0-1) of the over-threshold tail still admitted; `0` drops all excess. | `0` | no | | `threshold` | `number` | Identical lines admitted per (component, level, message) per tick before sampling. | `10` | no | | `tick` | `duration` | Sampling window. | `"10s"` | no | diff --git a/internal/runtime/logging/logger.go b/internal/runtime/logging/logger.go index 22a75e74919..bc75fa725bb 100644 --- a/internal/runtime/logging/logger.go +++ b/internal/runtime/logging/logger.go @@ -6,9 +6,10 @@ import ( "io" "log/slog" "sync" - "sync/atomic" "time" + "go.uber.org/atomic" + "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/common/model" diff --git a/internal/runtime/logging/sampling.go b/internal/runtime/logging/sampling.go index 1922251c34a..c2a706cb66e 100644 --- a/internal/runtime/logging/sampling.go +++ b/internal/runtime/logging/sampling.go @@ -3,7 +3,8 @@ package logging import ( "context" "log/slog" - "sync/atomic" + + "go.uber.org/atomic" "github.com/prometheus/client_golang/prometheus" slogsampling "github.com/samber/slog-sampling" @@ -104,7 +105,7 @@ func newRateLimitMetrics(reg prometheus.Registerer) *rateLimitMetrics { if existing := metricsutil.MustRegisterOrReturnExisting(reg, cv); existing != nil { cvExisting, ok := existing.(*prometheus.CounterVec) if !ok { - return nil + panic("alloy_logging_suppressed_lines_total already registered with unexpected collector type") } cv = cvExisting } diff --git a/internal/runtime/logging/sampling_test.go b/internal/runtime/logging/sampling_test.go index ab7c6405722..ba0698a1c38 100644 --- a/internal/runtime/logging/sampling_test.go +++ b/internal/runtime/logging/sampling_test.go @@ -6,10 +6,11 @@ import ( "io" "log/slog" "strings" - "sync/atomic" "testing" "time" + "go.uber.org/atomic" + slogsampling "github.com/samber/slog-sampling" "github.com/samber/slog-sampling/buffer" "github.com/stretchr/testify/require" diff --git a/internal/util/metricsutil/metricsutil.go b/internal/util/metricsutil/metricsutil.go index fd392f391a4..a55932287ae 100644 --- a/internal/util/metricsutil/metricsutil.go +++ b/internal/util/metricsutil/metricsutil.go @@ -8,8 +8,8 @@ import "github.com/prometheus/client_golang/prometheus" // MustRegisterOrReturnExisting registers c on reg. If c is already // registered, for example because multiple callers share one registerer, it -// returns the existing collector instead of panicking. -// If registration fails for any other reason, it panics. +// returns the existing collector instead of panicking. If registration succeeds, +// it returns nil. If registration fails for any other reason, it panics. func MustRegisterOrReturnExisting(reg prometheus.Registerer, c prometheus.Collector) prometheus.Collector { if err := reg.Register(c); err != nil { if are, ok := err.(prometheus.AlreadyRegisteredError); ok {