diff --git a/.github/dependabot.yml b/.github/dependabot.yml new file mode 100644 index 0000000..5ace460 --- /dev/null +++ b/.github/dependabot.yml @@ -0,0 +1,6 @@ +version: 2 +updates: + - package-ecosystem: "github-actions" + directory: "/" + schedule: + interval: "weekly" diff --git a/.github/workflows/apidiff.yaml b/.github/workflows/apidiff.yaml index a76a30c..7002b22 100644 --- a/.github/workflows/apidiff.yaml +++ b/.github/workflows/apidiff.yaml @@ -2,26 +2,29 @@ name: Run apidiff on: [ pull_request ] +permissions: + contents: read + jobs: apidiff: runs-on: ubuntu-latest if: github.base_ref steps: - name: Install Go - uses: actions/setup-go@v2 + uses: actions/setup-go@93397bea11091df50f3d7e59dc26a7711a8bcfbe # v4.1.0 with: - go-version: 1.18.x + go-version: 1.20.x - name: Add GOBIN to PATH run: echo "PATH=$(go env GOPATH)/bin:$PATH" >>$GITHUB_ENV - name: Install dependencies run: GO111MODULE=off go get golang.org/x/exp/cmd/apidiff - name: Checkout old code - uses: actions/checkout@v2 + uses: actions/checkout@b4ffde65f46336ab88eb53be808477a3936bae11 # v4.1.1 with: ref: ${{ github.base_ref }} path: "old" - name: Checkout new code - uses: actions/checkout@v2 + uses: actions/checkout@b4ffde65f46336ab88eb53be808477a3936bae11 # v4.1.1 with: path: "new" - name: APIDiff diff --git a/.github/workflows/assign.yaml b/.github/workflows/assign.yaml index e1bfb97..8f73815 100644 --- a/.github/workflows/assign.yaml +++ b/.github/workflows/assign.yaml @@ -6,11 +6,17 @@ on: pull_request_target: types: [opened, reopened] +permissions: + contents: read + jobs: assign: runs-on: ubuntu-latest + permissions: + issues: write + pull-requests: write steps: - - uses: actions/github-script@v6 + - uses: actions/github-script@d7906e4ad0b1822421a7e6a35d5ca353c962f410 # v6.4.1 with: script: | github.rest.issues.addAssignees({ diff --git a/.github/workflows/lint.yaml b/.github/workflows/lint.yaml index c46cb8b..80b51b5 100644 --- a/.github/workflows/lint.yaml +++ b/.github/workflows/lint.yaml @@ -2,14 +2,17 @@ name: Run lint on: [ push, pull_request ] +permissions: + contents: read + jobs: lint: runs-on: ubuntu-latest steps: - name: Checkout code - uses: actions/checkout@v2 + uses: actions/checkout@b4ffde65f46336ab88eb53be808477a3936bae11 # v4.1.1 - name: Lint - uses: golangci/golangci-lint-action@v2 + uses: golangci/golangci-lint-action@3a919529898de77ec3da873e3063ca4b10e7f5cc # v3.7.0 with: # version of golangci-lint to use in form of v1.2 or v1.2.3 or `latest` to use the latest version version: latest diff --git a/.github/workflows/scorecard.yml b/.github/workflows/scorecard.yml new file mode 100644 index 0000000..593645a --- /dev/null +++ b/.github/workflows/scorecard.yml @@ -0,0 +1,64 @@ +# This workflow uses actions that are not certified by GitHub. They are provided +# by a third-party and are governed by separate terms of service, privacy +# policy, and support documentation. + +name: Scorecard supply-chain security +on: + # For Branch-Protection check. Only the default branch is supported. See + # https://github.com/ossf/scorecard/blob/main/docs/checks.md#branch-protection + branch_protection_rule: + # To guarantee Maintained check is occasionally updated. See + # https://github.com/ossf/scorecard/blob/main/docs/checks.md#maintained + schedule: + - cron: '28 21 * * 1' + push: + branches: [ "master" ] + +# Declare default permissions as read only. +permissions: read-all + +jobs: + analysis: + name: Scorecard analysis + runs-on: ubuntu-latest + permissions: + # Needed to upload the results to code-scanning dashboard. + security-events: write + # Needed to publish results and get a badge (see publish_results below). + id-token: write + + steps: + - name: "Checkout code" + uses: actions/checkout@b4ffde65f46336ab88eb53be808477a3936bae11 # v4.1.1 + with: + persist-credentials: false + + - name: "Run analysis" + uses: ossf/scorecard-action@483ef80eb98fb506c348f7d62e28055e49fe2398 # v2.3.0 + with: + results_file: results.sarif + results_format: sarif + # (Optional) "write" PAT token. Uncomment the `repo_token` line below if: + # you want to enable the Branch-Protection check on a *public* repository, or + # To create the PAT, follow the steps in https://github.com/ossf/scorecard-action#authentication-with-pat. + # repo_token: ${{ secrets.SCORECARD_TOKEN }} + + # - Publish results to OpenSSF REST API for easy access by consumers + # - Allows the repository to include the Scorecard badge. + # - See https://github.com/ossf/scorecard-action#publishing-results. + publish_results: true + + # Upload the results as artifacts (optional). Commenting out will disable uploads of run results in SARIF + # format to the repository Actions tab. + - name: "Upload artifact" + uses: actions/upload-artifact@a8a3f3ad30e3422c9c7b888a15615d19a852ae32 # v3.1.3 + with: + name: SARIF file + path: results.sarif + retention-days: 5 + + # Upload the results to GitHub's code scanning dashboard. + - name: "Upload to code-scanning" + uses: github/codeql-action/upload-sarif@49abf0ba24d0b7953cb586944e918a0b92074c80 # v2.22.4 + with: + sarif_file: results.sarif diff --git a/.github/workflows/tests.yaml b/.github/workflows/tests.yaml index 2b7f2b5..add16a5 100644 --- a/.github/workflows/tests.yaml +++ b/.github/workflows/tests.yaml @@ -2,20 +2,23 @@ name: Run tests on: [ push, pull_request ] +permissions: + contents: read + jobs: test: strategy: matrix: - version: [ '1.15', '1.16', '1.17', '1.18' ] + version: [ '1.18', '1.19', '1.20', '1.21.0-rc.4' ] platform: [ ubuntu-latest, macos-latest, windows-latest ] runs-on: ${{ matrix.platform }} steps: - name: Install Go - uses: actions/setup-go@v2 + uses: actions/setup-go@93397bea11091df50f3d7e59dc26a7711a8bcfbe # v4.1.0 with: go-version: ${{ matrix.version }} - name: Checkout code - uses: actions/checkout@v2 + uses: actions/checkout@b4ffde65f46336ab88eb53be808477a3936bae11 # v4.1.1 - name: Build run: go build -v ./... - name: Test diff --git a/README.md b/README.md index ab59311..a8c29bf 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,7 @@ # A minimal logging API for Go [![Go Reference](https://pkg.go.dev/badge/github.com/go-logr/logr.svg)](https://pkg.go.dev/github.com/go-logr/logr) +[![OpenSSF Scorecard](https://api.securityscorecards.dev/projects/github.com/go-logr/logr/badge)](https://securityscorecards.dev/viewer/?platform=github.com&org=go-logr&repo=logr) logr offers an(other) opinion on how Go programs and libraries can do logging without becoming coupled to a particular logging implementation. This is not @@ -73,6 +74,29 @@ received: If the Go standard library had defined an interface for logging, this project probably would not be needed. Alas, here we are. +When the Go developers started developing such an interface with +[slog](https://github.com/golang/go/issues/56345), they adopted some of the +logr design but also left out some parts and changed others: + +| Feature | logr | slog | +|---------|------|------| +| High-level API | `Logger` (passed by value) | `Logger` (passed by [pointer](https://github.com/golang/go/issues/59126)) | +| Low-level API | `LogSink` | `Handler` | +| Stack unwinding | done by `LogSink` | done by `Logger` | +| Skipping helper functions | `WithCallDepth`, `WithCallStackHelper` | [not supported by Logger](https://github.com/golang/go/issues/59145) | +| Generating a value for logging on demand | `Marshaler` | `LogValuer` | +| Log levels | >= 0, higher meaning "less important" | positive and negative, with 0 for "info" and higher meaning "more important" | +| Error log entries | always logged, don't have a verbosity level | normal log entries with level >= `LevelError` | +| Passing logger via context | `NewContext`, `FromContext` | no API | +| Adding a name to a logger | `WithName` | no API | +| Modify verbosity of log entries in a call chain | `V` | no API | +| Grouping of key/value pairs | not supported | `WithGroup`, `GroupValue` | + +The high-level slog API is explicitly meant to be one of many different APIs +that can be layered on top of a shared `slog.Handler`. logr is one such +alternative API, with [interoperability](#slog-interoperability) provided by the [`slogr`](slogr) +package. + ### Inspiration Before you consider this package, please read [this blog post by the @@ -118,6 +142,91 @@ There are implementations for the following logging libraries: - **github.com/go-kit/log**: [gokitlogr](https://github.com/tonglil/gokitlogr) (also compatible with github.com/go-kit/kit/log since v0.12.0) - **bytes.Buffer** (writing to a buffer): [bufrlogr](https://github.com/tonglil/buflogr) (useful for ensuring values were logged, like during testing) +## slog interoperability + +Interoperability goes both ways, using the `logr.Logger` API with a `slog.Handler` +and using the `slog.Logger` API with a `logr.LogSink`. [slogr](./slogr) provides `NewLogr` and +`NewSlogHandler` API calls to convert between a `logr.Logger` and a `slog.Handler`. +As usual, `slog.New` can be used to wrap such a `slog.Handler` in the high-level +slog API. `slogr` itself leaves that to the caller. + +## Using a `logr.Sink` as backend for slog + +Ideally, a logr sink implementation should support both logr and slog by +implementing both the normal logr interface(s) and `slogr.SlogSink`. Because +of a conflict in the parameters of the common `Enabled` method, it is [not +possible to implement both slog.Handler and logr.Sink in the same +type](https://github.com/golang/go/issues/59110). + +If both are supported, log calls can go from the high-level APIs to the backend +without the need to convert parameters. `NewLogr` and `NewSlogHandler` can +convert back and forth without adding additional wrappers, with one exception: +when `Logger.V` was used to adjust the verbosity for a `slog.Handler`, then +`NewSlogHandler` has to use a wrapper which adjusts the verbosity for future +log calls. + +Such an implementation should also support values that implement specific +interfaces from both packages for logging (`logr.Marshaler`, `slog.LogValuer`, +`slog.GroupValue`). logr does not convert those. + +Not supporting slog has several drawbacks: +- Recording source code locations works correctly if the handler gets called + through `slog.Logger`, but may be wrong in other cases. That's because a + `logr.Sink` does its own stack unwinding instead of using the program counter + provided by the high-level API. +- slog levels <= 0 can be mapped to logr levels by negating the level without a + loss of information. But all slog levels > 0 (e.g. `slog.LevelWarning` as + used by `slog.Logger.Warn`) must be mapped to 0 before calling the sink + because logr does not support "more important than info" levels. +- The slog group concept is supported by prefixing each key in a key/value + pair with the group names, separated by a dot. For structured output like + JSON it would be better to group the key/value pairs inside an object. +- Special slog values and interfaces don't work as expected. +- The overhead is likely to be higher. + +These drawbacks are severe enough that applications using a mixture of slog and +logr should switch to a different backend. + +## Using a `slog.Handler` as backend for logr + +Using a plain `slog.Handler` without support for logr works better than the +other direction: +- All logr verbosity levels can be mapped 1:1 to their corresponding slog level + by negating them. +- Stack unwinding is done by the `slogr.SlogSink` and the resulting program + counter is passed to the `slog.Handler`. +- Names added via `Logger.WithName` are gathered and recorded in an additional + attribute with `logger` as key and the names separated by slash as value. +- `Logger.Error` is turned into a log record with `slog.LevelError` as level + and an additional attribute with `err` as key, if an error was provided. + +The main drawback is that `logr.Marshaler` will not be supported. Types should +ideally support both `logr.Marshaler` and `slog.Valuer`. If compatibility +with logr implementations without slog support is not important, then +`slog.Valuer` is sufficient. + +## Context support for slog + +Storing a logger in a `context.Context` is not supported by +slog. `logr.NewContext` and `logr.FromContext` can be used with slog like this +to fill this gap: + + func HandlerFromContext(ctx context.Context) slog.Handler { + logger, err := logr.FromContext(ctx) + if err == nil { + return slogr.NewSlogHandler(logger) + } + return slog.Default().Handler() + } + + func ContextWithHandler(ctx context.Context, handler slog.Handler) context.Context { + return logr.NewContext(ctx, slogr.NewLogr(handler)) + } + +The downside is that storing and retrieving a `slog.Handler` needs more +allocations compared to using a `logr.Logger`. Therefore the recommendation is +to use the `logr.Logger` API in code which uses contextual logging. + ## FAQ ### Conceptual @@ -241,7 +350,9 @@ Otherwise, you can start out with `0` as "you always want to see this", Then gradually choose levels in between as you need them, working your way down from 10 (for debug and trace style logs) and up from 1 (for chattier -info-type logs.) +info-type logs). For reference, slog pre-defines -4 for debug logs +(corresponds to 4 in logr), which matches what is +[recommended for Kubernetes](https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md#what-method-to-use). #### How do I choose my keys? diff --git a/SECURITY.md b/SECURITY.md new file mode 100644 index 0000000..1ca756f --- /dev/null +++ b/SECURITY.md @@ -0,0 +1,18 @@ +# Security Policy + +If you have discovered a security vulnerability in this project, please report it +privately. **Do not disclose it as a public issue.** This gives us time to work with you +to fix the issue before public exposure, reducing the chance that the exploit will be +used before a patch is released. + +You may submit the report in the following ways: + +- send an email to go-logr-security@googlegroups.com +- send us a [private vulnerability report](https://github.com/go-logr/logr/security/advisories/new) + +Please provide the following information in your report: + +- A description of the vulnerability and its impact +- How to reproduce the issue + +We ask that you give us 90 days to work on a fix before public exposure. diff --git a/benchmark/benchmark_test.go b/benchmark/benchmark_test.go index cd111bc..090e3ce 100644 --- a/benchmark/benchmark_test.go +++ b/benchmark/benchmark_test.go @@ -130,7 +130,7 @@ func doErrorValue(b *testing.B, log logr.Logger) { type Tmarshaler struct{ s string } -func (t Tmarshaler) MarshalLog() interface{} { +func (t Tmarshaler) MarshalLog() any { return t.s } @@ -181,8 +181,8 @@ func BenchmarkDiscardWithName(b *testing.B) { doWithName(b, log) } -func noopKV(prefix, args string) {} -func noopJSON(obj string) {} +func noopKV(_, _ string) {} +func noopJSON(_ string) {} func BenchmarkFuncrLogInfoOneArg(b *testing.B) { var log logr.Logger = funcr.New(noopKV, funcr.Options{}) diff --git a/example_marshaler_secret_test.go b/example_marshaler_secret_test.go index 1e59af3..39ac4a4 100644 --- a/example_marshaler_secret_test.go +++ b/example_marshaler_secret_test.go @@ -27,7 +27,7 @@ type ComplexObjectRef struct { Secret string } -func (ref ComplexObjectRef) MarshalLog() interface{} { +func (ref ComplexObjectRef) MarshalLog() any { return struct { Name, Namespace string }{ diff --git a/example_marshaler_test.go b/example_marshaler_test.go index 12fdaf3..f9cd00a 100644 --- a/example_marshaler_test.go +++ b/example_marshaler_test.go @@ -33,7 +33,7 @@ func (ref ObjectRef) String() string { return ref.Name } -func (ref ObjectRef) MarshalLog() interface{} { +func (ref ObjectRef) MarshalLog() any { // We implement fmt.Stringer for non-structured logging, but we want the // raw struct when using structured logs. Some logr implementations call // String if it is present, so we want to convert this struct to something diff --git a/examples/tab_logger.go b/examples/tab_logger.go index 1849797..b7335f5 100644 --- a/examples/tab_logger.go +++ b/examples/tab_logger.go @@ -28,7 +28,7 @@ import ( // It's terribly inefficient, and is only a basic example. type tabLogSink struct { name string - keyValues map[string]interface{} + keyValues map[string]any writer *tabwriter.Writer } @@ -43,7 +43,7 @@ func (_ tabLogSink) Enabled(level int) bool { return true } -func (l tabLogSink) Info(level int, msg string, kvs ...interface{}) { +func (l tabLogSink) Info(level int, msg string, kvs ...any) { fmt.Fprintf(l.writer, "%s\t%s\t", l.name, msg) for k, v := range l.keyValues { fmt.Fprintf(l.writer, "%s: %+v ", k, v) @@ -55,7 +55,7 @@ func (l tabLogSink) Info(level int, msg string, kvs ...interface{}) { l.writer.Flush() } -func (l tabLogSink) Error(err error, msg string, kvs ...interface{}) { +func (l tabLogSink) Error(err error, msg string, kvs ...any) { kvs = append(kvs, "error", err) l.Info(0, msg, kvs...) } @@ -68,8 +68,8 @@ func (l tabLogSink) WithName(name string) logr.LogSink { } } -func (l tabLogSink) WithValues(kvs ...interface{}) logr.LogSink { - newMap := make(map[string]interface{}, len(l.keyValues)+len(kvs)/2) +func (l tabLogSink) WithValues(kvs ...any) logr.LogSink { + newMap := make(map[string]any, len(l.keyValues)+len(kvs)/2) for k, v := range l.keyValues { newMap[k] = v } diff --git a/examples/usage_example.go b/examples/usage_example.go index a826d9c..7f736fe 100644 --- a/examples/usage_example.go +++ b/examples/usage_example.go @@ -34,17 +34,17 @@ import ( // (but a bit trickier) to use file-level "base" loggers. var objectMap = map[string]Object{ - "obj1": Object{ + "obj1": { Name: "obj1", Kind: "one", Details: 33, }, - "obj2": Object{ + "obj2": { Name: "obj2", Kind: "two", Details: "hi", }, - "obj3": Object{ + "obj3": { Name: "obj3", Kind: "one", Details: 1, @@ -54,7 +54,7 @@ var objectMap = map[string]Object{ type Object struct { Name string Kind string - Details interface{} + Details any } type Client struct { diff --git a/funcr/example_formatter_test.go b/funcr/example_formatter_test.go index e5ed6ec..474e510 100644 --- a/funcr/example_formatter_test.go +++ b/funcr/example_formatter_test.go @@ -45,7 +45,7 @@ func (l stdoutlogger) WithName(name string) logr.LogSink { return &l } -func (l stdoutlogger) WithValues(kvList ...interface{}) logr.LogSink { +func (l stdoutlogger) WithValues(kvList ...any) logr.LogSink { l.Formatter.AddValues(kvList) return &l } @@ -55,12 +55,12 @@ func (l stdoutlogger) WithCallDepth(depth int) logr.LogSink { return &l } -func (l stdoutlogger) Info(level int, msg string, kvList ...interface{}) { +func (l stdoutlogger) Info(level int, msg string, kvList ...any) { prefix, args := l.FormatInfo(level, msg, kvList) l.write("INFO", prefix, args) } -func (l stdoutlogger) Error(err error, msg string, kvList ...interface{}) { +func (l stdoutlogger) Error(err error, msg string, kvList ...any) { prefix, args := l.FormatError(err, msg, kvList) l.write("ERROR", prefix, args) } diff --git a/funcr/example_test.go b/funcr/example_test.go index 53373a2..4918154 100644 --- a/funcr/example_test.go +++ b/funcr/example_test.go @@ -74,7 +74,7 @@ func ExampleOptions() { func ExampleOptions_renderHooks() { // prefix all builtin keys with "log:" - prefixSpecialKeys := func(kvList []interface{}) []interface{} { + prefixSpecialKeys := func(kvList []any) []any { for i := 0; i < len(kvList); i += 2 { k, _ := kvList[i].(string) kvList[i] = "log:" + k @@ -83,8 +83,8 @@ func ExampleOptions_renderHooks() { } // present saved values as a single JSON object - valuesAsObject := func(kvList []interface{}) []interface{} { - return []interface{}{"labels", funcr.PseudoStruct(kvList)} + valuesAsObject := func(kvList []any) []any { + return []any{"labels", funcr.PseudoStruct(kvList)} } var log logr.Logger = funcr.NewJSON( @@ -104,7 +104,7 @@ func ExamplePseudoStruct() { var log logr.Logger = funcr.NewJSON( func(obj string) { fmt.Println(obj) }, funcr.Options{}) - kv := []interface{}{ + kv := []any{ "field1", 12345, "field2", true, } diff --git a/funcr/funcr.go b/funcr/funcr.go index e52f0cd..12e5807 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -116,17 +116,17 @@ type Options struct { // Equivalent hooks are offered for key-value pairs saved via // logr.Logger.WithValues or Formatter.AddValues (see RenderValuesHook) and // for user-provided pairs (see RenderArgsHook). - RenderBuiltinsHook func(kvList []interface{}) []interface{} + RenderBuiltinsHook func(kvList []any) []any // RenderValuesHook is the same as RenderBuiltinsHook, except that it is // only called for key-value pairs saved via logr.Logger.WithValues. See // RenderBuiltinsHook for more details. - RenderValuesHook func(kvList []interface{}) []interface{} + RenderValuesHook func(kvList []any) []any // RenderArgsHook is the same as RenderBuiltinsHook, except that it is only // called for key-value pairs passed directly to Info and Error. See // RenderBuiltinsHook for more details. - RenderArgsHook func(kvList []interface{}) []interface{} + RenderArgsHook func(kvList []any) []any // MaxLogDepth tells funcr how many levels of nested fields (e.g. a struct // that contains a struct, etc.) it may log. Every time it finds a struct, @@ -163,7 +163,7 @@ func (l fnlogger) WithName(name string) logr.LogSink { return &l } -func (l fnlogger) WithValues(kvList ...interface{}) logr.LogSink { +func (l fnlogger) WithValues(kvList ...any) logr.LogSink { l.Formatter.AddValues(kvList) return &l } @@ -173,12 +173,12 @@ func (l fnlogger) WithCallDepth(depth int) logr.LogSink { return &l } -func (l fnlogger) Info(level int, msg string, kvList ...interface{}) { +func (l fnlogger) Info(level int, msg string, kvList ...any) { prefix, args := l.FormatInfo(level, msg, kvList) l.write(prefix, args) } -func (l fnlogger) Error(err error, msg string, kvList ...interface{}) { +func (l fnlogger) Error(err error, msg string, kvList ...any) { prefix, args := l.FormatError(err, msg, kvList) l.write(prefix, args) } @@ -229,7 +229,7 @@ func newFormatter(opts Options, outfmt outputFormat) Formatter { type Formatter struct { outputFormat outputFormat prefix string - values []interface{} + values []any valuesStr string depth int opts *Options @@ -246,10 +246,10 @@ const ( ) // PseudoStruct is a list of key-value pairs that gets logged as a struct. -type PseudoStruct []interface{} +type PseudoStruct []any // render produces a log line, ready to use. -func (f Formatter) render(builtins, args []interface{}) string { +func (f Formatter) render(builtins, args []any) string { // Empirically bytes.Buffer is faster than strings.Builder for this. buf := bytes.NewBuffer(make([]byte, 0, 1024)) if f.outputFormat == outputJSON { @@ -292,7 +292,7 @@ func (f Formatter) render(builtins, args []interface{}) string { // This function returns a potentially modified version of kvList, which // ensures that there is a value for every key (adding a value if needed) and // that each key is a string (substituting a key if needed). -func (f Formatter) flatten(buf *bytes.Buffer, kvList []interface{}, continuing bool, escapeKeys bool) []interface{} { +func (f Formatter) flatten(buf *bytes.Buffer, kvList []any, continuing bool, escapeKeys bool) []any { // This logic overlaps with sanitize() but saves one type-cast per key, // which can be measurable. if len(kvList)%2 != 0 { @@ -334,7 +334,7 @@ func (f Formatter) flatten(buf *bytes.Buffer, kvList []interface{}, continuing b return kvList } -func (f Formatter) pretty(value interface{}) string { +func (f Formatter) pretty(value any) string { return f.prettyWithFlags(value, 0, 0) } @@ -343,7 +343,7 @@ const ( ) // TODO: This is not fast. Most of the overhead goes here. -func (f Formatter) prettyWithFlags(value interface{}, flags uint32, depth int) string { +func (f Formatter) prettyWithFlags(value any, flags uint32, depth int) string { if depth > f.opts.MaxLogDepth { return `""` } @@ -614,7 +614,7 @@ func isEmpty(v reflect.Value) bool { return false } -func invokeMarshaler(m logr.Marshaler) (ret interface{}) { +func invokeMarshaler(m logr.Marshaler) (ret any) { defer func() { if r := recover(); r != nil { ret = fmt.Sprintf("", r) @@ -675,12 +675,12 @@ func (f Formatter) caller() Caller { const noValue = "" -func (f Formatter) nonStringKey(v interface{}) string { +func (f Formatter) nonStringKey(v any) string { return fmt.Sprintf("", f.snippet(v)) } // snippet produces a short snippet string of an arbitrary value. -func (f Formatter) snippet(v interface{}) string { +func (f Formatter) snippet(v any) string { const snipLen = 16 snip := f.pretty(v) @@ -693,7 +693,7 @@ func (f Formatter) snippet(v interface{}) string { // sanitize ensures that a list of key-value pairs has a value for every key // (adding a value if needed) and that each key is a string (substituting a key // if needed). -func (f Formatter) sanitize(kvList []interface{}) []interface{} { +func (f Formatter) sanitize(kvList []any) []any { if len(kvList)%2 != 0 { kvList = append(kvList, noValue) } @@ -727,8 +727,8 @@ func (f Formatter) GetDepth() int { // FormatInfo renders an Info log message into strings. The prefix will be // empty when no names were set (via AddNames), or when the output is // configured for JSON. -func (f Formatter) FormatInfo(level int, msg string, kvList []interface{}) (prefix, argsStr string) { - args := make([]interface{}, 0, 64) // using a constant here impacts perf +func (f Formatter) FormatInfo(level int, msg string, kvList []any) (prefix, argsStr string) { + args := make([]any, 0, 64) // using a constant here impacts perf prefix = f.prefix if f.outputFormat == outputJSON { args = append(args, "logger", prefix) @@ -745,10 +745,10 @@ func (f Formatter) FormatInfo(level int, msg string, kvList []interface{}) (pref } // FormatError renders an Error log message into strings. The prefix will be -// empty when no names were set (via AddNames), or when the output is +// empty when no names were set (via AddNames), or when the output is // configured for JSON. -func (f Formatter) FormatError(err error, msg string, kvList []interface{}) (prefix, argsStr string) { - args := make([]interface{}, 0, 64) // using a constant here impacts perf +func (f Formatter) FormatError(err error, msg string, kvList []any) (prefix, argsStr string) { + args := make([]any, 0, 64) // using a constant here impacts perf prefix = f.prefix if f.outputFormat == outputJSON { args = append(args, "logger", prefix) @@ -761,12 +761,12 @@ func (f Formatter) FormatError(err error, msg string, kvList []interface{}) (pre args = append(args, "caller", f.caller()) } args = append(args, "msg", msg) - var loggableErr interface{} + var loggableErr any if err != nil { loggableErr = err.Error() } args = append(args, "error", loggableErr) - return f.prefix, f.render(args, kvList) + return prefix, f.render(args, kvList) } // AddName appends the specified name. funcr uses '/' characters to separate @@ -781,7 +781,7 @@ func (f *Formatter) AddName(name string) { // AddValues adds key-value pairs to the set of saved values to be logged with // each log line. -func (f *Formatter) AddValues(kvList []interface{}) { +func (f *Formatter) AddValues(kvList []any) { // Three slice args forces a copy. n := len(f.values) f.values = append(f.values[:n:n], kvList...) diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go index 8af3970..b3a6f70 100644 --- a/funcr/funcr_test.go +++ b/funcr/funcr_test.go @@ -54,7 +54,7 @@ func (p pointErr) MarshalText() ([]byte, error) { // Logging this should result in the MarshalLog() value. type Tmarshaler struct{ val string } -func (t Tmarshaler) MarshalLog() interface{} { +func (t Tmarshaler) MarshalLog() any { return struct{ Inner string }{"I am a logr.Marshaler"} } @@ -69,7 +69,7 @@ func (t Tmarshaler) Error() string { // Logging this should result in a panic. type Tmarshalerpanic struct{ val string } -func (t Tmarshalerpanic) MarshalLog() interface{} { +func (t Tmarshalerpanic) MarshalLog() any { panic("Tmarshalerpanic") } @@ -251,7 +251,7 @@ func TestPretty(t *testing.T) { } cases := []struct { - val interface{} + val any exp string // used in cases where JSON can't handle it }{{ val: "strval", @@ -402,11 +402,11 @@ func TestPretty(t *testing.T) { val: struct { A *int B *int - C interface{} - D interface{} + C any + D any }{ B: ptrint(1), - D: interface{}(2), + D: any(2), }, }, { val: Tmarshaler{"foobar"}, @@ -678,7 +678,7 @@ func TestPretty(t *testing.T) { } } -func makeKV(args ...interface{}) []interface{} { +func makeKV(args ...any) []any { return args } @@ -694,9 +694,9 @@ func TestRender(t *testing.T) { testCases := []struct { name string - builtins []interface{} - values []interface{} - args []interface{} + builtins []any + values []any + args []any expectKV string expectJSON string }{{ @@ -705,9 +705,9 @@ func TestRender(t *testing.T) { expectJSON: "{}", }, { name: "empty", - builtins: []interface{}{}, - values: []interface{}{}, - args: []interface{}{}, + builtins: []any{}, + values: []any{}, + args: []any{}, expectKV: "", expectJSON: "{}", }, { @@ -800,12 +800,12 @@ func TestRender(t *testing.T) { func TestSanitize(t *testing.T) { testCases := []struct { name string - kv []interface{} - expect []interface{} + kv []any + expect []any }{{ name: "empty", - kv: []interface{}{}, - expect: []interface{}{}, + kv: []any{}, + expect: []any{}, }, { name: "already sane", kv: makeKV("int", 1, "str", "ABC", "bool", true), @@ -867,212 +867,295 @@ type capture struct { } func (c *capture) Func(prefix, args string) { - c.log = prefix + " " + args + space := " " + if len(prefix) == 0 { + space = "" + } + c.log = prefix + space + args } func TestInfo(t *testing.T) { testCases := []struct { - name string - args []interface{} - expect string + name string + args []any + expectKV string + expectJSON string }{{ - name: "just msg", - args: makeKV(), - expect: ` "level"=0 "msg"="msg"`, + name: "just msg", + args: makeKV(), + expectKV: `"level"=0 "msg"="msg"`, + expectJSON: `{"logger":"","level":0,"msg":"msg"}`, }, { - name: "primitives", - args: makeKV("int", 1, "str", "ABC", "bool", true), - expect: ` "level"=0 "msg"="msg" "int"=1 "str"="ABC" "bool"=true`, + name: "primitives", + args: makeKV("int", 1, "str", "ABC", "bool", true), + expectKV: `"level"=0 "msg"="msg" "int"=1 "str"="ABC" "bool"=true`, + expectJSON: `{"logger":"","level":0,"msg":"msg","int":1,"str":"ABC","bool":true}`, }} for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{})) + t.Run("KV: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{})) + sink.Info(0, "msg", tc.args...) + if capt.log != tc.expectKV { + t.Errorf("\nexpected %q\n got %q", tc.expectKV, capt.log) + } + }) + t.Run("JSON: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{})) sink.Info(0, "msg", tc.args...) - if cap.log != tc.expect { - t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log) + if capt.log != tc.expectJSON { + t.Errorf("\nexpected %q\n got %q", tc.expectJSON, capt.log) } }) } } func TestInfoWithCaller(t *testing.T) { - t.Run("LogCaller=All", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All})) + t.Run("KV: LogCaller=All", func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: All})) sink.Info(0, "msg") _, file, line, _ := runtime.Caller(0) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line-1) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } sink.Error(fmt.Errorf("error"), "msg") _, file, line, _ = runtime.Caller(0) - expect = fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="error"`, filepath.Base(file), line-1) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect = fmt.Sprintf(`"caller"={"file":%q,"line":%d} "msg"="msg" "error"="error"`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) - t.Run("LogCaller=All, LogCallerFunc=true", func(t *testing.T) { - thisFunc := "github.com/go-logr/logr/funcr.TestInfoWithCaller.func2" - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All, LogCallerFunc: true})) + t.Run("JSON: LogCaller=All", func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{LogCaller: All})) sink.Info(0, "msg") _, file, line, _ := runtime.Caller(0) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d,"function":%q} "level"=0 "msg"="msg"`, filepath.Base(file), line-1, thisFunc) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`{"logger":"","caller":{"file":%q,"line":%d},"level":0,"msg":"msg"}`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } sink.Error(fmt.Errorf("error"), "msg") _, file, line, _ = runtime.Caller(0) - expect = fmt.Sprintf(` "caller"={"file":%q,"line":%d,"function":%q} "msg"="msg" "error"="error"`, filepath.Base(file), line-1, thisFunc) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect = fmt.Sprintf(`{"logger":"","caller":{"file":%q,"line":%d},"msg":"msg","error":"error"}`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) + } + }) + t.Run("KV: LogCaller=All, LogCallerFunc=true", func(t *testing.T) { + thisFunc := "github.com/go-logr/logr/funcr.TestInfoWithCaller.func3" + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: All, LogCallerFunc: true})) + sink.Info(0, "msg") + _, file, line, _ := runtime.Caller(0) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d,"function":%q} "level"=0 "msg"="msg"`, filepath.Base(file), line-1, thisFunc) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) + } + sink.Error(fmt.Errorf("error"), "msg") + _, file, line, _ = runtime.Caller(0) + expect = fmt.Sprintf(`"caller"={"file":%q,"line":%d,"function":%q} "msg"="msg" "error"="error"`, filepath.Base(file), line-1, thisFunc) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) + } + }) + t.Run("JSON: LogCaller=All, LogCallerFunc=true", func(t *testing.T) { + thisFunc := "github.com/go-logr/logr/funcr.TestInfoWithCaller.func4" + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{LogCaller: All, LogCallerFunc: true})) + sink.Info(0, "msg") + _, file, line, _ := runtime.Caller(0) + expect := fmt.Sprintf(`{"logger":"","caller":{"file":%q,"line":%d,"function":%q},"level":0,"msg":"msg"}`, filepath.Base(file), line-1, thisFunc) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) + } + sink.Error(fmt.Errorf("error"), "msg") + _, file, line, _ = runtime.Caller(0) + expect = fmt.Sprintf(`{"logger":"","caller":{"file":%q,"line":%d,"function":%q},"msg":"msg","error":"error"}`, filepath.Base(file), line-1, thisFunc) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) t.Run("LogCaller=Info", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Info})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: Info})) sink.Info(0, "msg") _, file, line, _ := runtime.Caller(0) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line-1) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } sink.Error(fmt.Errorf("error"), "msg") - expect = ` "msg"="msg" "error"="error"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect = `"msg"="msg" "error"="error"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) t.Run("LogCaller=Error", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Error})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: Error})) sink.Info(0, "msg") - expect := ` "level"=0 "msg"="msg"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := `"level"=0 "msg"="msg"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } sink.Error(fmt.Errorf("error"), "msg") _, file, line, _ := runtime.Caller(0) - expect = fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="error"`, filepath.Base(file), line-1) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect = fmt.Sprintf(`"caller"={"file":%q,"line":%d} "msg"="msg" "error"="error"`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) t.Run("LogCaller=None", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: None})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: None})) sink.Info(0, "msg") - expect := ` "level"=0 "msg"="msg"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := `"level"=0 "msg"="msg"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } sink.Error(fmt.Errorf("error"), "msg") - expect = ` "msg"="msg" "error"="error"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect = `"msg"="msg" "error"="error"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) } func TestError(t *testing.T) { testCases := []struct { - name string - args []interface{} - expect string + name string + args []any + expectKV string + expectJSON string }{{ - name: "just msg", - args: makeKV(), - expect: ` "msg"="msg" "error"="err"`, + name: "just msg", + args: makeKV(), + expectKV: `"msg"="msg" "error"="err"`, + expectJSON: `{"logger":"","msg":"msg","error":"err"}`, }, { - name: "primitives", - args: makeKV("int", 1, "str", "ABC", "bool", true), - expect: ` "msg"="msg" "error"="err" "int"=1 "str"="ABC" "bool"=true`, + name: "primitives", + args: makeKV("int", 1, "str", "ABC", "bool", true), + expectKV: `"msg"="msg" "error"="err" "int"=1 "str"="ABC" "bool"=true`, + expectJSON: `{"logger":"","msg":"msg","error":"err","int":1,"str":"ABC","bool":true}`, }} for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{})) + t.Run("KV: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{})) sink.Error(fmt.Errorf("err"), "msg", tc.args...) - if cap.log != tc.expect { - t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log) + if capt.log != tc.expectKV { + t.Errorf("\nexpected %q\n got %q", tc.expectKV, capt.log) + } + }) + t.Run("JSON: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{})) + sink.Error(fmt.Errorf("err"), "msg", tc.args...) + if capt.log != tc.expectJSON { + t.Errorf("\nexpected %q\n got %q", tc.expectJSON, capt.log) } }) } } func TestErrorWithCaller(t *testing.T) { - t.Run("LogCaller=All", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All})) + t.Run("KV: LogCaller=All", func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: All})) sink.Error(fmt.Errorf("err"), "msg") _, file, line, _ := runtime.Caller(0) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) + } + }) + t.Run("JSON: LogCaller=All", func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{LogCaller: All})) + sink.Error(fmt.Errorf("err"), "msg") + _, file, line, _ := runtime.Caller(0) + expect := fmt.Sprintf(`{"logger":"","caller":{"file":%q,"line":%d},"msg":"msg","error":"err"}`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) t.Run("LogCaller=Error", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Error})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: Error})) sink.Error(fmt.Errorf("err"), "msg") _, file, line, _ := runtime.Caller(0) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line-1) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) t.Run("LogCaller=Info", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: Info})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: Info})) sink.Error(fmt.Errorf("err"), "msg") - expect := ` "msg"="msg" "error"="err"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := `"msg"="msg" "error"="err"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) t.Run("LogCaller=None", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: None})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: None})) sink.Error(fmt.Errorf("err"), "msg") - expect := ` "msg"="msg" "error"="err"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := `"msg"="msg" "error"="err"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) } func TestInfoWithName(t *testing.T) { testCases := []struct { - name string - names []string - args []interface{} - expect string + name string + names []string + args []any + expectKV string + expectJSON string }{{ - name: "one", - names: []string{"pfx1"}, - args: makeKV("k", "v"), - expect: `pfx1 "level"=0 "msg"="msg" "k"="v"`, - }, { - name: "two", - names: []string{"pfx1", "pfx2"}, - args: makeKV("k", "v"), - expect: `pfx1/pfx2 "level"=0 "msg"="msg" "k"="v"`, + name: "one", + names: []string{"pfx1"}, + args: makeKV("k", "v"), + expectKV: `pfx1 "level"=0 "msg"="msg" "k"="v"`, + expectJSON: `{"logger":"pfx1","level":0,"msg":"msg","k":"v"}`, + }, { + name: "two", + names: []string{"pfx1", "pfx2"}, + args: makeKV("k", "v"), + expectKV: `pfx1/pfx2 "level"=0 "msg"="msg" "k"="v"`, + expectJSON: `{"logger":"pfx1/pfx2","level":0,"msg":"msg","k":"v"}`, }} for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{})) + t.Run("KV: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{})) + for _, n := range tc.names { + sink = sink.WithName(n) + } + sink.Info(0, "msg", tc.args...) + if capt.log != tc.expectKV { + t.Errorf("\nexpected %q\n got %q", tc.expectKV, capt.log) + } + }) + t.Run("JSON: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{})) for _, n := range tc.names { sink = sink.WithName(n) } sink.Info(0, "msg", tc.args...) - if cap.log != tc.expect { - t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log) + if capt.log != tc.expectJSON { + t.Errorf("\nexpected %q\n got %q", tc.expectJSON, capt.log) } }) } @@ -1080,32 +1163,46 @@ func TestInfoWithName(t *testing.T) { func TestErrorWithName(t *testing.T) { testCases := []struct { - name string - names []string - args []interface{} - expect string + name string + names []string + args []any + expectKV string + expectJSON string }{{ - name: "one", - names: []string{"pfx1"}, - args: makeKV("k", "v"), - expect: `pfx1 "msg"="msg" "error"="err" "k"="v"`, - }, { - name: "two", - names: []string{"pfx1", "pfx2"}, - args: makeKV("k", "v"), - expect: `pfx1/pfx2 "msg"="msg" "error"="err" "k"="v"`, + name: "one", + names: []string{"pfx1"}, + args: makeKV("k", "v"), + expectKV: `pfx1 "msg"="msg" "error"="err" "k"="v"`, + expectJSON: `{"logger":"pfx1","msg":"msg","error":"err","k":"v"}`, + }, { + name: "two", + names: []string{"pfx1", "pfx2"}, + args: makeKV("k", "v"), + expectKV: `pfx1/pfx2 "msg"="msg" "error"="err" "k"="v"`, + expectJSON: `{"logger":"pfx1/pfx2","msg":"msg","error":"err","k":"v"}`, }} for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{})) + t.Run("KV: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{})) + for _, n := range tc.names { + sink = sink.WithName(n) + } + sink.Error(fmt.Errorf("err"), "msg", tc.args...) + if capt.log != tc.expectKV { + t.Errorf("\nexpected %q\n got %q", tc.expectKV, capt.log) + } + }) + t.Run("JSON: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{})) for _, n := range tc.names { sink = sink.WithName(n) } sink.Error(fmt.Errorf("err"), "msg", tc.args...) - if cap.log != tc.expect { - t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log) + if capt.log != tc.expectJSON { + t.Errorf("\nexpected %q\n got %q", tc.expectJSON, capt.log) } }) } @@ -1113,40 +1210,54 @@ func TestErrorWithName(t *testing.T) { func TestInfoWithValues(t *testing.T) { testCases := []struct { - name string - values []interface{} - args []interface{} - expect string + name string + values []any + args []any + expectKV string + expectJSON string }{{ - name: "zero", - values: makeKV(), - args: makeKV("k", "v"), - expect: ` "level"=0 "msg"="msg" "k"="v"`, - }, { - name: "one", - values: makeKV("one", 1), - args: makeKV("k", "v"), - expect: ` "level"=0 "msg"="msg" "one"=1 "k"="v"`, - }, { - name: "two", - values: makeKV("one", 1, "two", 2), - args: makeKV("k", "v"), - expect: ` "level"=0 "msg"="msg" "one"=1 "two"=2 "k"="v"`, - }, { - name: "dangling", - values: makeKV("dangling"), - args: makeKV("k", "v"), - expect: ` "level"=0 "msg"="msg" "dangling"="" "k"="v"`, + name: "zero", + values: makeKV(), + args: makeKV("k", "v"), + expectKV: `"level"=0 "msg"="msg" "k"="v"`, + expectJSON: `{"logger":"","level":0,"msg":"msg","k":"v"}`, + }, { + name: "one", + values: makeKV("one", 1), + args: makeKV("k", "v"), + expectKV: `"level"=0 "msg"="msg" "one"=1 "k"="v"`, + expectJSON: `{"logger":"","level":0,"msg":"msg","one":1,"k":"v"}`, + }, { + name: "two", + values: makeKV("one", 1, "two", 2), + args: makeKV("k", "v"), + expectKV: `"level"=0 "msg"="msg" "one"=1 "two"=2 "k"="v"`, + expectJSON: `{"logger":"","level":0,"msg":"msg","one":1,"two":2,"k":"v"}`, + }, { + name: "dangling", + values: makeKV("dangling"), + args: makeKV("k", "v"), + expectKV: `"level"=0 "msg"="msg" "dangling"="" "k"="v"`, + expectJSON: `{"logger":"","level":0,"msg":"msg","dangling":"","k":"v"}`, }} for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{})) + t.Run("KV: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{})) + sink = sink.WithValues(tc.values...) + sink.Info(0, "msg", tc.args...) + if capt.log != tc.expectKV { + t.Errorf("\nexpected %q\n got %q", tc.expectKV, capt.log) + } + }) + t.Run("JSON: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{})) sink = sink.WithValues(tc.values...) sink.Info(0, "msg", tc.args...) - if cap.log != tc.expect { - t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log) + if capt.log != tc.expectJSON { + t.Errorf("\nexpected %q\n got %q", tc.expectJSON, capt.log) } }) } @@ -1154,40 +1265,54 @@ func TestInfoWithValues(t *testing.T) { func TestErrorWithValues(t *testing.T) { testCases := []struct { - name string - values []interface{} - args []interface{} - expect string + name string + values []any + args []any + expectKV string + expectJSON string }{{ - name: "zero", - values: makeKV(), - args: makeKV("k", "v"), - expect: ` "msg"="msg" "error"="err" "k"="v"`, - }, { - name: "one", - values: makeKV("one", 1), - args: makeKV("k", "v"), - expect: ` "msg"="msg" "error"="err" "one"=1 "k"="v"`, - }, { - name: "two", - values: makeKV("one", 1, "two", 2), - args: makeKV("k", "v"), - expect: ` "msg"="msg" "error"="err" "one"=1 "two"=2 "k"="v"`, - }, { - name: "dangling", - values: makeKV("dangling"), - args: makeKV("k", "v"), - expect: ` "msg"="msg" "error"="err" "dangling"="" "k"="v"`, + name: "zero", + values: makeKV(), + args: makeKV("k", "v"), + expectKV: `"msg"="msg" "error"="err" "k"="v"`, + expectJSON: `{"logger":"","msg":"msg","error":"err","k":"v"}`, + }, { + name: "one", + values: makeKV("one", 1), + args: makeKV("k", "v"), + expectKV: `"msg"="msg" "error"="err" "one"=1 "k"="v"`, + expectJSON: `{"logger":"","msg":"msg","error":"err","one":1,"k":"v"}`, + }, { + name: "two", + values: makeKV("one", 1, "two", 2), + args: makeKV("k", "v"), + expectKV: `"msg"="msg" "error"="err" "one"=1 "two"=2 "k"="v"`, + expectJSON: `{"logger":"","msg":"msg","error":"err","one":1,"two":2,"k":"v"}`, + }, { + name: "dangling", + values: makeKV("dangling"), + args: makeKV("k", "v"), + expectKV: `"msg"="msg" "error"="err" "dangling"="" "k"="v"`, + expectJSON: `{"logger":"","msg":"msg","error":"err","dangling":"","k":"v"}`, }} for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{})) + t.Run("KV: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{})) + sink = sink.WithValues(tc.values...) + sink.Error(fmt.Errorf("err"), "msg", tc.args...) + if capt.log != tc.expectKV { + t.Errorf("\nexpected %q\n got %q", tc.expectKV, capt.log) + } + }) + t.Run("JSON: "+tc.name, func(t *testing.T) { + capt := &capture{} + sink := newSink(capt.Func, NewFormatterJSON(Options{})) sink = sink.WithValues(tc.values...) sink.Error(fmt.Errorf("err"), "msg", tc.args...) - if cap.log != tc.expect { - t.Errorf("\nexpected %q\n got %q", tc.expect, cap.log) + if capt.log != tc.expectJSON { + t.Errorf("\nexpected %q\n got %q", tc.expectJSON, capt.log) } }) } @@ -1195,44 +1320,44 @@ func TestErrorWithValues(t *testing.T) { func TestInfoWithCallDepth(t *testing.T) { t.Run("one", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: All})) dSink, _ := sink.(logr.CallDepthLogSink) sink = dSink.WithCallDepth(1) sink.Info(0, "msg") _, file, line, _ := runtime.Caller(1) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d} "level"=0 "msg"="msg"`, filepath.Base(file), line) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) } func TestErrorWithCallDepth(t *testing.T) { t.Run("one", func(t *testing.T) { - cap := &capture{} - sink := newSink(cap.Func, NewFormatter(Options{LogCaller: All})) + capt := &capture{} + sink := newSink(capt.Func, NewFormatter(Options{LogCaller: All})) dSink, _ := sink.(logr.CallDepthLogSink) sink = dSink.WithCallDepth(1) sink.Error(fmt.Errorf("err"), "msg") _, file, line, _ := runtime.Caller(1) - expect := fmt.Sprintf(` "caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line) - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := fmt.Sprintf(`"caller"={"file":%q,"line":%d} "msg"="msg" "error"="err"`, filepath.Base(file), line) + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } }) } func TestOptionsTimestampFormat(t *testing.T) { - cap := &capture{} + capt := &capture{} // This timestamp format contains none of the characters that are // considered placeholders, so will produce a constant result. - sink := newSink(cap.Func, NewFormatter(Options{LogTimestamp: true, TimestampFormat: "TIMESTAMP"})) + sink := newSink(capt.Func, NewFormatter(Options{LogTimestamp: true, TimestampFormat: "TIMESTAMP"})) dSink, _ := sink.(logr.CallDepthLogSink) sink = dSink.WithCallDepth(1) sink.Info(0, "msg") - expect := ` "ts"="TIMESTAMP" "level"=0 "msg"="msg"` - if cap.log != expect { - t.Errorf("\nexpected %q\n got %q", expect, cap.log) + expect := `"ts"="TIMESTAMP" "level"=0 "msg"="msg"` + if capt.log != expect { + t.Errorf("\nexpected %q\n got %q", expect, capt.log) } } diff --git a/go.mod b/go.mod index 7baec9b..b4f52a4 100644 --- a/go.mod +++ b/go.mod @@ -1,3 +1,3 @@ module github.com/go-logr/logr -go 1.16 +go 1.18 diff --git a/logr.go b/logr.go index e027aea..2a5075a 100644 --- a/logr.go +++ b/logr.go @@ -127,9 +127,9 @@ limitations under the License. // such a value can call its methods without having to check whether the // instance is ready for use. // -// Calling methods with the null logger (Logger{}) as instance will crash -// because it has no LogSink. Therefore this null logger should never be passed -// around. For cases where passing a logger is optional, a pointer to Logger +// The zero logger (= Logger{}) is identical to Discard() and discards all log +// entries. Code that receives a Logger by value can simply call it, the methods +// will never crash. For cases where passing a logger is optional, a pointer to Logger // should be used. // // # Key Naming Conventions @@ -258,6 +258,12 @@ type Logger struct { // Enabled tests whether this Logger is enabled. For example, commandline // flags might be used to set the logging verbosity and disable some info logs. func (l Logger) Enabled() bool { + // Some implementations of LogSink look at the caller in Enabled (e.g. + // different verbosity levels per package or file), but we only pass one + // CallDepth in (via Init). This means that all calls from Logger to the + // LogSink's Enabled, Info, and Error methods must have the same number of + // frames. In other words, Logger methods can't call other Logger methods + // which call these LogSink methods unless we do it the same in all paths. return l.sink != nil && l.sink.Enabled(l.level) } @@ -267,11 +273,11 @@ func (l Logger) Enabled() bool { // line. The key/value pairs can then be used to add additional variable // information. The key/value pairs must alternate string keys and arbitrary // values. -func (l Logger) Info(msg string, keysAndValues ...interface{}) { +func (l Logger) Info(msg string, keysAndValues ...any) { if l.sink == nil { return } - if l.Enabled() { + if l.sink.Enabled(l.level) { // see comment in Enabled if withHelper, ok := l.sink.(CallStackHelperLogSink); ok { withHelper.GetCallStackHelper()() } @@ -289,7 +295,7 @@ func (l Logger) Info(msg string, keysAndValues ...interface{}) { // while the err argument should be used to attach the actual error that // triggered this log line, if present. The err parameter is optional // and nil may be passed instead of an error instance. -func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) { +func (l Logger) Error(err error, msg string, keysAndValues ...any) { if l.sink == nil { return } @@ -314,9 +320,16 @@ func (l Logger) V(level int) Logger { return l } +// GetV returns the verbosity level of the logger. If the logger's LogSink is +// nil as in the Discard logger, this will always return 0. +func (l Logger) GetV() int { + // 0 if l.sink nil because of the if check in V above. + return l.level +} + // WithValues returns a new Logger instance with additional key/value pairs. // See Info for documentation on how key/value pairs work. -func (l Logger) WithValues(keysAndValues ...interface{}) Logger { +func (l Logger) WithValues(keysAndValues ...any) Logger { if l.sink == nil { return l } @@ -467,15 +480,15 @@ type LogSink interface { // The level argument is provided for optional logging. This method will // only be called when Enabled(level) is true. See Logger.Info for more // details. - Info(level int, msg string, keysAndValues ...interface{}) + Info(level int, msg string, keysAndValues ...any) // Error logs an error, with the given message and key/value pairs as // context. See Logger.Error for more details. - Error(err error, msg string, keysAndValues ...interface{}) + Error(err error, msg string, keysAndValues ...any) // WithValues returns a new LogSink with additional key/value pairs. See // Logger.WithValues for more details. - WithValues(keysAndValues ...interface{}) LogSink + WithValues(keysAndValues ...any) LogSink // WithName returns a new LogSink with the specified name appended. See // Logger.WithName for more details. @@ -546,5 +559,5 @@ type Marshaler interface { // with exported fields // // It may return any value of any type. - MarshalLog() interface{} + MarshalLog() any } diff --git a/logr_test.go b/logr_test.go index 00ecf98..df60cb8 100644 --- a/logr_test.go +++ b/logr_test.go @@ -21,6 +21,7 @@ import ( "errors" "fmt" "reflect" + "runtime" "testing" ) @@ -28,9 +29,9 @@ import ( type testLogSink struct { fnInit func(ri RuntimeInfo) fnEnabled func(lvl int) bool - fnInfo func(lvl int, msg string, kv ...interface{}) - fnError func(err error, msg string, kv ...interface{}) - fnWithValues func(kv ...interface{}) + fnInfo func(lvl int, msg string, kv ...any) + fnError func(err error, msg string, kv ...any) + fnWithValues func(kv ...any) fnWithName func(name string) } @@ -49,19 +50,19 @@ func (l *testLogSink) Enabled(lvl int) bool { return false } -func (l *testLogSink) Info(lvl int, msg string, kv ...interface{}) { +func (l *testLogSink) Info(lvl int, msg string, kv ...any) { if l.fnInfo != nil { l.fnInfo(lvl, msg, kv...) } } -func (l *testLogSink) Error(err error, msg string, kv ...interface{}) { +func (l *testLogSink) Error(err error, msg string, kv ...any) { if l.fnError != nil { l.fnError(err, msg, kv...) } } -func (l *testLogSink) WithValues(kv ...interface{}) LogSink { +func (l *testLogSink) WithValues(kv ...any) LogSink { if l.fnWithValues != nil { l.fnWithValues(kv...) } @@ -148,10 +149,10 @@ func TestError(t *testing.T) { calledError := 0 errInput := fmt.Errorf("error") msgInput := "msg" - kvInput := []interface{}{0, 1, 2} + kvInput := []any{0, 1, 2} sink := &testLogSink{} - sink.fnError = func(err error, msg string, kv ...interface{}) { + sink.fnError = func(err error, msg string, kv ...any) { calledError++ if err != errInput { t.Errorf("unexpected err input, got %v", err) @@ -172,23 +173,53 @@ func TestError(t *testing.T) { } func TestV(t *testing.T) { - sink := &testLogSink{} - logger := New(sink) - - if l := logger.V(0); l.level != 0 { - t.Errorf("expected level 0, got %d", l.level) - } - if l := logger.V(93); l.level != 93 { - t.Errorf("expected level 93, got %d", l.level) - } - if l := logger.V(70).V(6); l.level != 76 { - t.Errorf("expected level 76, got %d", l.level) - } - if l := logger.V(-1); l.level != 0 { - t.Errorf("expected level 0, got %d", l.level) - } - if l := logger.V(1).V(-1); l.level != 1 { - t.Errorf("expected level 1, got %d", l.level) + for name, logger := range map[string]Logger{ + "testLogSink": New(&testLogSink{}), + "Discard": Discard(), + "Zero": {}, + } { + t.Run(name, func(t *testing.T) { + adjust := func(level int) int { + if logger.GetSink() == nil { + // The Discard and the zero Logger short-cut the V call and don't + // change the verbosity level. + return 0 + } + return level + } + inputs := []struct { + name string + fn func() Logger + exp int + }{{ + name: "V(0)", + fn: func() Logger { return logger.V(0) }, + exp: 0, + }, { + name: "V(93)", + fn: func() Logger { return logger.V(93) }, + exp: adjust(93), + }, { + name: "V(70).V(6)", + fn: func() Logger { return logger.V(70).V(6) }, + exp: adjust(76), + }, { + name: "V(-1)", + fn: func() Logger { return logger.V(-1) }, + exp: 0, + }, { + name: "V(1).V(-1)", + fn: func() Logger { return logger.V(1).V(-1) }, + exp: adjust(1), + }} + for _, in := range inputs { + t.Run(in.name, func(t *testing.T) { + if want, got := in.exp, in.fn().GetV(); got != want { + t.Errorf("expected %d, got %d", want, got) + } + }) + } + }) } } @@ -197,14 +228,14 @@ func TestInfo(t *testing.T) { calledInfo := 0 lvlInput := 0 msgInput := "msg" - kvInput := []interface{}{0, 1, 2} + kvInput := []any{0, 1, 2} sink := &testLogSink{} sink.fnEnabled = func(lvl int) bool { calledEnabled++ return lvl < 100 } - sink.fnInfo = func(lvl int, msg string, kv ...interface{}) { + sink.fnInfo = func(lvl int, msg string, kv ...any) { calledInfo++ if lvl != lvlInput { t.Errorf("unexpected lvl input, got %v", lvl) @@ -265,10 +296,10 @@ func TestInfo(t *testing.T) { func TestWithValues(t *testing.T) { calledWithValues := 0 - kvInput := []interface{}{"zero", 0, "one", 1, "two", 2} + kvInput := []any{"zero", 0, "one", 1, "two", 2} sink := &testLogSink{} - sink.fnWithValues = func(kv ...interface{}) { + sink.fnWithValues = func(kv ...any) { calledWithValues++ if !reflect.DeepEqual(kv, kvInput) { t.Errorf("unexpected kv input, got %v", kv) @@ -439,3 +470,46 @@ func TestZeroValue(t *testing.T) { l2.Error(errors.New("bar"), "some error") _, _ = l.WithCallStackHelper() } + +func TestCallDepthConsistent(t *testing.T) { + sink := &testLogSink{} + + depth := 0 + expect := "github.com/go-logr/logr.TestCallDepthConsistent" + sink.fnInit = func(ri RuntimeInfo) { + depth = ri.CallDepth + 1 // 1 for these function pointers + if caller := getCaller(depth); caller != expect { + t.Errorf("identified wrong caller %q", caller) + } + + } + sink.fnEnabled = func(_ int) bool { + if caller := getCaller(depth); caller != expect { + t.Errorf("identified wrong caller %q", caller) + } + return true + } + sink.fnError = func(_ error, _ string, _ ...any) { + if caller := getCaller(depth); caller != expect { + t.Errorf("identified wrong caller %q", caller) + } + } + l := New(sink) + + l.Enabled() + l.Info("msg") + l.Error(nil, "msg") +} + +func getCaller(depth int) string { + // +1 for this frame, +1 for Info/Error/Enabled. + pc, _, _, ok := runtime.Caller(depth + 2) + if !ok { + return "" + } + fp := runtime.FuncForPC(pc) + if fp == nil { + return "" + } + return fp.Name() +} diff --git a/slogr/example/main.go b/slogr/example/main.go new file mode 100644 index 0000000..c6379d2 --- /dev/null +++ b/slogr/example/main.go @@ -0,0 +1,103 @@ +//go:build go1.21 +// +build go1.21 + +/* +Copyright 2023 The logr 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 main is an example of using slogr. +package main + +import ( + "context" + "fmt" + "log/slog" + "os" + + "github.com/go-logr/logr" + "github.com/go-logr/logr/funcr" + "github.com/go-logr/logr/slogr" +) + +type e struct { + str string +} + +func (e e) Error() string { + return e.str +} + +func logrHelper(log logr.Logger, msg string) { + logrHelper2(log, msg) +} + +func logrHelper2(log logr.Logger, msg string) { + log.WithCallDepth(2).Info(msg) +} + +func slogHelper(log *slog.Logger, msg string) { + slogHelper2(log, msg) +} + +func slogHelper2(log *slog.Logger, msg string) { + // slog.Logger has no API for skipping helper functions, so this gets logged as call location. + log.Info(msg) +} + +func main() { + opts := slog.HandlerOptions{ + AddSource: true, + Level: slog.Level(-1), + } + handler := slog.NewJSONHandler(os.Stderr, &opts) + logrLogger := slogr.NewLogr(handler) + logrExample(logrLogger) + + logrLogger = funcr.NewJSON( + func(obj string) { fmt.Println(obj) }, + funcr.Options{ + LogCaller: funcr.All, + LogTimestamp: true, + Verbosity: 1, + }) + slogLogger := slog.New(slogr.NewSlogHandler(logrLogger)) + slogExample(slogLogger) +} + +func logrExample(log logr.Logger) { + log = log.WithName("my") + log = log.WithName("logger") + log = log.WithName("name") + log = log.WithValues("saved", "value") + log.Info("1) hello", "val1", 1, "val2", map[string]int{"k": 1}) + log.V(1).Info("2) you should see this") + log.V(1).V(1).Info("you should NOT see this") + log.Error(nil, "3) uh oh", "trouble", true, "reasons", []float64{0.1, 0.11, 3.14}) + log.Error(e{"an error occurred"}, "4) goodbye", "code", -1) + logrHelper(log, "5) thru a helper") +} + +func slogExample(log *slog.Logger) { + // There's no guarantee that this logs the right source code location. + // It works for Go 1.21.0 by compensating in slogr.NewSlogHandler + // for the additional callers, but those might change. + log = log.With("saved", "value") + log.Info("1) hello", "val1", 1, "val2", map[string]int{"k": 1}) + log.Log(context.TODO(), slog.Level(-1), "2) you should see this") + log.Log(context.TODO(), slog.Level(-2), "you should NOT see this") + log.Error("3) uh oh", "trouble", true, "reasons", []float64{0.1, 0.11, 3.14}) + log.Error("4) goodbye", "code", -1, "err", e{"an error occurred"}) + slogHelper(log, "5) thru a helper") +} diff --git a/slogr/sloghandler.go b/slogr/sloghandler.go new file mode 100644 index 0000000..ec6725c --- /dev/null +++ b/slogr/sloghandler.go @@ -0,0 +1,168 @@ +//go:build go1.21 +// +build go1.21 + +/* +Copyright 2023 The logr 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 slogr + +import ( + "context" + "log/slog" + + "github.com/go-logr/logr" +) + +type slogHandler struct { + // May be nil, in which case all logs get discarded. + sink logr.LogSink + // Non-nil if sink is non-nil and implements SlogSink. + slogSink SlogSink + + // groupPrefix collects values from WithGroup calls. It gets added as + // prefix to value keys when handling a log record. + groupPrefix string + + // levelBias can be set when constructing the handler to influence the + // slog.Level of log records. A positive levelBias reduces the + // slog.Level value. slog has no API to influence this value after the + // handler got created, so it can only be set indirectly through + // Logger.V. + levelBias slog.Level +} + +var _ slog.Handler = &slogHandler{} + +// groupSeparator is used to concatenate WithGroup names and attribute keys. +const groupSeparator = "." + +// GetLevel is used for black box unit testing. +func (l *slogHandler) GetLevel() slog.Level { + return l.levelBias +} + +func (l *slogHandler) Enabled(ctx context.Context, level slog.Level) bool { + return l.sink != nil && (level >= slog.LevelError || l.sink.Enabled(l.levelFromSlog(level))) +} + +func (l *slogHandler) Handle(ctx context.Context, record slog.Record) error { + if l.slogSink != nil { + // Only adjust verbosity level of log entries < slog.LevelError. + if record.Level < slog.LevelError { + record.Level -= l.levelBias + } + return l.slogSink.Handle(ctx, record) + } + + // No need to check for nil sink here because Handle will only be called + // when Enabled returned true. + + kvList := make([]any, 0, 2*record.NumAttrs()) + record.Attrs(func(attr slog.Attr) bool { + if attr.Key != "" { + kvList = append(kvList, l.addGroupPrefix(attr.Key), attr.Value.Resolve().Any()) + } + return true + }) + if record.Level >= slog.LevelError { + l.sinkWithCallDepth().Error(nil, record.Message, kvList...) + } else { + level := l.levelFromSlog(record.Level) + l.sinkWithCallDepth().Info(level, record.Message, kvList...) + } + return nil +} + +// sinkWithCallDepth adjusts the stack unwinding so that when Error or Info +// are called by Handle, code in slog gets skipped. +// +// This offset currently (Go 1.21.0) works for calls through +// slog.New(NewSlogHandler(...)). There's no guarantee that the call +// chain won't change. Wrapping the handler will also break unwinding. It's +// still better than not adjusting at all.... +// +// This cannot be done when constructing the handler because NewLogr needs +// access to the original sink without this adjustment. A second copy would +// work, but then WithAttrs would have to be called for both of them. +func (l *slogHandler) sinkWithCallDepth() logr.LogSink { + if sink, ok := l.sink.(logr.CallDepthLogSink); ok { + return sink.WithCallDepth(2) + } + return l.sink +} + +func (l *slogHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if l.sink == nil || len(attrs) == 0 { + return l + } + + copy := *l + if l.slogSink != nil { + copy.slogSink = l.slogSink.WithAttrs(attrs) + copy.sink = copy.slogSink + } else { + kvList := make([]any, 0, 2*len(attrs)) + for _, attr := range attrs { + if attr.Key != "" { + kvList = append(kvList, l.addGroupPrefix(attr.Key), attr.Value.Resolve().Any()) + } + } + copy.sink = l.sink.WithValues(kvList...) + } + return © +} + +func (l *slogHandler) WithGroup(name string) slog.Handler { + if l.sink == nil { + return l + } + copy := *l + if l.slogSink != nil { + copy.slogSink = l.slogSink.WithGroup(name) + copy.sink = l.slogSink + } else { + copy.groupPrefix = copy.addGroupPrefix(name) + } + return © +} + +func (l *slogHandler) addGroupPrefix(name string) string { + if l.groupPrefix == "" { + return name + } + return l.groupPrefix + groupSeparator + name +} + +// levelFromSlog adjusts the level by the logger's verbosity and negates it. +// It ensures that the result is >= 0. This is necessary because the result is +// passed to a logr.LogSink and that API did not historically document whether +// levels could be negative or what that meant. +// +// Some example usage: +// logrV0 := getMyLogger() +// logrV2 := logrV0.V(2) +// slogV2 := slog.New(slogr.NewSlogHandler(logrV2)) +// slogV2.Debug("msg") // =~ logrV2.V(4) =~ logrV0.V(6) +// slogV2.Info("msg") // =~ logrV2.V(0) =~ logrV0.V(2) +// slogv2.Warn("msg") // =~ logrV2.V(-4) =~ logrV0.V(0) +func (l *slogHandler) levelFromSlog(level slog.Level) int { + result := -level + result += l.levelBias // in case the original logr.Logger had a V level + if result < 0 { + result = 0 // because logr.LogSink doesn't expect negative V levels + } + return int(result) +} diff --git a/slogr/slogr.go b/slogr/slogr.go new file mode 100644 index 0000000..eb519ae --- /dev/null +++ b/slogr/slogr.go @@ -0,0 +1,108 @@ +//go:build go1.21 +// +build go1.21 + +/* +Copyright 2023 The logr 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 slogr enables usage of a slog.Handler with logr.Logger as front-end +// API and of a logr.LogSink through the slog.Handler and thus slog.Logger +// APIs. +// +// See the README in the top-level [./logr] package for a discussion of +// interoperability. +package slogr + +import ( + "context" + "log/slog" + + "github.com/go-logr/logr" +) + +// NewLogr returns a logr.Logger which writes to the slog.Handler. +// +// The logr verbosity level is mapped to slog levels such that V(0) becomes +// slog.LevelInfo and V(4) becomes slog.LevelDebug. +func NewLogr(handler slog.Handler) logr.Logger { + if handler, ok := handler.(*slogHandler); ok { + if handler.sink == nil { + return logr.Discard() + } + return logr.New(handler.sink).V(int(handler.levelBias)) + } + return logr.New(&slogSink{handler: handler}) +} + +// NewSlogHandler returns a slog.Handler which writes to the same sink as the logr.Logger. +// +// The returned logger writes all records with level >= slog.LevelError as +// error log entries with LogSink.Error, regardless of the verbosity level of +// the logr.Logger: +// +// logger := +// slog.New(NewSlogHandler(logger.V(10))).Error(...) -> logSink.Error(...) +// +// The level of all other records gets reduced by the verbosity +// level of the logr.Logger and the result is negated. If it happens +// to be negative, then it gets replaced by zero because a LogSink +// is not expected to handled negative levels: +// +// slog.New(NewSlogHandler(logger)).Debug(...) -> logger.GetSink().Info(level=4, ...) +// slog.New(NewSlogHandler(logger)).Warning(...) -> logger.GetSink().Info(level=0, ...) +// slog.New(NewSlogHandler(logger)).Info(...) -> logger.GetSink().Info(level=0, ...) +// slog.New(NewSlogHandler(logger.V(4))).Info(...) -> logger.GetSink().Info(level=4, ...) +func NewSlogHandler(logger logr.Logger) slog.Handler { + if sink, ok := logger.GetSink().(*slogSink); ok && logger.GetV() == 0 { + return sink.handler + } + + handler := &slogHandler{sink: logger.GetSink(), levelBias: slog.Level(logger.GetV())} + if slogSink, ok := handler.sink.(SlogSink); ok { + handler.slogSink = slogSink + } + return handler +} + +// SlogSink is an optional interface that a LogSink can implement to support +// logging through the slog.Logger or slog.Handler APIs better. It then should +// also support special slog values like slog.Group. When used as a +// slog.Handler, the advantages are: +// +// - stack unwinding gets avoided in favor of logging the pre-recorded PC, +// as intended by slog +// - proper grouping of key/value pairs via WithGroup +// - verbosity levels > slog.LevelInfo can be recorded +// - less overhead +// +// Both APIs (logr.Logger and slog.Logger/Handler) then are supported equally +// well. Developers can pick whatever API suits them better and/or mix +// packages which use either API in the same binary with a common logging +// implementation. +// +// This interface is necessary because the type implementing the LogSink +// interface cannot also implement the slog.Handler interface due to the +// different prototype of the common Enabled method. +// +// An implementation could support both interfaces in two different types, but then +// additional interfaces would be needed to convert between those types in NewLogr +// and NewSlogHandler. +type SlogSink interface { + logr.LogSink + + Handle(ctx context.Context, record slog.Record) error + WithAttrs(attrs []slog.Attr) SlogSink + WithGroup(name string) SlogSink +} diff --git a/slogr/slogr_test.go b/slogr/slogr_test.go new file mode 100644 index 0000000..2e5f0ff --- /dev/null +++ b/slogr/slogr_test.go @@ -0,0 +1,262 @@ +//go:build go1.21 +// +build go1.21 + +/* +Copyright 2023 The logr 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 slogr_test + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "fmt" + "io" + "log/slog" + "os" + "path" + "runtime" + "strings" + "testing" + "testing/slogtest" + + "github.com/go-logr/logr" + "github.com/go-logr/logr/funcr" + "github.com/go-logr/logr/slogr" +) + +var debugWithoutTime = &slog.HandlerOptions{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if a.Key == "time" { + return slog.Attr{} + } + return a + }, + Level: slog.LevelDebug, +} + +func ExampleNew() { + logger := slogr.NewLogr(slog.NewTextHandler(os.Stdout, debugWithoutTime)) + + logger.Info("hello world") + logger.Error(errors.New("fake error"), "ignore me") + logger.WithValues("x", 1, "y", 2).WithValues("str", "abc").WithName("foo").WithName("bar").V(4).Info("with values, verbosity and name") + + // Output: + // level=INFO msg="hello world" + // level=ERROR msg="ignore me" err="fake error" + // level=DEBUG msg="with values, verbosity and name" x=1 y=2 str=abc logger=foo/bar +} + +func ExampleNewSlogLogger() { + funcrLogger := funcr.New(func(prefix, args string) { + if prefix != "" { + fmt.Fprintln(os.Stdout, prefix, args) + } else { + fmt.Fprintln(os.Stdout, args) + } + }, funcr.Options{ + Verbosity: 10, + }) + + logger := slog.New(slogr.NewSlogHandler(funcrLogger)) + logger.Info("hello world") + logger.Error("ignore me", "err", errors.New("fake error")) + logger.With("x", 1, "y", 2).WithGroup("group").With("str", "abc").Warn("with values and group") + + logger = slog.New(slogr.NewSlogHandler(funcrLogger.V(int(-slog.LevelDebug)))) + logger.Info("info message reduced to debug level") + + // Output: + // "level"=0 "msg"="hello world" + // "msg"="ignore me" "error"=null "err"="fake error" + // "level"=0 "msg"="with values and group" "x"=1 "y"=2 "group.str"="abc" + // "level"=4 "msg"="info message reduced to debug level" +} + +func TestWithCallDepth(t *testing.T) { + debugWithCaller := *debugWithoutTime + debugWithCaller.AddSource = true + var buffer bytes.Buffer + logger := slogr.NewLogr(slog.NewTextHandler(&buffer, &debugWithCaller)) + + logHelper(logger) + _, file, line, _ := runtime.Caller(0) + expectedSource := fmt.Sprintf("%s:%d", path.Base(file), line-1) + actual := buffer.String() + if !strings.Contains(actual, expectedSource) { + t.Errorf("expected log entry with %s as caller source code location, got instead:\n%s", expectedSource, actual) + } +} + +func logHelper(logger logr.Logger) { + logger.WithCallDepth(1).Info("hello") +} + +func TestJSONHandler(t *testing.T) { + testSlog(t, func(buffer *bytes.Buffer) logr.Logger { + handler := slog.NewJSONHandler(buffer, nil) + sink := testSlogSink{handler: handler} + return logr.New(sink) + }) +} + +var _ logr.LogSink = testSlogSink{} +var _ slogr.SlogSink = testSlogSink{} + +// testSlogSink is only used through slog and thus doesn't need to implement the +// normal LogSink methods. +type testSlogSink struct { + handler slog.Handler +} + +func (s testSlogSink) Init(logr.RuntimeInfo) {} +func (s testSlogSink) Enabled(int) bool { return true } +func (s testSlogSink) Error(error, string, ...interface{}) {} +func (s testSlogSink) Info(int, string, ...interface{}) {} +func (s testSlogSink) WithName(string) logr.LogSink { return s } +func (s testSlogSink) WithValues(...interface{}) logr.LogSink { return s } + +func (s testSlogSink) Handle(ctx context.Context, record slog.Record) error { + return s.handler.Handle(ctx, record) +} +func (s testSlogSink) WithAttrs(attrs []slog.Attr) slogr.SlogSink { + return testSlogSink{handler: s.handler.WithAttrs(attrs)} +} +func (s testSlogSink) WithGroup(name string) slogr.SlogSink { + return testSlogSink{handler: s.handler.WithGroup(name)} +} + +func TestFuncrHandler(t *testing.T) { + testSlog(t, func(buffer *bytes.Buffer) logr.Logger { + logger := funcr.NewJSON(func(obj string) { + fmt.Fprintln(buffer, obj) + }, funcr.Options{ + LogTimestamp: true, + Verbosity: 10, + RenderBuiltinsHook: func(kvList []any) []any { + mappedKVList := make([]any, len(kvList)) + for i := 0; i < len(kvList); i += 2 { + key := kvList[i] + switch key { + case "ts": + mappedKVList[i] = "time" + default: + mappedKVList[i] = key + } + mappedKVList[i+1] = kvList[i+1] + } + return mappedKVList + }, + }) + return logger + }, + "a Handler should ignore a zero Record.Time", // Time is generated by sink. + "a Handler should handle Group attributes", // funcr doesn't. + "a Handler should inline the Attrs of a group with an empty key", // funcr doesn't know about groups. + "a Handler should not output groups for an empty Record", // Relies on WithGroup. Text may change, see https://go.dev/cl/516155 + "a Handler should handle the WithGroup method", // logHandler does by prefixing keys, which is not what the test expects. + "a Handler should handle multiple WithGroup and WithAttr calls", // Same. + "a Handler should call Resolve on attribute values in groups", // funcr doesn't do that and slogHandler can't do it for it. + ) +} + +func testSlog(t *testing.T, createLogger func(buffer *bytes.Buffer) logr.Logger, exceptions ...string) { + var buffer bytes.Buffer + logger := createLogger(&buffer) + handler := slogr.NewSlogHandler(logger) + err := slogtest.TestHandler(handler, func() []map[string]any { + var ms []map[string]any + for _, line := range bytes.Split(buffer.Bytes(), []byte{'\n'}) { + if len(line) == 0 { + continue + } + var m map[string]any + if err := json.Unmarshal(line, &m); err != nil { + t.Fatal(err) + } + ms = append(ms, m) + } + return ms + }) + + // Correlating failures with individual test cases is hard with the current API. + // See https://github.com/golang/go/issues/61758 + t.Logf("Output:\n%s", buffer.String()) + if err != nil { + if err, ok := err.(interface { + Unwrap() []error + }); ok { + for _, err := range err.Unwrap() { + if !containsOne(err.Error(), exceptions...) { + t.Errorf("Unexpected error: %v", err) + } + } + } else { + // Shouldn't be reached, errors from errors.Join can be split up. + t.Errorf("Unexpected errors:\n%v", err) + } + } +} + +func containsOne(hay string, needles ...string) bool { + for _, needle := range needles { + if strings.Contains(hay, needle) { + return true + } + } + return false +} + +func TestDiscard(t *testing.T) { + logger := slog.New(slogr.NewSlogHandler(logr.Discard())) + logger.WithGroup("foo").With("x", 1).Info("hello") +} + +func TestConversion(t *testing.T) { + d := logr.Discard() + d2 := slogr.NewLogr(slogr.NewSlogHandler(d)) + expectEqual(t, d, d2) + + e := logr.Logger{} + e2 := slogr.NewLogr(slogr.NewSlogHandler(e)) + expectEqual(t, e, e2) + + f := funcr.New(func(prefix, args string) {}, funcr.Options{}) + f2 := slogr.NewLogr(slogr.NewSlogHandler(f)) + expectEqual(t, f, f2) + + text := slog.NewTextHandler(io.Discard, nil) + text2 := slogr.NewSlogHandler(slogr.NewLogr(text)) + expectEqual(t, text, text2) + + text3 := slogr.NewSlogHandler(slogr.NewLogr(text).V(1)) + if handler, ok := text3.(interface { + GetLevel() slog.Level + }); ok { + expectEqual(t, handler.GetLevel(), slog.Level(1)) + } else { + t.Errorf("Expected a slogHandler which implements V(1), got instead: %T %+v", text3, text3) + } +} + +func expectEqual(t *testing.T, expected, actual any) { + if expected != actual { + t.Helper() + t.Errorf("Expected %T %+v, got instead: %T %+v", expected, expected, actual, actual) + } +} diff --git a/slogr/slogsink.go b/slogr/slogsink.go new file mode 100644 index 0000000..6fbac56 --- /dev/null +++ b/slogr/slogsink.go @@ -0,0 +1,122 @@ +//go:build go1.21 +// +build go1.21 + +/* +Copyright 2023 The logr 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 slogr + +import ( + "context" + "log/slog" + "runtime" + "time" + + "github.com/go-logr/logr" +) + +var ( + _ logr.LogSink = &slogSink{} + _ logr.CallDepthLogSink = &slogSink{} + _ Underlier = &slogSink{} +) + +// Underlier is implemented by the LogSink returned by NewLogr. +type Underlier interface { + // GetUnderlying returns the Handler used by the LogSink. + GetUnderlying() slog.Handler +} + +const ( + // nameKey is used to log the `WithName` values as an additional attribute. + nameKey = "logger" + + // errKey is used to log the error parameter of Error as an additional attribute. + errKey = "err" +) + +type slogSink struct { + callDepth int + name string + handler slog.Handler +} + +func (l *slogSink) Init(info logr.RuntimeInfo) { + l.callDepth = info.CallDepth +} + +func (l *slogSink) GetUnderlying() slog.Handler { + return l.handler +} + +func (l *slogSink) WithCallDepth(depth int) logr.LogSink { + newLogger := *l + newLogger.callDepth += depth + return &newLogger +} + +func (l *slogSink) Enabled(level int) bool { + return l.handler.Enabled(context.Background(), slog.Level(-level)) +} + +func (l *slogSink) Info(level int, msg string, kvList ...interface{}) { + l.log(nil, msg, slog.Level(-level), kvList...) +} + +func (l *slogSink) Error(err error, msg string, kvList ...interface{}) { + l.log(err, msg, slog.LevelError, kvList...) +} + +func (l *slogSink) log(err error, msg string, level slog.Level, kvList ...interface{}) { + var pcs [1]uintptr + // skip runtime.Callers, this function, Info/Error, and all helper functions above that. + runtime.Callers(3+l.callDepth, pcs[:]) + + record := slog.NewRecord(time.Now(), level, msg, pcs[0]) + if l.name != "" { + record.AddAttrs(slog.String(nameKey, l.name)) + } + if err != nil { + record.AddAttrs(slog.Any(errKey, err)) + } + record.Add(kvList...) + l.handler.Handle(context.Background(), record) +} + +func (l slogSink) WithName(name string) logr.LogSink { + if l.name != "" { + l.name = l.name + "/" + } + l.name += name + return &l +} + +func (l slogSink) WithValues(kvList ...interface{}) logr.LogSink { + l.handler = l.handler.WithAttrs(kvListToAttrs(kvList...)) + return &l +} + +func kvListToAttrs(kvList ...interface{}) []slog.Attr { + // We don't need the record itself, only its Add method. + record := slog.NewRecord(time.Time{}, 0, "", 0) + record.Add(kvList...) + attrs := make([]slog.Attr, 0, record.NumAttrs()) + record.Attrs(func(attr slog.Attr) bool { + attrs = append(attrs, attr) + return true + }) + return attrs +} diff --git a/testr/testr.go b/testr/testr.go index 2772b49..5eabe2b 100644 --- a/testr/testr.go +++ b/testr/testr.go @@ -54,7 +54,7 @@ func NewWithOptions(t *testing.T, opts Options) logr.Logger { // TestingT is an interface wrapper around testing.T, testing.B and testing.F. type TestingT interface { Helper() - Log(args ...interface{}) + Log(args ...any) } // NewWithInterface returns a logr.Logger that prints through a @@ -92,7 +92,7 @@ type UnderlierInterface interface { } // Info logging implementation shared between testLogger and testLoggerInterface. -func logInfo(t TestingT, formatInfo func(int, string, []interface{}) (string, string), level int, msg string, kvList ...interface{}) { +func logInfo(t TestingT, formatInfo func(int, string, []any) (string, string), level int, msg string, kvList ...any) { prefix, args := formatInfo(level, msg, kvList) t.Helper() if prefix != "" { @@ -102,7 +102,7 @@ func logInfo(t TestingT, formatInfo func(int, string, []interface{}) (string, st } // Error logging implementation shared between testLogger and testLoggerInterface. -func logError(t TestingT, formatError func(error, string, []interface{}) (string, string), err error, msg string, kvList ...interface{}) { +func logError(t TestingT, formatError func(error, string, []any) (string, string), err error, msg string, kvList ...any) { prefix, args := formatError(err, msg, kvList) t.Helper() if prefix != "" { @@ -134,7 +134,7 @@ func (l testloggerInterface) WithName(name string) logr.LogSink { return &l } -func (l testloggerInterface) WithValues(kvList ...interface{}) logr.LogSink { +func (l testloggerInterface) WithValues(kvList ...any) logr.LogSink { l.Formatter.AddValues(kvList) return &l } @@ -143,12 +143,12 @@ func (l testloggerInterface) GetCallStackHelper() func() { return l.t.Helper } -func (l testloggerInterface) Info(level int, msg string, kvList ...interface{}) { +func (l testloggerInterface) Info(level int, msg string, kvList ...any) { l.t.Helper() logInfo(l.t, l.FormatInfo, level, msg, kvList...) } -func (l testloggerInterface) Error(err error, msg string, kvList ...interface{}) { +func (l testloggerInterface) Error(err error, msg string, kvList ...any) { l.t.Helper() logError(l.t, l.FormatError, err, msg, kvList...) } diff --git a/testr/testr_fuzz_test.go b/testr/testr_fuzz_test.go index d1def0e..ea5217d 100644 --- a/testr/testr_fuzz_test.go +++ b/testr/testr_fuzz_test.go @@ -21,7 +21,7 @@ package testr import "testing" -func TestLoggerTestingF(t *testing.T) { +func TestLoggerTestingF(_ *testing.T) { f := &testing.F{} _ = NewWithInterface(f, Options{}) } diff --git a/testr/testr_test.go b/testr/testr_test.go index 252c4be..01d51fd 100644 --- a/testr/testr_test.go +++ b/testr/testr_test.go @@ -71,7 +71,7 @@ func TestLoggerInterface(t *testing.T) { } } -func TestLoggerTestingB(t *testing.T) { +func TestLoggerTestingB(_ *testing.T) { b := &testing.B{} _ = NewWithInterface(b, Options{}) }