From abb6c2d9c5ca9e8ea97f4886bc1f36308857a591 Mon Sep 17 00:00:00 2001 From: bwplotka Date: Fri, 31 Jan 2025 13:30:35 +0000 Subject: [PATCH 1/2] promslog: Make AllowedLevel concurrency safe. Needed for https://github.com/prometheus/prometheus/issues/10352 Also I renamed AllowedLevel and AllowedFormat to Level and Format. Default level (and String()) is also now 'info' not empty. It's a breaking change, but I suspect nobody was using those constructs directly, WDYT? Signed-off-by: bwplotka --- promslog/flag/flag.go | 4 +- promslog/slog.go | 270 ++++++++++++++++++++++-------------------- promslog/slog_test.go | 18 +-- 3 files changed, 154 insertions(+), 138 deletions(-) diff --git a/promslog/flag/flag.go b/promslog/flag/flag.go index 0a164fcc1..85c67b250 100644 --- a/promslog/flag/flag.go +++ b/promslog/flag/flag.go @@ -42,12 +42,12 @@ var FormatFlagHelp = "Output format of log messages. One of: [" + strings.Join(p // AddFlags adds the flags used by this package to the Kingpin application. // To use the default Kingpin application, call AddFlags(kingpin.CommandLine) func AddFlags(a *kingpin.Application, config *promslog.Config) { - config.Level = &promslog.AllowedLevel{} + config.Level = promslog.NewLevel() a.Flag(LevelFlagName, LevelFlagHelp). Default("info").HintOptions(promslog.LevelFlagOptions...). SetValue(config.Level) - config.Format = &promslog.AllowedFormat{} + config.Format = promslog.NewFormat() a.Flag(FormatFlagName, FormatFlagHelp). Default("logfmt").HintOptions(promslog.FormatFlagOptions...). SetValue(config.Format) diff --git a/promslog/slog.go b/promslog/slog.go index 11c33fb66..c0ea0d3aa 100644 --- a/promslog/slog.go +++ b/promslog/slog.go @@ -28,6 +28,7 @@ import ( "time" ) +// LogStyle represents the common logging formats in the Prometheus ecosystem. type LogStyle string const ( @@ -38,115 +39,29 @@ const ( ) var ( - LevelFlagOptions = []string{"debug", "info", "warn", "error"} + // LevelFlagOptions represents allowed logging levels. + LevelFlagOptions = []string{"debug", "info", "warn", "error"} + // FormatFlagOptions represents allowed formats. FormatFlagOptions = []string{"logfmt", "json"} - callerAddFunc = false - defaultWriter = os.Stderr - goKitStyleReplaceAttrFunc = func(groups []string, a slog.Attr) slog.Attr { - key := a.Key - switch key { - case slog.TimeKey, "ts": - if t, ok := a.Value.Any().(time.Time); ok { - a.Key = "ts" - - // This timestamp format differs from RFC3339Nano by using .000 instead - // of .999999999 which changes the timestamp from 9 variable to 3 fixed - // decimals (.130 instead of .130987456). - a.Value = slog.StringValue(t.UTC().Format("2006-01-02T15:04:05.000Z07:00")) - } else { - // If we can't cast the any from the value to a - // time.Time, it means the caller logged - // another attribute with a key of `ts`. - // Prevent duplicate keys (necessary for proper - // JSON) by renaming the key to `logged_ts`. - a.Key = reservedKeyPrefix + key - } - case slog.SourceKey, "caller": - if src, ok := a.Value.Any().(*slog.Source); ok { - a.Key = "caller" - switch callerAddFunc { - case true: - a.Value = slog.StringValue(filepath.Base(src.File) + "(" + filepath.Base(src.Function) + "):" + strconv.Itoa(src.Line)) - default: - a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line)) - } - } else { - // If we can't cast the any from the value to - // an *slog.Source, it means the caller logged - // another attribute with a key of `caller`. - // Prevent duplicate keys (necessary for proper - // JSON) by renaming the key to - // `logged_caller`. - a.Key = reservedKeyPrefix + key - } - case slog.LevelKey: - if lvl, ok := a.Value.Any().(slog.Level); ok { - a.Value = slog.StringValue(strings.ToLower(lvl.String())) - } else { - // If we can't cast the any from the value to - // an slog.Level, it means the caller logged - // another attribute with a key of `level`. - // Prevent duplicate keys (necessary for proper - // JSON) by renaming the key to `logged_level`. - a.Key = reservedKeyPrefix + key - } - default: - } - - return a - } - defaultReplaceAttrFunc = func(groups []string, a slog.Attr) slog.Attr { - key := a.Key - switch key { - case slog.TimeKey: - if t, ok := a.Value.Any().(time.Time); ok { - a.Value = slog.TimeValue(t.UTC()) - } else { - // If we can't cast the any from the value to a - // time.Time, it means the caller logged - // another attribute with a key of `time`. - // Prevent duplicate keys (necessary for proper - // JSON) by renaming the key to `logged_time`. - a.Key = reservedKeyPrefix + key - } - case slog.SourceKey: - if src, ok := a.Value.Any().(*slog.Source); ok { - a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line)) - } else { - // If we can't cast the any from the value to - // an *slog.Source, it means the caller logged - // another attribute with a key of `source`. - // Prevent duplicate keys (necessary for proper - // JSON) by renaming the key to - // `logged_source`. - a.Key = reservedKeyPrefix + key - } - case slog.LevelKey: - if _, ok := a.Value.Any().(slog.Level); !ok { - // If we can't cast the any from the value to - // an slog.Level, it means the caller logged - // another attribute with a key of `level`. - // Prevent duplicate keys (necessary for proper - // JSON) by renaming the key to - // `logged_level`. - a.Key = reservedKeyPrefix + key - } - default: - } - - return a - } + defaultWriter = os.Stderr ) -// AllowedLevel is a settable identifier for the minimum level a log entry -// must be have. -type AllowedLevel struct { - s string +// Level controls a logging level, with an info default. +// It wraps slog.LevelVar with string-based level control. +// Level is safe to be used concurrently. +type Level struct { lvl *slog.LevelVar } -func (l *AllowedLevel) UnmarshalYAML(unmarshal func(interface{}) error) error { +// NewLevel returns a new Level. +func NewLevel() *Level { + return &Level{ + lvl: &slog.LevelVar{}, + } +} + +func (l *Level) UnmarshalYAML(unmarshal func(interface{}) error) error { var s string type plain string if err := unmarshal((*plain)(&s)); err != nil { @@ -155,55 +70,60 @@ func (l *AllowedLevel) UnmarshalYAML(unmarshal func(interface{}) error) error { if s == "" { return nil } - lo := &AllowedLevel{} - if err := lo.Set(s); err != nil { + if err := l.Set(s); err != nil { return err } - *l = *lo return nil } -func (l *AllowedLevel) String() string { - return l.s -} - -// Set updates the value of the allowed level. -func (l *AllowedLevel) Set(s string) error { - if l.lvl == nil { - l.lvl = &slog.LevelVar{} +// String returns the current level. +func (l *Level) String() string { + switch l.lvl.Level() { + case slog.LevelDebug: + return "debug" + case slog.LevelInfo: + return "info" + case slog.LevelWarn: + return "warn" + case slog.LevelError: + return "error" + default: + return "" } +} +// Set updates the logging level with the validation. +func (l *Level) Set(s string) error { switch strings.ToLower(s) { case "debug": l.lvl.Set(slog.LevelDebug) - callerAddFunc = true case "info": l.lvl.Set(slog.LevelInfo) - callerAddFunc = false case "warn": l.lvl.Set(slog.LevelWarn) - callerAddFunc = false case "error": l.lvl.Set(slog.LevelError) - callerAddFunc = false default: return fmt.Errorf("unrecognized log level %s", s) } - l.s = s return nil } -// AllowedFormat is a settable identifier for the output format that the logger can have. -type AllowedFormat struct { +// Format controls a logging output format. +// Not concurrency-safe. +type Format struct { s string } -func (f *AllowedFormat) String() string { +// NewFormat creates a new Format. +func NewFormat() *Format { return &Format{} } + +func (f *Format) String() string { return f.s } // Set updates the value of the allowed format. -func (f *AllowedFormat) Set(s string) error { +func (f *Format) Set(s string) error { switch s { case "logfmt", "json": f.s = s @@ -215,17 +135,113 @@ func (f *AllowedFormat) Set(s string) error { // Config is a struct containing configurable settings for the logger type Config struct { - Level *AllowedLevel - Format *AllowedFormat + Level *Level + Format *Format Style LogStyle Writer io.Writer } +func newGoKitStyleReplaceAttrFunc(lvl *Level) func(groups []string, a slog.Attr) slog.Attr { + return func(groups []string, a slog.Attr) slog.Attr { + key := a.Key + switch key { + case slog.TimeKey, "ts": + if t, ok := a.Value.Any().(time.Time); ok { + a.Key = "ts" + + // This timestamp format differs from RFC3339Nano by using .000 instead + // of .999999999 which changes the timestamp from 9 variable to 3 fixed + // decimals (.130 instead of .130987456). + a.Value = slog.StringValue(t.UTC().Format("2006-01-02T15:04:05.000Z07:00")) + } else { + // If we can't cast the any from the value to a + // time.Time, it means the caller logged + // another attribute with a key of `ts`. + // Prevent duplicate keys (necessary for proper + // JSON) by renaming the key to `logged_ts`. + a.Key = reservedKeyPrefix + key + } + case slog.SourceKey, "caller": + if src, ok := a.Value.Any().(*slog.Source); ok { + a.Key = "caller" + switch lvl.String() { + case "debug": + a.Value = slog.StringValue(filepath.Base(src.File) + "(" + filepath.Base(src.Function) + "):" + strconv.Itoa(src.Line)) + default: + a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line)) + } + } else { + // If we can't cast the any from the value to + // an *slog.Source, it means the caller logged + // another attribute with a key of `caller`. + // Prevent duplicate keys (necessary for proper + // JSON) by renaming the key to + // `logged_caller`. + a.Key = reservedKeyPrefix + key + } + case slog.LevelKey: + if lvl, ok := a.Value.Any().(slog.Level); ok { + a.Value = slog.StringValue(strings.ToLower(lvl.String())) + } else { + // If we can't cast the any from the value to + // an slog.Level, it means the caller logged + // another attribute with a key of `level`. + // Prevent duplicate keys (necessary for proper + // JSON) by renaming the key to `logged_level`. + a.Key = reservedKeyPrefix + key + } + default: + } + return a + } +} + +func defaultReplaceAttr(_ []string, a slog.Attr) slog.Attr { + key := a.Key + switch key { + case slog.TimeKey: + if t, ok := a.Value.Any().(time.Time); ok { + a.Value = slog.TimeValue(t.UTC()) + } else { + // If we can't cast the any from the value to a + // time.Time, it means the caller logged + // another attribute with a key of `time`. + // Prevent duplicate keys (necessary for proper + // JSON) by renaming the key to `logged_time`. + a.Key = reservedKeyPrefix + key + } + case slog.SourceKey: + if src, ok := a.Value.Any().(*slog.Source); ok { + a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line)) + } else { + // If we can't cast the any from the value to + // an *slog.Source, it means the caller logged + // another attribute with a key of `source`. + // Prevent duplicate keys (necessary for proper + // JSON) by renaming the key to + // `logged_source`. + a.Key = reservedKeyPrefix + key + } + case slog.LevelKey: + if _, ok := a.Value.Any().(slog.Level); !ok { + // If we can't cast the any from the value to + // an slog.Level, it means the caller logged + // another attribute with a key of `level`. + // Prevent duplicate keys (necessary for proper + // JSON) by renaming the key to + // `logged_level`. + a.Key = reservedKeyPrefix + key + } + default: + } + return a +} + // New returns a new slog.Logger. Each logged line will be annotated // with a timestamp. The output always goes to stderr. func New(config *Config) *slog.Logger { if config.Level == nil { - config.Level = &AllowedLevel{} + config.Level = NewLevel() _ = config.Level.Set("info") } @@ -236,11 +252,11 @@ func New(config *Config) *slog.Logger { logHandlerOpts := &slog.HandlerOptions{ Level: config.Level.lvl, AddSource: true, - ReplaceAttr: defaultReplaceAttrFunc, + ReplaceAttr: defaultReplaceAttr, } if config.Style == GoKitStyle { - logHandlerOpts.ReplaceAttr = goKitStyleReplaceAttrFunc + logHandlerOpts.ReplaceAttr = newGoKitStyleReplaceAttrFunc(config.Level) } if config.Format != nil && config.Format.s == "json" { diff --git a/promslog/slog_test.go b/promslog/slog_test.go index 6da14d987..ea4e176c2 100644 --- a/promslog/slog_test.go +++ b/promslog/slog_test.go @@ -43,29 +43,29 @@ func TestDefaultConfig(t *testing.T) { } func TestUnmarshallLevel(t *testing.T) { - l := &AllowedLevel{} + l := NewLevel() err := yaml.Unmarshal([]byte(`debug`), l) if err != nil { t.Error(err) } - if l.s != "debug" { - t.Errorf("expected %s, got %s", "debug", l.s) + if got := l.String(); got != "debug" { + t.Errorf("expected %s, got %s", "debug", got) } } func TestUnmarshallEmptyLevel(t *testing.T) { - l := &AllowedLevel{} + l := NewLevel() err := yaml.Unmarshal([]byte(``), l) if err != nil { t.Error(err) } - if l.s != "" { - t.Errorf("expected empty level, got %s", l.s) + if got := l.String(); got != "info" { + t.Errorf("expected info (default) level, got %s", got) } } func TestUnmarshallBadLevel(t *testing.T) { - l := &AllowedLevel{} + l := NewLevel() err := yaml.Unmarshal([]byte(`debugg`), l) if err == nil { t.Error("expected error") @@ -74,8 +74,8 @@ func TestUnmarshallBadLevel(t *testing.T) { if err.Error() != expErr { t.Errorf("expected error %s, got %s", expErr, err.Error()) } - if l.s != "" { - t.Errorf("expected empty level, got %s", l.s) + if got := l.String(); got != "info" { + t.Errorf("expected info (default) level, got %s", got) } } From d2c0a787ae3ad03a851011b309162770f35c2d85 Mon Sep 17 00:00:00 2001 From: bwplotka Date: Fri, 31 Jan 2025 13:48:31 +0000 Subject: [PATCH 2/2] info is by default, so no need for the set in New Signed-off-by: bwplotka --- promslog/slog.go | 1 - 1 file changed, 1 deletion(-) diff --git a/promslog/slog.go b/promslog/slog.go index c0ea0d3aa..f9f899663 100644 --- a/promslog/slog.go +++ b/promslog/slog.go @@ -242,7 +242,6 @@ func defaultReplaceAttr(_ []string, a slog.Attr) slog.Attr { func New(config *Config) *slog.Logger { if config.Level == nil { config.Level = NewLevel() - _ = config.Level.Set("info") } if config.Writer == nil {