Repository: prometheus/common
Pull request #677 (2024-08-16 20:57:56)

feat: new promslog and promslog/flag packages to wrap log/slog
Prereq for prometheus/prometheus#14355

This adds a new `promslog` package to create an opinionated slog logger
for use within the prometheus ecosystem. By default, logs are written at
`info` level and formatted to add a kv pair for the source caller. If
backwards compatibility for the literal output format of the logging is
required, logs can be styled in a format that is similar to how the
`promlog` package formatted it's go-kit/log output [1].  The `promslog`
package also makes use of an `slog.LevelVar` to dynamically adjust the
level of an existing logger. Similar to the old `promlog` package, we
provide means to log in `logfmt` and `json` output formats.

Creating a logger is similar to the old promlog package -- optionally
populate a `Config` struct, and then call `New()` with the config.

In order to dynamically adjust the logger's level, retain the `Config`
struct as it's own variable to access the `AllowedLevel.Set()` method,
which internally updates the `AllowedLevel`'s slog.LevelVar to the
desired log level. Ex:

```go
config := &promslog.Config{} // Retain as variable if you need to dynamically adjust log level
logger := promslog.New(config)
config.Level.Set("debug")
logger.Debug("your message here", "hello", "world")
```

To use go-kit style log output:
```go
config := &promslog.Config{Style: promslog.GoKitStyle} // Retain as variable if you need to dynamically adjust log level
logger := promslog.New(config)
config.Level.Set("debug")
logger.Debug("your message here", "hello", "world")
```

1. When using the `go-kit` log style, the following changes are made to the
default slog output:
- adjusts slog default timestamp key from `timestamp` -> `ts`
- adjusts the timestamp value to use the same time format string
  ("2006-01-02T15:04:05.000Z07:00")
- adjusts slog default sourcecode key from `source` -> `caller`
- adjusts the formatting of the sourcecode values to trim paths with
  `filepath.Base()`. The formatting of the sourcecode value is similar
to the go-kit/log usage, with the addition of the source function in
parenthesis when debug logging is enabled.

Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>

tjhop: @SuperQ @beorn7:

This should be ready for review now. I believe I was able to set things up in a way where flag interactions can remain consistent (by also creating a new promslog/flag package to pair with the logger). Formatting for the literal log lines themselves _should_ be pretty close old formatting of the logger from promlog, with the exception of the value of the `caller` source key -- I didn't look into trying to tap into `runtime.Caller()` myself for slog, as is used behind the scenes when we call `log.Caller()` [here](https://github.com/prometheus/common/blob/2cac84e1490776cacb3f46f14e7adbaf8dcb4596/promlog/log.go#L191). 

Feedback welcome!
SuperQ: Nice!

My only question so far is how much we care about keeping the same log line formatting as before. Since this is intended for Prometheus 3.0, we can make breaking changes. 

Do we want to deviate from some of the minor slog defaults for formatting? Or use this as an opportunity to reset.
tjhop: We can certainly use it as an opportunity to reset -- my primary thought was that by maintaining log formatting, we would cause the least downstream disruption for anything that is parsing the resulting log lines. We're ok with making the breaking changes to formatting for prometheus because of the 3.0 release, but any other downstream projects would also inherit those formatting changes. 

I'd like to not be the cause of someone getting paged in the middle of the night because an upgrade to $someService was done and their loki recording/alerting rules broke from unexpected formatting changes, etc :upside_down_face: 
SuperQ: So let's break this down into individual decisions:

1. adjusts slog default timestamp key from timestamp -> ts
2. adjusts the timestamp value to use the same time format string
("2006-01-02T15:04:05.000Z07:00")
3. adjusts slog default sourcecode key from source -> caller
4. adjusts the formatting of the sourcecode values to trim paths with
filepath.Base(). The formatting of the sourcecode value is similar
to the go-kit/log usage, with the addition of the source function in
parenthesis when debug logging is enabled.

My vote:
1. Yes
2. No
3. No
4. Maybe
tjhop: There's also this (it made it in during a final refactor but I forgot to update commit description/PR summary):

