From 2a44646912e06515abcbeb57e26c363b2b52acfb Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Thu, 22 Apr 2021 11:11:26 -0700 Subject: [PATCH 1/6] Make the benchmark not inline ther impl In real code, the definition of the Logger would be far away from the logging call-sites. The benchmark now forces the compiler to NOT inline, even though it could. It also now tests logr.Discard() and funcr. --- benchmark/benchmark_test.go | 105 ++++++++++++++++++++++++++++-------- 1 file changed, 84 insertions(+), 21 deletions(-) diff --git a/benchmark/benchmark_test.go b/benchmark/benchmark_test.go index e16bd07..0c0d0fa 100644 --- a/benchmark/benchmark_test.go +++ b/benchmark/benchmark_test.go @@ -27,17 +27,15 @@ import ( func noop(prefix, args string) { } -func BenchmarkInfoOneArg(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doInfoOneArg(b *testing.B, log logr.Logger) { for i := 0; i < b.N; i++ { log.Info("this is", "a", "string") } } -func BenchmarkInfoSeveralArgs(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doInfoSeveralArgs(b *testing.B, log logr.Logger) { for i := 0; i < b.N; i++ { log.Info("multi", "bool", true, "string", "str", "int", 42, @@ -45,9 +43,8 @@ func BenchmarkInfoSeveralArgs(b *testing.B) { } } -func BenchmarkV0Info(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doV0Info(b *testing.B, log logr.Logger) { for i := 0; i < b.N; i++ { log.V(0).Info("multi", "bool", true, "string", "str", "int", 42, @@ -55,9 +52,8 @@ func BenchmarkV0Info(b *testing.B) { } } -func BenchmarkV9Info(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doV9Info(b *testing.B, log logr.Logger) { for i := 0; i < b.N; i++ { log.V(9).Info("multi", "bool", true, "string", "str", "int", 42, @@ -65,9 +61,8 @@ func BenchmarkV9Info(b *testing.B) { } } -func BenchmarkError(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doError(b *testing.B, log logr.Logger) { err := fmt.Errorf("error message") for i := 0; i < b.N; i++ { log.Error(err, "multi", @@ -76,20 +71,88 @@ func BenchmarkError(b *testing.B) { } } -func BenchmarkWithValues(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doWithValues(b *testing.B, log logr.Logger) { for i := 0; i < b.N; i++ { l := log.WithValues("k1", "v1", "k2", "v2") _ = l } } -func BenchmarkWithName(b *testing.B) { - var log logr.Logger = funcr.New(noop, funcr.Options{}) - +//go:noinline +func doWithName(b *testing.B, log logr.Logger) { for i := 0; i < b.N; i++ { l := log.WithName("name") _ = l } } + +func BenchmarkDiscardInfoOneArg(b *testing.B) { + var log logr.Logger = logr.Discard() + doInfoOneArg(b, log) +} + +func BenchmarkDiscardInfoSeveralArgs(b *testing.B) { + var log logr.Logger = logr.Discard() + doInfoSeveralArgs(b, log) +} + +func BenchmarkDiscardV0Info(b *testing.B) { + var log logr.Logger = logr.Discard() + doV0Info(b, log) +} + +func BenchmarkDiscardV9Info(b *testing.B) { + var log logr.Logger = logr.Discard() + doV9Info(b, log) +} + +func BenchmarkDiscardError(b *testing.B) { + var log logr.Logger = logr.Discard() + doError(b, log) +} + +func BenchmarkDiscardWithValues(b *testing.B) { + var log logr.Logger = logr.Discard() + doWithValues(b, log) +} + +func BenchmarkDiscardWithName(b *testing.B) { + var log logr.Logger = logr.Discard() + doWithName(b, log) +} + +func BenchmarkFuncrInfoOneArg(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doInfoOneArg(b, log) +} + +func BenchmarkFuncrInfoSeveralArgs(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doInfoSeveralArgs(b, log) +} + +func BenchmarkFuncrV0Info(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doV0Info(b, log) +} + +func BenchmarkFuncrV9Info(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doV9Info(b, log) +} + +func BenchmarkFuncrError(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doError(b, log) +} + +func BenchmarkFuncrWithValues(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doWithValues(b, log) +} + +func BenchmarkFuncrWithName(b *testing.B) { + var log logr.Logger = funcr.New(noop, funcr.Options{}) + doWithName(b, log) +} From bb231ff675f32d58bb1eb2ebe42756339b560feb Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Fri, 2 Apr 2021 14:20:24 -0700 Subject: [PATCH 2/6] Per-driven overhaul Convert Logger from an interfact to a concrete type that calls out to a LogSink interface. !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! !! !! !! THIS IS A BREAKING CHANGE !! !! !! !! Most end-users just need to recompile. !! !! !! !! Logging implementations need to make code changes. !! !! !! !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Before: ``` $ go test -bench='.' ./benchmark/ goos: linux goarch: amd64 pkg: github.com/go-logr/logr/benchmark cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz BenchmarkInfoOneArg-6 3013077 400.9 ns/op BenchmarkInfoSeveralArgs-6 1162088 1039 ns/op BenchmarkV0Info-6 754347 1418 ns/op BenchmarkV9Info-6 4605950 267.8 ns/op BenchmarkError-6 935028 1135 ns/op BenchmarkWithValues-6 5127631 232.5 ns/op BenchmarkWithName-6 12850569 106.5 ns/op ``` After: ``` $ go test -bench='.' ./benchmark/ goos: linux goarch: amd64 pkg: github.com/go-logr/logr/benchmark cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz BenchmarkInfoOneArg-6 2465788 475.7 ns/op BenchmarkInfoSeveralArgs-6 893026 1226 ns/op BenchmarkV0Info-6 817473 1250 ns/op BenchmarkV9Info-6 8595180 155.1 ns/op BenchmarkError-6 1000000 1371 ns/op BenchmarkWithValues-6 3902214 292.0 ns/op BenchmarkWithName-6 11271037 106.6 ns/op ``` Logs that actually write are dominated by the cost of preparing the message. Logs which do not write (e.g. `V(9)`) are faster here (thog glog raw is much faster still). The main difference is the variadic slice setup. This is a candidate for Go to optimize - it now knows that the args are only used inside the conditional (`Enabled()`), and when that path is not executed, it can elide that work. --- discard.go | 18 +++++------ funcr/funcr.go | 50 +++++++++++++++--------------- logr.go | 83 +++++++++++++++++++++++++++++++++++--------------- 3 files changed, 91 insertions(+), 60 deletions(-) diff --git a/discard.go b/discard.go index 2bafb13..7d3c684 100644 --- a/discard.go +++ b/discard.go @@ -19,33 +19,29 @@ package logr // Discard returns a valid Logger that discards all messages logged to it. // It can be used whenever the caller is not interested in the logs. func Discard() Logger { - return DiscardLogger{} + return Logger{0, DiscardLogger{}} } // DiscardLogger is a Logger that discards all messages. type DiscardLogger struct{} -func (l DiscardLogger) Enabled() bool { +func (l DiscardLogger) Enabled(int) bool { return false } -func (l DiscardLogger) Info(msg string, keysAndValues ...interface{}) { +func (l DiscardLogger) Info(int, string, ...interface{}) { } -func (l DiscardLogger) Error(err error, msg string, keysAndValues ...interface{}) { +func (l DiscardLogger) Error(error, string, ...interface{}) { } -func (l DiscardLogger) V(level int) Logger { +func (l DiscardLogger) WithValues(...interface{}) LogSink { return l } -func (l DiscardLogger) WithValues(keysAndValues ...interface{}) Logger { - return l -} - -func (l DiscardLogger) WithName(name string) Logger { +func (l DiscardLogger) WithName(string) LogSink { return l } // Verify that it actually implements the interface -var _ Logger = DiscardLogger{} +var _ LogSink = DiscardLogger{} diff --git a/funcr/funcr.go b/funcr/funcr.go index 613a66d..923c80e 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -33,14 +33,15 @@ import ( // New returns a logr.Logger which is implemented by a function. func New(fn func(prefix, args string), opts Options) logr.Logger { - return fnlogger{ - level: 0, + fnl := fnlogger{ prefix: "", values: nil, + depth: 0, write: fn, logCaller: opts.LogCaller, verbosity: opts.Verbosity, } + return logr.New(0, fnl) } type Options struct { @@ -63,9 +64,9 @@ const ( ) type fnlogger struct { - level int prefix string values []interface{} + depth int write func(prefix, args string) logCaller MessageClass verbosity int @@ -269,29 +270,27 @@ func (l fnlogger) caller() callerID { // +1 for this frame, +1 for logr itself. // FIXME: Maybe logr should offer a clue as to how many frames are // needed here? Or is it part of the contract to LogSinks? - _, file, line, ok := runtime.Caller(framesToCaller() + 2) + _, file, line, ok := runtime.Caller(framesToCaller() + l.depth + 2) if !ok { return callerID{"", 0} } return callerID{filepath.Base(file), line} } -func (l fnlogger) Enabled() bool { - return l.level <= l.verbosity +func (l fnlogger) Enabled(level int) bool { + return level <= l.verbosity } -func (l fnlogger) Info(msg string, kvList ...interface{}) { - if l.Enabled() { - args := make([]interface{}, 0, 64) // using a constant here impacts perf - if l.logCaller == All || l.logCaller == Info { - args = append(args, "caller", l.caller()) - } - args = append(args, "level", l.level, "msg", msg) - args = append(args, l.values...) - args = append(args, kvList...) - argsStr := flatten(args...) - l.write(l.prefix, argsStr) +func (l fnlogger) Info(level int, msg string, kvList ...interface{}) { + args := make([]interface{}, 0, 64) // using a constant here impacts perf + if l.logCaller == All || l.logCaller == Info { + args = append(args, "caller", l.caller()) } + args = append(args, "level", level, "msg", msg) + args = append(args, l.values...) + args = append(args, kvList...) + argsStr := flatten(args...) + l.write(l.prefix, argsStr) } func (l fnlogger) Error(err error, msg string, kvList ...interface{}) { @@ -311,15 +310,10 @@ func (l fnlogger) Error(err error, msg string, kvList ...interface{}) { l.write(l.prefix, argsStr) } -func (l fnlogger) V(level int) logr.Logger { - l.level += level - return l -} - // WithName returns a new Logger with the specified name appended. funcr // uses '/' characters to separate name elements. Callers should not pass '/' // in the provided name string, but this library does not actually enforce that. -func (l fnlogger) WithName(name string) logr.Logger { +func (l fnlogger) WithName(name string) logr.LogSink { if len(l.prefix) > 0 { l.prefix = l.prefix + "/" } @@ -327,11 +321,17 @@ func (l fnlogger) WithName(name string) logr.Logger { return l } -func (l fnlogger) WithValues(kvList ...interface{}) logr.Logger { +func (l fnlogger) WithValues(kvList ...interface{}) logr.LogSink { // Three slice args forces a copy. n := len(l.values) l.values = append(l.values[:n:n], kvList...) return l } -var _ logr.Logger = fnlogger{} +func (l fnlogger) WithCallDepth(depth int) logr.LogSink { + l.depth += depth + return l +} + +var _ logr.LogSink = fnlogger{} +var _ logr.CallDepthLogSink = fnlogger{} diff --git a/logr.go b/logr.go index 842428b..1d12a3c 100644 --- a/logr.go +++ b/logr.go @@ -140,16 +140,12 @@ import ( "context" ) -// TODO: consider adding back in format strings if they're really needed -// TODO: consider other bits of zap/zapcore functionality like ObjectMarshaller (for arbitrary objects) -// TODO: consider other bits of glog functionality like Flush, OutputStats - -// Logger represents the ability to log messages, both errors and not. -type Logger interface { - // Enabled tests whether this Logger is enabled. For example, commandline +// LogSink represents the ability to log messages, both errors and not. +type LogSink interface { + // Enabled tests whether this LogSink is enabled. For example, commandline // flags might be used to set the logging verbosity and disable some info // logs. - Enabled() bool + Enabled(level int) bool // Info logs a non-error message with the given key/value pairs as context. // @@ -157,7 +153,7 @@ type Logger interface { // the log line. The key/value pairs can then be used to add additional // variable information. The key/value pairs should alternate string // keys and arbitrary values. - Info(msg string, keysAndValues ...interface{}) + Info(level int, msg string, keysAndValues ...interface{}) // Error logs an error, with the given message and key/value pairs as context. // It functions similarly to calling Info with the "error" named value, but may @@ -169,22 +165,62 @@ type Logger interface { // triggered this log line, if present. Error(err error, msg string, keysAndValues ...interface{}) - // V returns an Logger value for a specific verbosity level, relative to - // this Logger. In other words, V values are additive. V higher verbosity - // level means a log message is less important. It's illegal to pass a log - // level less than zero. - V(level int) Logger - // WithValues adds some key-value pairs of context to a logger. // See Info for documentation on how key/value pairs work. - WithValues(keysAndValues ...interface{}) Logger + WithValues(keysAndValues ...interface{}) LogSink // WithName adds a new element to the logger's name. // Successive calls with WithName continue to append // suffixes to the logger's name. It's strongly recommended // that name segments contain only letters, digits, and hyphens // (see the package documentation for more information). - WithName(name string) Logger + WithName(name string) LogSink +} + +func New(level int, sink LogSink) Logger { + return Logger{ + level: level, + sink: sink, + } +} + +// Logger is a concrete type, for performance reasons, but all the real work is +// passed on to a LogSink. Implementations of LogSink should provide their own +// constructors thsat return Logger, not LogSink. +type Logger struct { + level int + sink LogSink +} + +func (l Logger) Enabled() bool { + return l.sink.Enabled(l.level) +} + +func (l Logger) Info(msg string, keysAndValues ...interface{}) { + if l.Enabled() { + l.sink.Info(l.level, msg, keysAndValues...) + } +} + +func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) { + if l.Enabled() { + l.sink.Error(err, msg, keysAndValues...) + } +} + +func (l Logger) V(level int) Logger { + l.level += level + return l +} + +func (l Logger) WithValues(keysAndValues ...interface{}) Logger { + l.sink = l.sink.WithValues(keysAndValues...) + return l +} + +func (l Logger) WithName(name string) Logger { + l.sink = l.sink.WithName(name) + return l } // InfoLogger provides compatibility with code that relies on the v0.1.0 @@ -204,7 +240,8 @@ func FromContext(ctx context.Context) Logger { return v } - return nil + //FIXME: what to do here? Could switch to pointers, but yuck? + return Logger{} } // FromContextOrDiscard returns a Logger constructed from ctx or a Logger @@ -232,15 +269,13 @@ func NewContext(ctx context.Context, l Logger) context.Context { // // This is an optional interface and implementations are not required to // support it. -type CallDepthLogger interface { - Logger - +type CallDepthLogSink interface { // WithCallDepth returns a Logger that will offset the call stack by the // specified number of frames when logging call site information. If depth // is 0 the attribution should be to the direct caller of this method. If // depth is 1 the attribution should skip 1 call frame, and so on. // Successive calls to this are additive. - WithCallDepth(depth int) Logger + WithCallDepth(depth int) LogSink } // WithCallDepth returns a Logger that will offset the call stack by the @@ -259,8 +294,8 @@ type CallDepthLogger interface { // Callers which care about whether this was supported or not should test for // CallDepthLogger support themselves. func WithCallDepth(logger Logger, depth int) Logger { - if decorator, ok := logger.(CallDepthLogger); ok { - return decorator.WithCallDepth(depth) + if decorator, ok := logger.sink.(CallDepthLogSink); ok { + logger.sink = decorator.WithCallDepth(depth) } return logger } From 698710201f62cec5f86ffacd0d325f0a8d369213 Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Thu, 22 Apr 2021 22:30:06 -0700 Subject: [PATCH 3/6] Move code, fix comments --- README.md | 23 ++- discard.go | 17 ++- discard_test.go | 2 +- examples/tab_logger.go | 40 +++-- funcr/funcr_test.go | 16 ++ logr.go | 323 ++++++++++++++++++++++++++--------------- logr_test.go | 77 +++++----- testing/test.go | 38 +---- testing/test_test.go | 30 ++++ 9 files changed, 343 insertions(+), 223 deletions(-) create mode 100644 testing/test_test.go diff --git a/README.md b/README.md index e9b5520..304163d 100644 --- a/README.md +++ b/README.md @@ -35,11 +35,11 @@ This is a BETA grade API. There are implementations for the following logging libraries: +- **a function**: [funcr](https://github.com/go-logr/logr/funcr) - **github.com/google/glog**: [glogr](https://github.com/go-logr/glogr) - **k8s.io/klog**: [klogr](https://git.k8s.io/klog/klogr) - **go.uber.org/zap**: [zapr](https://github.com/go-logr/zapr) -- **log** (the Go standard library logger): - [stdr](https://github.com/go-logr/stdr) +- **log** (the Go standard library logger): [stdr](https://github.com/go-logr/stdr) - **github.com/sirupsen/logrus**: [logrusr](https://github.com/bombsimon/logrusr) - **github.com/wojas/genericr**: [genericr](https://github.com/wojas/genericr) (makes it easy to implement your own backend) - **logfmt** (Heroku style [logging](https://www.brandur.org/logfmt)): [logfmtr](https://github.com/iand/logfmtr) @@ -60,7 +60,7 @@ There are implementations for the following logging libraries: Similarly to searchability, if you maintain conventions around your keys, it becomes easy to gather all log lines related to a particular concept. - + - **Structured logs allow better dimensions of filtering**: if you have structure to your logs, you've got more precise control over how much information is logged -- you might choose in a particular configuration @@ -169,7 +169,7 @@ 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). -## How do I choose my keys +## How do I choose my keys? - make your keys human-readable - constant keys are generally a good idea @@ -180,4 +180,19 @@ While key names are mostly unrestricted (and spaces are acceptable), it's generally a good idea to stick to printable ascii characters, or at least match the general character set of your log lines. +## Why should keys be constant values? + +The point of structured logging is to make later log processing easier. Your +keys are, effectively, the schema of each log message. If you use different +keys across instances of the same log-line, you will make your structured logs +much harder to use. `Sprintf()` is for values, not for keys! + +## Why is this not a pure interface? + +The Logger type is implemented as a struct in order to allow the Go compiler to +optimize things like high-V Info logs that are not triggered. Not all of these +implementations are implemented yet, but this structure was suggested as a way to +ensure they *can* be implemented. All of the real work is behind the LogSink +interface. + [warning-makes-no-sense]: http://dave.cheney.net/2015/11/05/lets-talk-about-logging diff --git a/discard.go b/discard.go index 7d3c684..9a36257 100644 --- a/discard.go +++ b/discard.go @@ -16,15 +16,21 @@ limitations under the License. package logr -// Discard returns a valid Logger that discards all messages logged to it. -// It can be used whenever the caller is not interested in the logs. +// Discard returns a Logger that discards all messages logged to it. It can be +// used whenever the caller is not interested in the logs. func Discard() Logger { - return Logger{0, DiscardLogger{}} + return Logger{ + level: 0, + sink: DiscardLogger{}, + } } -// DiscardLogger is a Logger that discards all messages. +// DiscardLogger is a LogSink that discards all messages. type DiscardLogger struct{} +// Verify that it actually implements the interface +var _ LogSink = DiscardLogger{} + func (l DiscardLogger) Enabled(int) bool { return false } @@ -42,6 +48,3 @@ func (l DiscardLogger) WithValues(...interface{}) LogSink { func (l DiscardLogger) WithName(string) LogSink { return l } - -// Verify that it actually implements the interface -var _ LogSink = DiscardLogger{} diff --git a/discard_test.go b/discard_test.go index e2a01cb..4bb1628 100644 --- a/discard_test.go +++ b/discard_test.go @@ -23,7 +23,7 @@ import ( func TestDiscard(t *testing.T) { l := Discard() - if _, ok := l.(DiscardLogger); !ok { + if _, ok := l.sink.(DiscardLogger); !ok { t.Error("did not return the expected underlying type") } // Verify that none of the methods panic, there is not more we can test. diff --git a/examples/tab_logger.go b/examples/tab_logger.go index 445c6d6..46e2ac2 100644 --- a/examples/tab_logger.go +++ b/examples/tab_logger.go @@ -24,18 +24,21 @@ import ( "github.com/go-logr/logr" ) -// TabLogger is a sample logr.Logger that logs to stderr. -// It's terribly inefficient, and is *only* a basic example. -type TabLogger struct { +// tabLogSink is a sample logr.LogSink that logs to stderr. +// It's terribly inefficient, and is only a basic example. +type tabLogSink struct { name string keyValues map[string]interface{} - - writer *tabwriter.Writer + writer *tabwriter.Writer } -var _ logr.Logger = &TabLogger{} +var _ logr.LogSink = tabLogSink{} -func (l *TabLogger) Info(msg string, kvs ...interface{}) { +func (_ tabLogSink) Enabled(level int) bool { + return true +} + +func (l tabLogSink) Info(level int, msg string, kvs ...interface{}) { 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) @@ -47,28 +50,20 @@ func (l *TabLogger) Info(msg string, kvs ...interface{}) { l.writer.Flush() } -func (_ *TabLogger) Enabled() bool { - return true -} - -func (l *TabLogger) Error(err error, msg string, kvs ...interface{}) { +func (l tabLogSink) Error(err error, msg string, kvs ...interface{}) { kvs = append(kvs, "error", err) - l.Info(msg, kvs...) -} - -func (l *TabLogger) V(_ int) logr.Logger { - return l + l.Info(0, msg, kvs...) } -func (l *TabLogger) WithName(name string) logr.Logger { - return &TabLogger{ +func (l tabLogSink) WithName(name string) logr.LogSink { + return tabLogSink{ name: l.name + "." + name, keyValues: l.keyValues, writer: l.writer, } } -func (l *TabLogger) WithValues(kvs ...interface{}) logr.Logger { +func (l tabLogSink) WithValues(kvs ...interface{}) logr.LogSink { newMap := make(map[string]interface{}, len(l.keyValues)+len(kvs)/2) for k, v := range l.keyValues { newMap[k] = v @@ -76,7 +71,7 @@ func (l *TabLogger) WithValues(kvs ...interface{}) logr.Logger { for i := 0; i < len(kvs); i += 2 { newMap[kvs[i].(string)] = kvs[i+1] } - return &TabLogger{ + return tabLogSink{ name: l.name, keyValues: newMap, writer: l.writer, @@ -84,7 +79,8 @@ func (l *TabLogger) WithValues(kvs ...interface{}) logr.Logger { } func NewTabLogger() logr.Logger { - return &TabLogger{ + sink := tabLogSink{ writer: tabwriter.NewWriter(os.Stderr, 40, 8, 2, '\t', 0), } + return logr.New(0, sink) } diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go index 2971e20..c38e0fc 100644 --- a/funcr/funcr_test.go +++ b/funcr/funcr_test.go @@ -1,3 +1,19 @@ +/* +Copyright 2021 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 funcr import ( diff --git a/logr.go b/logr.go index 1d12a3c..8bb4381 100644 --- a/logr.go +++ b/logr.go @@ -17,84 +17,110 @@ limitations under the License. // This design derives from Dave Cheney's blog: // http://dave.cheney.net/2015/11/05/lets-talk-about-logging // -// This is a BETA grade API. Until there is a significant 2nd implementation, -// I don't really know how it will change. +// This is a BETA grade API. -// Package logr defines abstract interfaces for logging. Packages can depend on -// these interfaces and callers can implement logging in whatever way is -// appropriate. +// Package logr defines a general-purpose logging API and abstract interfaces +// to back that API. Packages in the Go ecosystem can depend on this package, +// while callers can implement logging with whatever backend is appropriate. // // Usage +// ----- // -// Logging is done using a Logger. Loggers can have name prefixes and named -// values attached, so that all log messages logged with that Logger have some -// base context associated. +// Logging is done using a Logger instance. Logger is a concrete type with +// methods, which defers the actual logging to a LogSink interface. The main +// methods of Logger are Info() and Error(). Arguments to Info() and Error() +// are key/value pairs rather than printf-style formatted strings, emphasizing +// "structured logging". // -// The term "key" is used to refer to the name associated with a particular -// value, to disambiguate it from the general Logger name. +// With Go's standard log package, we might write: +// log.Printf("setting target value %s", targetValue) // -// For instance, suppose we're trying to reconcile the state of an object, and -// we want to log that we've made some decision. +// With logr's structured logging, we'd write: +// logger.Info("setting target", "value", targetValue) // -// With the traditional log package, we might write: -// log.Printf("decided to set field foo to value %q for object %s/%s", -// targetValue, object.Namespace, object.Name) +// Errors are much the same. Instead of: +// log.Printf("failed to open the pod bay door for user %s: %v", user, err) // -// With logr's structured logging, we'd write: -// // elsewhere in the file, set up the logger to log with the prefix of -// // "reconcilers", and the named value target-type=Foo, for extra context. -// log := mainLogger.WithName("reconcilers").WithValues("target-type", "Foo") +// We'd write: +// logger.Error(err, "failed to open the pod bay door", "user", user) // -// // later on... -// log.Info("setting foo on object", "value", targetValue, "object", object) +// Info() and Error() are very similar, but they are separate methods so that +// LogSink implementations can choose to do things like attach additional +// information (such as stack traces) on calls to Error(). // -// Depending on our logging implementation, we could then make logging decisions -// based on field values (like only logging such events for objects in a certain -// namespace), or copy the structured information into a structured log store. +// Verbosity +// --------- // -// For logging errors, Logger has a method called Error. Suppose we wanted to -// log an error while reconciling. With the traditional log package, we might -// write: -// log.Errorf("unable to reconcile object %s/%s: %v", object.Namespace, object.Name, err) +// Often we want to log information only when the application in "verbose +// mode". To write log-lines that are more verbose, Logger has a V() method. +// The higher the V-level of a log-line, the less critical it is considered. +// Log-lines with V-levels that are not enabled (as per the LogSink) will not +// be written. Level V(0) is the default, and logger.V(0).Info() has the same +// meaning as logger.Info(). Negative V-levels have the same meaning as V(0). // -// With logr, we'd instead write: -// // assuming the above setup for log -// log.Error(err, "unable to reconcile object", "object", object) +// Where we might have written: +// if flVerbose >= 2 { +// log.Printf("an unusual thing happened") +// } +// +// We can write: +// logger.V(2).Info("an unusual thing happened") // -// This functions similarly to: -// log.Info("unable to reconcile object", "error", err, "object", object) +// Logger Names +// ------------ // -// However, it ensures that a standard key for the error value ("error") is used -// across all error logging. Furthermore, certain implementations may choose to -// attach additional information (such as stack traces) on calls to Error, so -// it's preferred to use Error to log errors. +// Logger instances can have name strings so that all messages logged through +// that instance have additional context. For example, you might want to add +// a subsystem name: // -// Parts of a log line +// logger.WithName("compactor").Info("started", "time", time.Now()) // -// Each log message from a Logger has four types of context: -// logger name, log verbosity, log message, and the named values. +// The WithName() method returns a new Logger, which can be passed to +// constructors or other functions for further use. Repeated use of WithName() +// will accumulate name "segments". These name segments will be joined in some +// way by the LogSink implementation. It is strongly recommended that name +// segments contain simple identifiers (letters, digits, and hyphen), and do +// not contain characters that could muddle the log output or confuse the +// joining operation (e.g. whitespace, commas, periods, slashes, brackets, +// quotes, etc). // -// The Logger name consists of a series of name "segments" added by successive -// calls to WithName. These name segments will be joined in some way by the -// underlying implementation. It is strongly recommended that name segments -// contain simple identifiers (letters, digits, and hyphen), and do not contain -// characters that could muddle the log output or confuse the joining operation -// (e.g. whitespace, commas, periods, slashes, brackets, quotes, etc). +// Saved Values +// ------------ // -// Log verbosity represents how little a log matters. Level zero, the default, -// matters most. Increasing levels matter less and less. Try to avoid lots of -// different verbosity levels, and instead provide useful keys, logger names, -// and log messages for users to filter on. It's illegal to pass a log level -// below zero. +// Logger instances can store any number of key/value pairs, which will be +// logged alongside all messages logged through that instance. For example, +// you might want to create a Logger instance per managed object: +// +// With the standard log package, we might write: +// log.Printf("decided to set field foo to value %q for object %s/%s", +// targetValue, object.Namespace, object.Name) +// +// With logr's we'd write: +// // Elsewhere: set up the logger to log the object name. +// obj.logger = mainLogger.WithValues( +// "name", obj.name, "namespace", obj.namespace) +// +// // later on... +// obj.logger.Info("setting foo", "value", targetValue) +// +// Best Practices +// -------------- +// +// Logger has very few hard rules, with the goal that LogSink implementations +// might have a lot of freedom to differentiate. There are, however, some +// things to consider. // // The log message consists of a constant message attached to the log line. // This should generally be a simple description of what's occurring, and should -// never be a format string. +// never be a format string. Variable information can then be attached using +// named values. // -// Variable information can then be attached using named values (key/value -// pairs). Keys are arbitrary strings, while values may be any Go value. +// Keys are arbitrary strings, but should generally be constant values. Values +// may be any Go value, but how the value is formatted is determined by the +// LogSink implementation. // // Key Naming Conventions +// ---------------------- // // Keys are not strictly required to conform to any specification or regex, but // it is recommended that they: @@ -125,6 +151,9 @@ limitations under the License. // would be necessary to represent at least message and timestamp as ordinary // named values). // +// Break Glass +// ----------- +// // Implementations may choose to give callers access to the underlying // logging implementation. The recommended pattern for this is: // // Underlier exposes access to the underlying logging implementation. @@ -140,89 +169,110 @@ import ( "context" ) -// LogSink represents the ability to log messages, both errors and not. -type LogSink interface { - // Enabled tests whether this LogSink is enabled. For example, commandline - // flags might be used to set the logging verbosity and disable some info - // logs. - Enabled(level int) bool - - // Info logs a non-error message with the given key/value pairs as context. - // - // The msg argument should be used to add some constant description to - // the log line. The key/value pairs can then be used to add additional - // variable information. The key/value pairs should alternate string - // keys and arbitrary values. - Info(level int, msg string, keysAndValues ...interface{}) - - // Error logs an error, with the given message and key/value pairs as context. - // It functions similarly to calling Info with the "error" named value, but may - // have unique behavior, and should be preferred for logging errors (see the - // package documentations for more information). - // - // The msg field should be used to add context to any underlying error, - // while the err field should be used to attach the actual error that - // triggered this log line, if present. - Error(err error, msg string, keysAndValues ...interface{}) - - // WithValues adds some key-value pairs of context to a logger. - // See Info for documentation on how key/value pairs work. - WithValues(keysAndValues ...interface{}) LogSink - - // WithName adds a new element to the logger's name. - // Successive calls with WithName continue to append - // suffixes to the logger's name. It's strongly recommended - // that name segments contain only letters, digits, and hyphens - // (see the package documentation for more information). - WithName(name string) LogSink -} - +// New returns a new Logger instance. This is primarily used by libraries +// implementing LogSink, rather than end users. func New(level int, sink LogSink) Logger { - return Logger{ + logger := Logger{ level: level, sink: sink, } + if withCallDepth, ok := sink.(CallDepthLogSink); ok { + logger.withCallDepth = withCallDepth + } + return logger } -// Logger is a concrete type, for performance reasons, but all the real work is -// passed on to a LogSink. Implementations of LogSink should provide their own -// constructors thsat return Logger, not LogSink. +// Logger is an interface to an abstract logging implementation. This is a +// concrete type for performance reasons, but all the real work is passed on +// to a LogSink. Implementations of LogSink should provide their own +// constructors that return Logger, not LogSink. type Logger struct { - level int - sink LogSink + level int + sink LogSink + withCallDepth CallDepthLogSink } +// 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 { return l.sink.Enabled(l.level) } +// Info logs a non-error message with the given key/value pairs as context. +// +// The msg argument should be used to add some constant description to +// the log 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{}) { if l.Enabled() { l.sink.Info(l.level, msg, keysAndValues...) } } +// Error logs an error, with the given message and key/value pairs as context. +// It functions similarly to Info, but may have unique behavior, and should be +// preferred for logging errors (see the package documentations for more +// information). +// +// The msg argument should be used to add context to any underlying error, +// while the err argument should be used to attach the actual error that +// triggered this log line, if present. func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) { if l.Enabled() { l.sink.Error(err, msg, keysAndValues...) } } +// V returns a new Logger instance for a specific verbosity level, relative to +// this Logger. In other words, V-levels are additive. A higher verbosity +// level means a log message is less important. Negative V-levels are treated +// as 0. func (l Logger) V(level int) Logger { + if level < 0 { + level = 0 + } l.level += level return l } +// 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 { l.sink = l.sink.WithValues(keysAndValues...) return l } +// WithName returns a new Logger instance with the specified name element added +// to the Logger's name. Successive calls with WithName append additional +// suffixes to the Logger's name. It's strongly recommended that name segments +// contain only letters, digits, and hyphens (see the package documentation for +// more information). func (l Logger) WithName(name string) Logger { l.sink = l.sink.WithName(name) return l } +// WithCallDepth returns a Logger instance that offsets the call stack by the +// specified number of frames when logging call site information, if possible. +// This is useful for users who have helper functions between the "real" call +// site and the actual calls to Logger methods. If depth is 0 the attribution +// should be to the direct caller of this function. If depth is 1 the +// attribution should skip 1 call frame, and so on. Successive calls to this +// are additive. +// +// If the underlying log implementation supports a WithCallDepth(int) method, +// it will be called and the result returned. If the implementation does not +// support CallDepthLogSink, the original Logger will be returned. +func (l Logger) WithCallDepth(depth int) Logger { + if l.withCallDepth == nil { + return l + } + l.sink = l.withCallDepth.WithCallDepth(depth) + return l +} + // InfoLogger provides compatibility with code that relies on the v0.1.0 // interface. // @@ -231,21 +281,31 @@ func (l Logger) WithName(name string) Logger { // will be removed in a future release. type InfoLogger = Logger +// contextKey is how we find Loggers in a context.Context. type contextKey struct{} -// FromContext returns a Logger constructed from ctx or nil if no -// logger details are found. -func FromContext(ctx context.Context) Logger { +// FromContext returns a Logger from ctx or an error if no Logger is found. +func FromContext(ctx context.Context) (Logger, error) { if v, ok := ctx.Value(contextKey{}).(Logger); ok { - return v + return v, nil } - //FIXME: what to do here? Could switch to pointers, but yuck? - return Logger{} + return Logger{}, notFoundError{} } -// FromContextOrDiscard returns a Logger constructed from ctx or a Logger -// that discards all messages if no logger details are found. +// notFoundError exists to carry an IsNotFound method. +type notFoundError struct{} + +func (notFoundError) Error() string { + return "no logr.Logger was present" +} + +func (notFoundError) IsNotFound() bool { + return true +} + +// FromContextOrDiscard returns a Logger from ctx. If no Logger is found, this +// returns a Logger that discards all log messages. func FromContextOrDiscard(ctx context.Context) Logger { if v, ok := ctx.Value(contextKey{}).(Logger); ok { return v @@ -254,12 +314,40 @@ func FromContextOrDiscard(ctx context.Context) Logger { return Discard() } -// NewContext returns a new context derived from ctx that embeds the Logger. -func NewContext(ctx context.Context, l Logger) context.Context { - return context.WithValue(ctx, contextKey{}, l) +// NewContext returns a new Context, derived from ctx, which carries the +// provided Logger. +func NewContext(ctx context.Context, logger Logger) context.Context { + return context.WithValue(ctx, contextKey{}, logger) +} + +// LogSink represents a logging implementation. End-users will generally not +// interact with this type. +type LogSink interface { + // Enabled tests whether this LogSink is enabled at the specified V-level. + // For example, commandline flags might be used to set the logging + // verbosity and disable some info logs. + Enabled(level int) bool + + // Info logs a non-error message with the given key/value pairs as context. + // 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{}) + + // 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{}) + + // WithValues returns a new LogSink with additional key/value pairs. See + // Logger.WithValues for more details. + WithValues(keysAndValues ...interface{}) LogSink + + // WithName returns a new LogSink with the specified name appended. See + // Logger.WithName for more details. + WithName(name string) LogSink } -// CallDepthLogger represents a Logger that knows how to climb the call stack +// CallDepthLogSink represents a Logger that knows how to climb the call stack // to identify the original call site and can offset the depth by a specified // number of frames. This is useful for users who have helper functions // between the "real" call site and the actual calls to Logger methods. @@ -286,16 +374,13 @@ type CallDepthLogSink interface { // attribution should skip 1 call frame, and so on. Successive calls to this // are additive. // -// If the underlying log implementation supports the CallDepthLogger interface, -// the WithCallDepth method will be called and the result returned. If the -// implementation does not support CallDepthLogger, the original Logger will be -// returned. +// If the underlying log implementation supports a WithCallDepth(int) method, +// it will be called and the result returned. If the implementation does not +// support CallDepthLogSink, the original Logger will be returned. // -// Callers which care about whether this was supported or not should test for -// CallDepthLogger support themselves. +// Deprecated: WithCallDepth is an artifact of early versions of this API. New +// users should never use it and existing users should use Logger.WithCallDepth +// instead. This will be removed in a future release. func WithCallDepth(logger Logger, depth int) Logger { - if decorator, ok := logger.sink.(CallDepthLogSink); ok { - logger.sink = decorator.WithCallDepth(depth) - } - return logger + return logger.WithCallDepth(depth) } diff --git a/logr_test.go b/logr_test.go index e88f888..619e544 100644 --- a/logr_test.go +++ b/logr_test.go @@ -21,91 +21,88 @@ import ( "testing" ) -// testLogger is a Logger just for testing that does nothing. -type testLogger struct{} +// testLogSink is a Logger just for testing that does nothing. +type testLogSink struct{} -func (l *testLogger) Enabled() bool { +func (l *testLogSink) Enabled(int) bool { return false } -func (l *testLogger) Info(msg string, keysAndValues ...interface{}) { +func (l *testLogSink) Info(level int, msg string, keysAndValues ...interface{}) { } -func (l *testLogger) Error(err error, msg string, keysAndValues ...interface{}) { +func (l *testLogSink) Error(err error, msg string, keysAndValues ...interface{}) { } -func (l *testLogger) V(level int) Logger { +func (l *testLogSink) WithValues(keysAndValues ...interface{}) LogSink { return l } -func (l *testLogger) WithValues(keysAndValues ...interface{}) Logger { - return l -} - -func (l *testLogger) WithName(name string) Logger { +func (l *testLogSink) WithName(name string) LogSink { return l } // Verify that it actually implements the interface -var _ Logger = &testLogger{} +var _ LogSink = &testLogSink{} func TestContext(t *testing.T) { ctx := context.TODO() - if out := FromContext(ctx); out != nil { - t.Errorf("expected nil logger, got %#v", out) + if out, err := FromContext(ctx); err == nil { + t.Errorf("expected error, got %#v", out) } - if out := FromContextOrDiscard(ctx); out == nil { - t.Errorf("expected non-nil logger") - } else if _, ok := out.(DiscardLogger); !ok { + out := FromContextOrDiscard(ctx) + if _, ok := out.sink.(DiscardLogger); !ok { t.Errorf("expected a DiscardLogger, got %#v", out) } - logger := &testLogger{} + sink := &testLogSink{} + logger := New(0, sink) lctx := NewContext(ctx, logger) - if out := FromContext(lctx); out == nil { - t.Errorf("expected non-nil logger") - } else if out.(*testLogger) != logger { - t.Errorf("expected output to be the same as input: got in=%p, out=%p", logger, out) + if out, err := FromContext(lctx); err != nil { + t.Errorf("unexpected error: %v", err) + } else if p := out.sink.(*testLogSink); p != sink { + t.Errorf("expected output to be the same as input: got in=%p, out=%p", sink, p) } - if out := FromContextOrDiscard(lctx); out == nil { - t.Errorf("expected non-nil logger") - } else if out.(*testLogger) != logger { - t.Errorf("expected output to be the same as input: got in=%p, out=%p", logger, out) + out = FromContextOrDiscard(lctx) + if p := out.sink.(*testLogSink); p != sink { + t.Errorf("expected output to be the same as input: got in=%p, out=%p", sink, p) } } -// testCallDepthLogger is a Logger just for testing that does nothing. -type testCallDepthLogger struct { - *testLogger +// testCallDepthLogSink is a Logger just for testing that does nothing. +type testCallDepthLogSink struct { + *testLogSink depth int } -func (l *testCallDepthLogger) WithCallDepth(depth int) Logger { - return &testCallDepthLogger{l.testLogger, l.depth + depth} +func (l *testCallDepthLogSink) WithCallDepth(depth int) LogSink { + return &testCallDepthLogSink{l.testLogSink, l.depth + depth} } // Verify that it actually implements the interface -var _ CallDepthLogger = &testCallDepthLogger{} +var _ CallDepthLogSink = &testCallDepthLogSink{} func TestWithCallDepth(t *testing.T) { // Test an impl that does not support it. t.Run("not supported", func(t *testing.T) { - in := &testLogger{} - out := WithCallDepth(in, 42) - if out.(*testLogger) != in { - t.Errorf("expected output to be the same as input: got in=%p, out=%p", in, out) + in := &testLogSink{} + l := New(0, in) + out := l.WithCallDepth(42) + if p := out.sink.(*testLogSink); p != in { + t.Errorf("expected output to be the same as input: got in=%p, out=%p", in, p) } }) // Test an impl that does support it. t.Run("supported", func(t *testing.T) { - in := &testCallDepthLogger{&testLogger{}, 0} - out := WithCallDepth(in, 42) - if out.(*testCallDepthLogger) == in { + in := &testCallDepthLogSink{&testLogSink{}, 0} + l := New(0, in) + out := l.WithCallDepth(42) + if out.sink.(*testCallDepthLogSink) == in { t.Errorf("expected output to be different than input: got in=out=%p", in) } - if cdl := out.(*testCallDepthLogger); cdl.depth != 42 { + if cdl := out.sink.(*testCallDepthLogSink); cdl.depth != 42 { t.Errorf("expected depth=42, got %d", cdl.depth) } }) diff --git a/testing/test.go b/testing/test.go index 1222fae..98f7f78 100644 --- a/testing/test.go +++ b/testing/test.go @@ -20,36 +20,14 @@ import ( "testing" "github.com/go-logr/logr" + "github.com/go-logr/logr/funcr" ) -// TestLogger is a logr.Logger that prints through a testing.T object. -// Only error logs will have any effect. -type TestLogger struct { - T *testing.T -} - -var _ logr.Logger = TestLogger{} - -func (_ TestLogger) Info(_ string, _ ...interface{}) { - // Do nothing. -} - -func (_ TestLogger) Enabled() bool { - return false -} - -func (log TestLogger) Error(err error, msg string, args ...interface{}) { - log.T.Logf("%s: %v -- %v", msg, err, args) -} - -func (log TestLogger) V(v int) logr.Logger { - return log -} - -func (log TestLogger) WithName(_ string) logr.Logger { - return log -} - -func (log TestLogger) WithValues(_ ...interface{}) logr.Logger { - return log +// NewTestLogger returns a logr.Logger that prints through a testing.T object. +// Info logs are only enabled at V(0). +func NewTestLogger(t *testing.T) logr.Logger { + fn := func(prefix, args string) { + t.Logf("%s: %s", prefix, args) + } + return funcr.New(fn, funcr.Options{}) } diff --git a/testing/test_test.go b/testing/test_test.go new file mode 100644 index 0000000..467518d --- /dev/null +++ b/testing/test_test.go @@ -0,0 +1,30 @@ +/* +Copyright 2021 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 testing + +import ( + "fmt" + "testing" +) + +func TestTestLogger(t *testing.T) { + logger := NewTestLogger(t) + logger.Info("info") + logger.V(0).Info("V(0).info") + logger.V(1).Info("v(1).info") + logger.Error(fmt.Errorf("error"), "error") +} From 000e78e4b68fb8cd158a2c39ac90a3e0d86da092 Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Thu, 22 Apr 2021 22:36:02 -0700 Subject: [PATCH 4/6] simpler logr.New() signature --- examples/tab_logger.go | 2 +- funcr/funcr.go | 2 +- logr.go | 5 ++--- logr_test.go | 6 +++--- 4 files changed, 7 insertions(+), 8 deletions(-) diff --git a/examples/tab_logger.go b/examples/tab_logger.go index 46e2ac2..46df2db 100644 --- a/examples/tab_logger.go +++ b/examples/tab_logger.go @@ -82,5 +82,5 @@ func NewTabLogger() logr.Logger { sink := tabLogSink{ writer: tabwriter.NewWriter(os.Stderr, 40, 8, 2, '\t', 0), } - return logr.New(0, sink) + return logr.New(sink) } diff --git a/funcr/funcr.go b/funcr/funcr.go index 923c80e..34c19f4 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -41,7 +41,7 @@ func New(fn func(prefix, args string), opts Options) logr.Logger { logCaller: opts.LogCaller, verbosity: opts.Verbosity, } - return logr.New(0, fnl) + return logr.New(fnl) } type Options struct { diff --git a/logr.go b/logr.go index 8bb4381..05e36e5 100644 --- a/logr.go +++ b/logr.go @@ -171,10 +171,9 @@ import ( // New returns a new Logger instance. This is primarily used by libraries // implementing LogSink, rather than end users. -func New(level int, sink LogSink) Logger { +func New(sink LogSink) Logger { logger := Logger{ - level: level, - sink: sink, + sink: sink, } if withCallDepth, ok := sink.(CallDepthLogSink); ok { logger.withCallDepth = withCallDepth diff --git a/logr_test.go b/logr_test.go index 619e544..60a1c7b 100644 --- a/logr_test.go +++ b/logr_test.go @@ -57,7 +57,7 @@ func TestContext(t *testing.T) { } sink := &testLogSink{} - logger := New(0, sink) + logger := New(sink) lctx := NewContext(ctx, logger) if out, err := FromContext(lctx); err != nil { t.Errorf("unexpected error: %v", err) @@ -87,7 +87,7 @@ func TestWithCallDepth(t *testing.T) { // Test an impl that does not support it. t.Run("not supported", func(t *testing.T) { in := &testLogSink{} - l := New(0, in) + l := New(in) out := l.WithCallDepth(42) if p := out.sink.(*testLogSink); p != in { t.Errorf("expected output to be the same as input: got in=%p, out=%p", in, p) @@ -97,7 +97,7 @@ func TestWithCallDepth(t *testing.T) { // Test an impl that does support it. t.Run("supported", func(t *testing.T) { in := &testCallDepthLogSink{&testLogSink{}, 0} - l := New(0, in) + l := New(in) out := l.WithCallDepth(42) if out.sink.(*testCallDepthLogSink) == in { t.Errorf("expected output to be different than input: got in=out=%p", in) From 19480e9f17db08bddf290c7b6b3205c7d7183696 Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Sun, 16 May 2021 16:26:45 -0700 Subject: [PATCH 5/6] Add LogSink.Init() mechanism This allows logr to pass params about internal stuff (such as the number of call frames it adds) to LogSink implementations. --- discard.go | 3 +++ examples/tab_logger.go | 3 +++ funcr/funcr.go | 42 +++++++++++++++++++++++++----------------- logr.go | 20 ++++++++++++++++++++ logr_test.go | 3 +++ 5 files changed, 54 insertions(+), 17 deletions(-) diff --git a/discard.go b/discard.go index 9a36257..97e64c2 100644 --- a/discard.go +++ b/discard.go @@ -31,6 +31,9 @@ type DiscardLogger struct{} // Verify that it actually implements the interface var _ LogSink = DiscardLogger{} +func (l DiscardLogger) Init(RuntimeInfo) { +} + func (l DiscardLogger) Enabled(int) bool { return false } diff --git a/examples/tab_logger.go b/examples/tab_logger.go index 46df2db..84892ae 100644 --- a/examples/tab_logger.go +++ b/examples/tab_logger.go @@ -34,6 +34,9 @@ type tabLogSink struct { var _ logr.LogSink = tabLogSink{} +func (_ tabLogSink) Init(info logr.RuntimeInfo) { +} + func (_ tabLogSink) Enabled(level int) bool { return true } diff --git a/funcr/funcr.go b/funcr/funcr.go index 34c19f4..4262969 100644 --- a/funcr/funcr.go +++ b/funcr/funcr.go @@ -33,7 +33,7 @@ import ( // New returns a logr.Logger which is implemented by a function. func New(fn func(prefix, args string), opts Options) logr.Logger { - fnl := fnlogger{ + fnl := &fnlogger{ prefix: "", values: nil, depth: 0, @@ -267,16 +267,18 @@ type callerID struct { } func (l fnlogger) caller() callerID { - // +1 for this frame, +1 for logr itself. - // FIXME: Maybe logr should offer a clue as to how many frames are - // needed here? Or is it part of the contract to LogSinks? - _, file, line, ok := runtime.Caller(framesToCaller() + l.depth + 2) + // +1 for this frame. + _, file, line, ok := runtime.Caller(framesToCaller() + l.depth + 1) if !ok { return callerID{"", 0} } return callerID{filepath.Base(file), line} } +func (l *fnlogger) Init(info logr.RuntimeInfo) { + l.depth += info.CallDepth +} + func (l fnlogger) Enabled(level int) bool { return level <= l.verbosity } @@ -313,25 +315,31 @@ func (l fnlogger) Error(err error, msg string, kvList ...interface{}) { // WithName returns a new Logger with the specified name appended. funcr // uses '/' characters to separate name elements. Callers should not pass '/' // in the provided name string, but this library does not actually enforce that. -func (l fnlogger) WithName(name string) logr.LogSink { - if len(l.prefix) > 0 { - l.prefix = l.prefix + "/" +func (l *fnlogger) WithName(name string) logr.LogSink { + l2 := &fnlogger{} + *l2 = *l + if len(l2.prefix) > 0 { + l.prefix = l2.prefix + "/" } - l.prefix += name + l2.prefix += name return l } -func (l fnlogger) WithValues(kvList ...interface{}) logr.LogSink { +func (l *fnlogger) WithValues(kvList ...interface{}) logr.LogSink { + l2 := &fnlogger{} + *l2 = *l // Three slice args forces a copy. n := len(l.values) - l.values = append(l.values[:n:n], kvList...) - return l + l2.values = append(l2.values[:n:n], kvList...) + return l2 } -func (l fnlogger) WithCallDepth(depth int) logr.LogSink { - l.depth += depth - return l +func (l *fnlogger) WithCallDepth(depth int) logr.LogSink { + l2 := &fnlogger{} + *l2 = *l + l2.depth += depth + return l2 } -var _ logr.LogSink = fnlogger{} -var _ logr.CallDepthLogSink = fnlogger{} +var _ logr.LogSink = &fnlogger{} +var _ logr.CallDepthLogSink = &fnlogger{} diff --git a/logr.go b/logr.go index 05e36e5..c0eb273 100644 --- a/logr.go +++ b/logr.go @@ -178,6 +178,7 @@ func New(sink LogSink) Logger { if withCallDepth, ok := sink.(CallDepthLogSink); ok { logger.withCallDepth = withCallDepth } + sink.Init(runtimeInfo) return logger } @@ -319,9 +320,28 @@ func NewContext(ctx context.Context, logger Logger) context.Context { return context.WithValue(ctx, contextKey{}, logger) } +// RuntimeInfo holds information that the logr "core" library knows which +// LogSinks might want to know. +type RuntimeInfo struct { + // CallDepth is the number of call frames the logr library adds between the + // end-user and the LogSink. LogSink implementations which choose to print + // the original logging site (e.g. file & line) should climb this many + // additional frames to find it. + CallDepth int +} + +// runtimeInfo is a static global. It must not be changed at run time. +var runtimeInfo = RuntimeInfo{ + CallDepth: 1, +} + // LogSink represents a logging implementation. End-users will generally not // interact with this type. type LogSink interface { + // Init receives optional information about the logr library for LogSink + // implementations that need it. + Init(info RuntimeInfo) + // Enabled tests whether this LogSink is enabled at the specified V-level. // For example, commandline flags might be used to set the logging // verbosity and disable some info logs. diff --git a/logr_test.go b/logr_test.go index 60a1c7b..0d2b0d2 100644 --- a/logr_test.go +++ b/logr_test.go @@ -24,6 +24,9 @@ import ( // testLogSink is a Logger just for testing that does nothing. type testLogSink struct{} +func (l *testLogSink) Init(RuntimeInfo) { +} + func (l *testLogSink) Enabled(int) bool { return false } From 68c541ab34dfcfbd75ac96d8512073072840c1f5 Mon Sep 17 00:00:00 2001 From: Tim Hockin Date: Sun, 16 May 2021 16:31:59 -0700 Subject: [PATCH 6/6] Remove deprecated back-compat things DiscardLogger became a LogSink, so leaving that as a type was only needed for NullLogger. NullLogger can be completely replaced with Discard(). InfoLogger is vestigial and since this is a breaking change anyway, let's kill it off. Not that Logger is a type, we do not need WithCallDepth() as a standalone anymore. --- discard.go | 20 ++++++++++---------- discard_test.go | 2 +- logr.go | 27 --------------------------- logr_test.go | 4 ++-- testing/null.go | 26 -------------------------- 5 files changed, 13 insertions(+), 66 deletions(-) delete mode 100644 testing/null.go diff --git a/discard.go b/discard.go index 97e64c2..ec02a78 100644 --- a/discard.go +++ b/discard.go @@ -21,33 +21,33 @@ package logr func Discard() Logger { return Logger{ level: 0, - sink: DiscardLogger{}, + sink: discardLogger{}, } } -// DiscardLogger is a LogSink that discards all messages. -type DiscardLogger struct{} +// discardLogger is a LogSink that discards all messages. +type discardLogger struct{} // Verify that it actually implements the interface -var _ LogSink = DiscardLogger{} +var _ LogSink = discardLogger{} -func (l DiscardLogger) Init(RuntimeInfo) { +func (l discardLogger) Init(RuntimeInfo) { } -func (l DiscardLogger) Enabled(int) bool { +func (l discardLogger) Enabled(int) bool { return false } -func (l DiscardLogger) Info(int, string, ...interface{}) { +func (l discardLogger) Info(int, string, ...interface{}) { } -func (l DiscardLogger) Error(error, string, ...interface{}) { +func (l discardLogger) Error(error, string, ...interface{}) { } -func (l DiscardLogger) WithValues(...interface{}) LogSink { +func (l discardLogger) WithValues(...interface{}) LogSink { return l } -func (l DiscardLogger) WithName(string) LogSink { +func (l discardLogger) WithName(string) LogSink { return l } diff --git a/discard_test.go b/discard_test.go index 4bb1628..c1a6177 100644 --- a/discard_test.go +++ b/discard_test.go @@ -23,7 +23,7 @@ import ( func TestDiscard(t *testing.T) { l := Discard() - if _, ok := l.sink.(DiscardLogger); !ok { + if _, ok := l.sink.(discardLogger); !ok { t.Error("did not return the expected underlying type") } // Verify that none of the methods panic, there is not more we can test. diff --git a/logr.go b/logr.go index c0eb273..9ea027b 100644 --- a/logr.go +++ b/logr.go @@ -273,14 +273,6 @@ func (l Logger) WithCallDepth(depth int) Logger { return l } -// InfoLogger provides compatibility with code that relies on the v0.1.0 -// interface. -// -// Deprecated: InfoLogger is an artifact of early versions of this API. New -// users should never use it and existing users should use Logger instead. This -// will be removed in a future release. -type InfoLogger = Logger - // contextKey is how we find Loggers in a context.Context. type contextKey struct{} @@ -384,22 +376,3 @@ type CallDepthLogSink interface { // Successive calls to this are additive. WithCallDepth(depth int) LogSink } - -// WithCallDepth returns a Logger that will offset the call stack by the -// specified number of frames when logging call site information, if possible. -// This is useful for users who have helper functions between the "real" call -// site and the actual calls to Logger methods. If depth is 0 the attribution -// should be to the direct caller of this function. If depth is 1 the -// attribution should skip 1 call frame, and so on. Successive calls to this -// are additive. -// -// If the underlying log implementation supports a WithCallDepth(int) method, -// it will be called and the result returned. If the implementation does not -// support CallDepthLogSink, the original Logger will be returned. -// -// Deprecated: WithCallDepth is an artifact of early versions of this API. New -// users should never use it and existing users should use Logger.WithCallDepth -// instead. This will be removed in a future release. -func WithCallDepth(logger Logger, depth int) Logger { - return logger.WithCallDepth(depth) -} diff --git a/logr_test.go b/logr_test.go index 0d2b0d2..cb79a1b 100644 --- a/logr_test.go +++ b/logr_test.go @@ -55,8 +55,8 @@ func TestContext(t *testing.T) { t.Errorf("expected error, got %#v", out) } out := FromContextOrDiscard(ctx) - if _, ok := out.sink.(DiscardLogger); !ok { - t.Errorf("expected a DiscardLogger, got %#v", out) + if _, ok := out.sink.(discardLogger); !ok { + t.Errorf("expected a discardLogger, got %#v", out) } sink := &testLogSink{} diff --git a/testing/null.go b/testing/null.go deleted file mode 100644 index f5444b1..0000000 --- a/testing/null.go +++ /dev/null @@ -1,26 +0,0 @@ -/* -Copyright 2019 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 testing - -import "github.com/go-logr/logr" - -// NullLogger is a logr.Logger that does nothing. -// -// Deprecated: NullLogger is idenitcal to logr.DiscardLogger. It is retained -// for backwards compatibility, but new users should use logr.DiscardLogger -// instead. -type NullLogger = logr.DiscardLogger