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 <[email protected]>

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)
+}

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))
+}

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()
+		})
+	}
+}