5. The normalization of the `level` flag to use lowercase values, since slog's default is uppercase (`DEBUG` vs `debug`)

That said, I'll cast my vote:
1. I can go either way for timestamp key name
2. No
3. No
4. Yes for filepath trimming, maybe for adding in source func on debug level
5. Yes (purely personal preference)
tjhop: I believe I've addressed all PR feedback, the only remaining item should be determining the approach we want to take on the style initialization, whether we take the constructor approach or advocate consumers use the existing methods when prepping the logger config 
ArthurSens: You could use go's type safety to prevent library users from setting weird log styles:


```go
type LogStyle string

const (
	SlogStyle  LogStyle = "slog"
	GoKitStyle LogStyle = "go-kit"
)

// Config is a struct containing configurable settings for the logger
type Config struct {
	Level    *AllowedLevel
	Format   *AllowedFormat
	Style    LogStyle
	ioWriter io.Writer
}
```

But while quickly trying this out I realized it would require to refactor the whole implementation 😵 . I'm fine with returning error from the constructor
ArthurSens: Hey, I'm creating a new release to unblock the UTF8 work, but I can create another release tomorrow with this PR as well :)
ArthurSens: Do you also need a new release ASAP to get things done in Prometheus?
tjhop: @ArthurSens @SuperQ the last commit adjusts the log style to be a custom type, it's no longer settable :+1: 
tjhop: > Do you also need a new release ASAP to get things done in Prometheus?

A release would be helpful whenever y'all are comfortable with the final change set and have time. For now, I'm using go workspaces to start hacking on the prometheus 3.0 conversion :upside_down_face: 
SuperQ: @tjhop Do you want to squash up commits and finalize the commit/PR descriptions?
tjhop: > @tjhop Do you want to squash up commits and finalize the commit/PR descriptions?

no worries, can do :+1: 

Patch:
diff --git a/promslog/flag/flag.go b/promslog/flag/flag.go
new file mode 100644
index 0000000..34edb6f
--- /dev/null
+++ b/promslog/flag/flag.go
@@ -0,0 +1,56 @@
+// Copyright 2024 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Package flag defines standardised flag interactions for use with promslog
+// across Prometheus components.
+// It should typically only ever be imported by main packages.
+
+//go:build go1.21
+
+package flag
+
+import (
+	"strings"
+
+	kingpin "github.com/alecthomas/kingpin/v2"
+
+	"github.com/prometheus/common/promslog"
+)
+
+// LevelFlagName is the canonical flag name to configure the allowed log level
+// within Prometheus projects.
+const LevelFlagName = "log.level"
+
+// LevelFlagHelp is the help description for the log.level flag.
+var LevelFlagHelp = "Only log messages with the given severity or above. One of: [" + strings.Join(promslog.LevelFlagOptions, ", ") + "]"
+
+// FormatFlagName is the canonical flag name to configure the log format
+// within Prometheus projects.
+const FormatFlagName = "log.format"
+
+// FormatFlagHelp is the help description for the log.format flag.
+var FormatFlagHelp = "Output format of log messages. One of: [" + strings.Join(promslog.FormatFlagOptions, ", ") + "]"
+
+// 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{}
+	a.Flag(LevelFlagName, LevelFlagHelp).
+		Default("info").HintOptions(promslog.LevelFlagOptions...).
+		SetValue(config.Level)
+
+	config.Format = &promslog.AllowedFormat{}
+	a.Flag(FormatFlagName, FormatFlagHelp).
+		Default("logfmt").HintOptions(promslog.FormatFlagOptions...).
+		SetValue(config.Format)
+}
diff --git a/promslog/slog.go b/promslog/slog.go
new file mode 100644
index 0000000..7fb24d4
--- /dev/null
+++ b/promslog/slog.go
@@ -0,0 +1,182 @@
+// Copyright 2024 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Package promslog defines standardised ways to initialize the Go standard
+// library's log/slog logger.
+// It should typically only ever be imported by main packages.
+
+//go:build go1.21
+
+package promslog
+
+import (
+	"fmt"
+	"io"
+	"log/slog"
+	"os"
+	"path/filepath"
+	"strconv"
+	"strings"
+)
+
+type LogStyle string
+
+const (
+	SlogStyle  LogStyle = "slog"
+	GoKitStyle LogStyle = "go-kit"
+)
+
+var (
+	LevelFlagOptions  = []string{"debug", "info", "warn", "error"}
+	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:
+			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).
+			t := a.Value.Time()
+			a.Value = slog.StringValue(t.Format("2006-01-02T15:04:05.000Z07:00"))
+		case slog.SourceKey:
+			a.Key = "caller"
+			src, _ := a.Value.Any().(*slog.Source)
+
+			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))
+			}
+		case slog.LevelKey:
+			a.Value = slog.StringValue(strings.ToLower(a.Value.String()))
+		default:
+		}
+
+		return a
+	}
+)
+
+// AllowedLevel is a settable identifier for the minimum level a log entry
+// must be have.
+type AllowedLevel struct {
+	s   string
+	lvl *slog.LevelVar
+}
+
+func (l *AllowedLevel) UnmarshalYAML(unmarshal func(interface{}) error) error {
+	var s string
+	type plain string
+	if err := unmarshal((*plain)(&s)); err != nil {
+		return err
+	}
+	if s == "" {
+		return nil
+	}
+	lo := &AllowedLevel{}
+	if err := lo.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{}
+	}
+
+	switch 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 {
+	s string
+}
+
+func (f *AllowedFormat) String() string {
+	return f.s
+}
+
+// Set updates the value of the allowed format.
+func (f *AllowedFormat) Set(s string) error {
+	switch s {
+	case "logfmt", "json":
+		f.s = s
+	default:
+		return fmt.Errorf("unrecognized log format %s", s)
+	}
+	return nil
+}
+
+// Config is a struct containing configurable settings for the logger
+type Config struct {
+	Level    *AllowedLevel
+	Format   *AllowedFormat
+	Style    LogStyle
+	ioWriter io.Writer
+}
+
+// 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.Set("info")
+	}
+
+	if config.ioWriter == nil {
+		config.ioWriter = defaultWriter
+	}
+
+	logHandlerOpts := &slog.HandlerOptions{
+		Level:     config.Level.lvl,
+		AddSource: true,
+	}
+
+	if config.Style == GoKitStyle {
+		logHandlerOpts.ReplaceAttr = goKitStyleReplaceAttrFunc
+	}
+
+	if config.Format != nil && config.Format.s == "json" {
+		return slog.New(slog.NewJSONHandler(config.ioWriter, logHandlerOpts))
+	}
+	return slog.New(slog.NewTextHandler(config.ioWriter, logHandlerOpts))
+}


Test patch:
diff --git a/promslog/slog_test.go b/promslog/slog_test.go
new file mode 100644
index 0000000..5f37e18
--- /dev/null
+++ b/promslog/slog_test.go
@@ -0,0 +1,150 @@
+// Copyright 2024 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+//go:build go1.21
+
+package promslog
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"log/slog"
+	"regexp"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+	"gopkg.in/yaml.v2"
+)
+
+var (
+	slogStyleLogRegexp  = regexp.MustCompile(`(?P<TimeKey>time)=.*level=(?P<LevelValue>WARN|INFO|ERROR|DEBUG).*(?P<SourceKey>source)=.*`)
+	goKitStyleLogRegexp = regexp.MustCompile(`(?P<TimeKey>ts)=.*level=(?P<LevelValue>warn|info|error|debug).*(?P<SourceKey>caller)=.*`)
+)
+
+// Make sure creating and using a logger with an empty configuration doesn't
+// result in a panic.
+func TestDefaultConfig(t *testing.T) {
+	require.NotPanics(t, func() {
+		logger := New(&Config{})
+		logger.Info("empty config `Info()` test", "hello", "world")
+		logger.Log(context.Background(), slog.LevelInfo, "empty config `Log()` test", "hello", "world")
+		logger.LogAttrs(context.Background(), slog.LevelInfo, "empty config `LogAttrs()` test", slog.String("hello", "world"))
+	})
+}
+
+func TestUnmarshallLevel(t *testing.T) {
+	l := &AllowedLevel{}
+	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)
+	}
+}
+
+func TestUnmarshallEmptyLevel(t *testing.T) {
+	l := &AllowedLevel{}
+	err := yaml.Unmarshal([]byte(``), l)
+	if err != nil {
+		t.Error(err)
+	}
+	if l.s != "" {
+		t.Errorf("expected empty level, got %s", l.s)
+	}
+}
+
+func TestUnmarshallBadLevel(t *testing.T) {
+	l := &AllowedLevel{}
+	err := yaml.Unmarshal([]byte(`debugg`), l)
+	if err == nil {
+		t.Error("expected error")
+	}
+	expErr := `unrecognized log level debugg`
+	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)
+	}
+}
+
+func getLogEntryLevelCounts(s string, re *regexp.Regexp) map[string]int {
+	counters := make(map[string]int)
+	lines := strings.Split(s, "\n")
+	for _, line := range lines {
+		matches := re.FindStringSubmatch(line)
+		if len(matches) > 1 {
+			levelIndex := re.SubexpIndex("LevelValue")
+
+			counters[strings.ToLower(matches[levelIndex])]++
+		}
+	}
+
+	return counters
+}
+
+func TestDynamicLevels(t *testing.T) {
+	var buf bytes.Buffer
+	wantedLevelCounts := map[string]int{"info": 1, "debug": 1}
+
+	tests := map[string]struct {
+		logStyle         LogStyle
+		logStyleRegexp   *regexp.Regexp
+		wantedLevelCount map[string]int
+	}{
+		"slog_log_style":   {logStyle: SlogStyle, logStyleRegexp: slogStyleLogRegexp, wantedLevelCount: wantedLevelCounts},
+		"go-kit_log_style": {logStyle: GoKitStyle, logStyleRegexp: goKitStyleLogRegexp, wantedLevelCount: wantedLevelCounts},
+	}
+
+	for name, tc := range tests {
+		t.Run(name, func(t *testing.T) {
+			buf.Reset() // Ensure buf is reset prior to tests
+			config := &Config{ioWriter: &buf, Style: tc.logStyle}
+			logger := New(config)
+
+			// Test that log level can be adjusted on-the-fly to debug and that a
+			// log entry can be written to the file.
+			if err := config.Level.Set("debug"); err != nil {
+				t.Fatal(err)
+			}
+			logger.Info("info", "hello", "world")
+			logger.Debug("debug", "hello", "world")
+
+			counts := getLogEntryLevelCounts(buf.String(), tc.logStyleRegexp)
+			require.Equal(t, tc.wantedLevelCount["info"], counts["info"], "info log successfully detected")
+			require.Equal(t, tc.wantedLevelCount["debug"], counts["debug"], "debug log successfully detected")
+			// Print logs for humans to see, if needed.
+			fmt.Println(buf.String())
+			buf.Reset()
+
+			// Test that log level can be adjusted on-the-fly to info and that a
+			// subsequent call to write a debug level log is _not_ written to the
+			// file.
+			if err := config.Level.Set("info"); err != nil {
+				t.Fatal(err)
+			}
+			logger.Info("info", "hello", "world")
+			logger.Debug("debug", "hello", "world")
+
+			counts = getLogEntryLevelCounts(buf.String(), tc.logStyleRegexp)
+			require.Equal(t, tc.wantedLevelCount["info"], counts["info"], "info log successfully detected")
+			require.NotEqual(t, tc.wantedLevelCount["debug"], counts["debug"], "extra debug log detected")
+			// Print logs for humans to see, if needed.
+			fmt.Println(buf.String())
+			buf.Reset()
+		})
+	}
+}