Repository: go-logr/logr
Pull request #74 (2021-08-17 18:46:02)

fix incremental WithCallDepth
When WithCallDepth stored the new sink, it didn't update the cached
withCallDepth implementation. When that then was called again by
another WithCallDepth, the previously incremented call depth was
overwritten.

thockin: The alternative is to do away with the cached result of the assertion, and just do it on each call.  I added this to the benchmark.  On my workstation it's ~10ns per interface assertion.  The baseline is 43ns.

On one hand, we're talking 10ns

On the other, we're talking 25%

This could get called on every log-line if there's a log helper function.

So I guess I agree with you.
pohly: Even if the benchmark result had been less clear, introducing SetSink and hiding the field would have been better because it is a more flexible API: if later it turns out that we do need caching or something else when setting a new sink, then we can't add that without an API break when the field is exported and we told users that they may set it directly.

When SetSink is the only way to modify the sink, we can add or remove such additional code without an API break. Assuming that it gets inlined, performance also should be similar to directly setting the field.

I'll rework this PR with SetSink and GetSink.
pohly: Regarding benchmarking: when users repeatedly call WithCallDepth for the same logger, caching the interface is cheaper (set once, used multiple times).

But when the usage pattern is to instantiate a logger once and use WithValues repeatedly without ever calling WithCallDepth, then we pay the price for the assertion during each WithValues call without ever using the cached value.

It looks like we need a more intelligent caching:
- in SetSink, clear the cached value and remember that it is unset.
- On demand do the assertion and remember the result for future reuse.

In this PR I am just going to do the API change. Improving the caching then becomes an implementation detail that can be tackled separately.

thockin: Yeah, I thought about the just-in-time caching, but don't know how it will go wrt reentrancy.  logr doesn't really make a lot of guarantees about locking, assuming that the copy-on-write nature will protect us, and that LogSinks will do what they need to be safe.

Once we add state in Logger itself, we need to be more careful.
thockin: On the topic of state and mutations, this isn't safe.  One goroutine could SetSink while another tries to write logs.

What if `SetSink` became `WithSink`, and followed the copy-on-write pattern.  Keep a private `setSink()` internally, so we can keep that encapsulation, I guess.  That way (I think?) no locking needed.

thockin: I suspect we will ultimately fall back on doing the interface assertion in each `WithCallDepth` to avoid the locking.
pohly: > On the topic of state and mutations, this isn't safe. One goroutine could SetSink while another tries to write logs.

If `SetSink` is used inside a custom `WithFooBar` function which takes a logger by value, then that can't happen. But I agree, it imposes constraints on the caller that aren't documented.

> What if SetSink became WithSink, and followed the copy-on-write pattern. 

That enforces the correct behavior at the cost of copying twice - not a big deal IMHO and safer, so I think we should use `WithSink`.



Patch:
diff --git a/discard.go b/discard.go
index 389f6a3..9d92a38 100644
--- a/discard.go
+++ b/discard.go
@@ -22,7 +22,7 @@ package logr
 func Discard() Logger {
 	return Logger{
 		level: 0,
-		Sink:  discardLogSink{},
+		sink:  discardLogSink{},
 	}
 }
 
diff --git a/funcr/example/main.go b/funcr/example/main.go
index 0a8131d..36bf4e6 100644
--- a/funcr/example/main.go
+++ b/funcr/example/main.go
@@ -42,10 +42,7 @@ func helper2(log logr.Logger, msg string) {
 func main() {
 	log := funcr.New(
 		func(pfx, args string) { fmt.Println(pfx, args) },
-		funcr.Options{
-			LogCaller:    funcr.All,
-			LogTimestamp: true,
-		})
+		funcr.Options{LogCaller: funcr.All})
 	example(log.WithValues("module", "example"))
 }
 
diff --git a/funcr/funcr.go b/funcr/funcr.go
index d2913ec..033cd7a 100644
--- a/funcr/funcr.go
+++ b/funcr/funcr.go
@@ -15,8 +15,7 @@ limitations under the License.
 */
 
 // Package funcr implements github.com/go-logr/logr.Logger in terms of
-// an arbitrary "write" function.  This will not call String or
-// Error methods on values.
+// an arbitrary "write" function.
 package funcr
 
 import (
@@ -27,7 +26,6 @@ import (
 	"runtime"
 	"strconv"
 	"strings"
-	"time"
 
 	"github.com/go-logr/logr"
 )
@@ -47,13 +45,12 @@ type Underlier interface {
 
 func newSink(fn func(prefix, args string), opts Options) logr.LogSink {
 	return &fnlogger{
-		prefix:       "",
-		values:       nil,
-		depth:        0,
-		write:        fn,
-		logCaller:    opts.LogCaller,
-		logTimestamp: opts.LogTimestamp,
-		verbosity:    opts.Verbosity,
+		prefix:    "",
+		values:    nil,
+		depth:     0,
+		write:     fn,
+		logCaller: opts.LogCaller,
+		verbosity: opts.Verbosity,
 	}
 }
 
@@ -63,10 +60,6 @@ type Options struct {
 	// This has some overhead, so some users might not want it.
 	LogCaller MessageClass
 
-	// LogTimestamps tells funcr to add a "ts" key to log lines.  This has some
-	// overhead, so some users might not want it.
-	LogTimestamp bool
-
 	// Verbosity tells funcr which V logs to be write.  Higher values enable
 	// more logs.
 	Verbosity int
@@ -82,16 +75,13 @@ const (
 	Error
 )
 
-const timestampFmt = "2006-01-02 15:04:05.000000"
-
 type fnlogger struct {
-	prefix       string
-	values       []interface{}
-	depth        int
-	write        func(prefix, args string)
-	logCaller    MessageClass
-	logTimestamp bool
-	verbosity    int
+	prefix    string
+	values    []interface{}
+	depth     int
+	write     func(prefix, args string)
+	logCaller MessageClass
+	verbosity int
 }
 
 // Assert conformance to the interfaces.
@@ -283,9 +273,6 @@ func (l fnlogger) Enabled(level int) bool {
 
 func (l fnlogger) Info(level int, msg string, kvList ...interface{}) {
 	args := make([]interface{}, 0, 64) // using a constant here impacts perf
-	if l.logTimestamp {
-		args = append(args, "ts", time.Now().Format(timestampFmt))
-	}
 	if l.logCaller == All || l.logCaller == Info {
 		args = append(args, "caller", l.caller())
 	}
@@ -298,9 +285,6 @@ func (l fnlogger) Info(level int, msg string, kvList ...interface{}) {
 
 func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
 	args := make([]interface{}, 0, 64) // using a constant here impacts perf
-	if l.logTimestamp {
-		args = append(args, "ts", time.Now().Format(timestampFmt))
-	}
 	if l.logCaller == All || l.logCaller == Error {
 		args = append(args, "caller", l.caller())
 	}
diff --git a/logr.go b/logr.go
index 68ee4e1..4b0effb 100644
--- a/logr.go
+++ b/logr.go
@@ -163,21 +163,21 @@ limitations under the License.
 //       GetUnderlying() <underlying-type>
 //   }
 //
-// Logger exports the Sink field to enable type assertions like this:
+// Logger grants access to the sink to enable type assertions like this:
 //   func DoSomethingWithImpl(log logr.Logger) {
-//       if underlier, ok := log.Sink(impl.Underlier) {
+//       if underlier, ok := log.GetSink()(impl.Underlier) {
 //          implLogger := underlier.GetUnderlying()
 //          ...
 //       }
 //   }
 //
 // Custom `With*` functions can be implemented by copying the complete
-// Logger struct and replacing the Sink field in the copy:
+// Logger struct and replacing the sink in the copy:
 //   // WithFooBar changes the foobar parameter in the log sink and returns a new logger with that modified sink.
 //   // It does nothing for loggers where the sink doesn't support that parameter.
 //   func WithFoobar(log logr.Logger, foobar int) logr.Logger {
-//      if foobarLogSink, ok := log.Sink(FoobarSink); ok {
-//         log.Sink = foobarLogSink.WithFooBar(foobar)
+//      if foobarLogSink, ok := log.GetSink()(FoobarSink); ok {
+//         log = log.WithSink(foobarLogSink.WithFooBar(foobar))
 //      }
 //      return log
 //   }
@@ -198,26 +198,45 @@ import (
 // New returns a new Logger instance.  This is primarily used by libraries
 // implementing LogSink, rather than end users.
 func New(sink LogSink) Logger {
-	logger := Logger{
-		Sink: sink,
-	}
-	if withCallDepth, ok := sink.(CallDepthLogSink); ok {
-		logger.withCallDepth = withCallDepth
-	}
+	logger := Logger{}
+	logger.setSink(sink)
 	sink.Init(runtimeInfo)
 	return logger
 }
 
+// setSink stores the sink and updates all related fields. It mutates
+// the logger and thus is only safe to use for loggers that are not
+// accessed concurrently.
+func (l *Logger) setSink(sink LogSink) {
+	l.sink = sink
+	// Always update the cached value to ensure that it matches
+	// the new sink, either with a valid implementation of the
+	// additional interface or nil.
+	l.withCallDepth, _ = sink.(CallDepthLogSink)
+}
+
+// GetSink returns the stored sink.
+func (l Logger) GetSink() LogSink {
+	return l.sink
+}
+
+// WithSink returns a copy of the logger with the new sink.
+func (l Logger) WithSink(sink LogSink) Logger {
+	l.setSink(sink)
+	return l
+}
+
 // 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.
+//
+// The underlying sink can be accessed through GetSink and be modified
+// through WithSink. This enables the implementation of custom
+// extensions (see "Break Glass" in the package
+// documentation). Normally the sink should be used only indirectly.
 type Logger struct {
-	// Sink is the underlying logger implementation and normally
-	// should not be accessed directly. The field gets exported to
-	// support the implementation of custom extensions (see "Break
-	// Glass" in the package documentation).
-	Sink LogSink
+	sink LogSink
 
 	level         int
 	withCallDepth CallDepthLogSink
@@ -227,7 +246,7 @@ type Logger struct {
 // 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)
+	return l.sink.Enabled(l.level)
 }
 
 // Info logs a non-error message with the given key/value pairs as context.
@@ -238,7 +257,7 @@ func (l Logger) Enabled() bool {
 // keys and arbitrary values.
 func (l Logger) Info(msg string, keysAndValues ...interface{}) {
 	if l.Enabled() {
-		l.Sink.Info(l.level, msg, keysAndValues...)
+		l.sink.Info(l.level, msg, keysAndValues...)
 	}
 }
 
@@ -251,7 +270,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.
 func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) {
-	l.Sink.Error(err, msg, keysAndValues...)
+	l.sink.Error(err, msg, keysAndValues...)
 }
 
 // V returns a new Logger instance for a specific verbosity level, relative to
@@ -269,7 +288,7 @@ func (l Logger) V(level int) Logger {
 // 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...)
+	l.setSink(l.sink.WithValues(keysAndValues...))
 	return l
 }
 
@@ -279,7 +298,7 @@ func (l Logger) WithValues(keysAndValues ...interface{}) Logger {
 // 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)
+	l.setSink(l.sink.WithName(name))
 	return l
 }
 
@@ -298,7 +317,7 @@ func (l Logger) WithCallDepth(depth int) Logger {
 	if l.withCallDepth == nil {
 		return l
 	}
-	l.Sink = l.withCallDepth.WithCallDepth(depth)
+	l.setSink(l.withCallDepth.WithCallDepth(depth))
 	return l
 }
 


Test patch:
diff --git a/benchmark/benchmark_test.go b/benchmark/benchmark_test.go
index 3f746df..0c0d0fa 100644
--- a/benchmark/benchmark_test.go
+++ b/benchmark/benchmark_test.go
@@ -87,14 +87,6 @@ func doWithName(b *testing.B, log logr.Logger) {
 	}
 }
 
-//go:noinline
-func doWithCallDepth(b *testing.B, log logr.Logger) {
-	for i := 0; i < b.N; i++ {
-		l := log.WithCallDepth(1)
-		_ = l
-	}
-}
-
 func BenchmarkDiscardInfoOneArg(b *testing.B) {
 	var log logr.Logger = logr.Discard()
 	doInfoOneArg(b, log)
@@ -164,8 +156,3 @@ func BenchmarkFuncrWithName(b *testing.B) {
 	var log logr.Logger = funcr.New(noop, funcr.Options{})
 	doWithName(b, log)
 }
-
-func BenchmarkFuncrWithCallDepth(b *testing.B) {
-	var log logr.Logger = funcr.New(noop, funcr.Options{})
-	doWithCallDepth(b, log)
-}
diff --git a/discard_test.go b/discard_test.go
index 89ffb43..c9a02de 100644
--- a/discard_test.go
+++ b/discard_test.go
@@ -24,7 +24,7 @@ import (
 
 func TestDiscard(t *testing.T) {
 	l := Discard()
-	if _, ok := l.Sink.(discardLogSink); !ok {
+	if _, ok := l.GetSink().(discardLogSink); !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/funcr/example_test.go b/funcr/example_test.go
index ebd8d20..6fae6a5 100644
--- a/funcr/example_test.go
+++ b/funcr/example_test.go
@@ -28,7 +28,7 @@ func ExampleUnderlier() {
 		fmt.Println(prefix, args)
 	}, funcr.Options{})
 
-	if underlier, ok := log.Sink.(funcr.Underlier); ok {
+	if underlier, ok := log.GetSink().(funcr.Underlier); ok {
 		fn := underlier.GetUnderlying()
 		fn("hello", "world")
 	}
diff --git a/logr_test.go b/logr_test.go
index 9b89a20..8b36c0e 100644
--- a/logr_test.go
+++ b/logr_test.go
@@ -78,6 +78,7 @@ func (l *testLogSink) WithName(name string) LogSink {
 
 type testCallDepthLogSink struct {
 	testLogSink
+	callDepth       int
 	fnWithCallDepth func(depth int)
 }
 
@@ -88,6 +89,7 @@ func (l *testCallDepthLogSink) WithCallDepth(depth int) LogSink {
 		l.fnWithCallDepth(depth)
 	}
 	out := *l
+	out.callDepth += depth
 	return &out
 }
 
@@ -103,8 +105,8 @@ func TestNew(t *testing.T) {
 	}
 	logger := New(sink)
 
-	if logger.Sink == nil {
-		t.Errorf("expected sink to be set, got %v", logger.Sink)
+	if logger.sink == nil {
+		t.Errorf("expected sink to be set, got %v", logger.sink)
 	}
 	if calledInit != 1 {
 		t.Errorf("expected sink.Init() to be called once, got %d", calledInit)
@@ -277,7 +279,7 @@ func TestWithValues(t *testing.T) {
 	if calledWithValues != 1 {
 		t.Errorf("expected sink.WithValues() to be called once, got %d", calledWithValues)
 	}
-	if p := out.Sink.(*testLogSink); p == sink {
+	if p := out.sink.(*testLogSink); p == sink {
 		t.Errorf("expected output to be different from input, got in=%p, out=%p", sink, p)
 	}
 }
@@ -299,7 +301,7 @@ func TestWithName(t *testing.T) {
 	if calledWithName != 1 {
 		t.Errorf("expected sink.WithName() to be called once, got %d", calledWithName)
 	}
-	if p := out.Sink.(*testLogSink); p == sink {
+	if p := out.sink.(*testLogSink); p == sink {
 		t.Errorf("expected output to be different from input, got in=%p, out=%p", sink, p)
 	}
 }
@@ -311,7 +313,7 @@ func TestWithCallDepthNotImplemented(t *testing.T) {
 	logger := New(sink)
 
 	out := logger.WithCallDepth(depthInput)
-	if p := out.Sink.(*testLogSink); p != sink {
+	if p := out.sink.(*testLogSink); p != sink {
 		t.Errorf("expected output to be the same as input, got in=%p, out=%p", sink, p)
 	}
 }
@@ -333,9 +335,42 @@ func TestWithCallDepthImplemented(t *testing.T) {
 	if calledWithCallDepth != 1 {
 		t.Errorf("expected sink.WithCallDepth() to be called once, got %d", calledWithCallDepth)
 	}
-	if p := out.Sink.(*testCallDepthLogSink); p == sink {
+	p := out.sink.(*testCallDepthLogSink)
+	if p == sink {
 		t.Errorf("expected output to be different from input, got in=%p, out=%p", sink, p)
 	}
+	if p.callDepth != depthInput {
+		t.Errorf("expected sink to have call depth %d, got %d", depthInput, p.callDepth)
+	}
+}
+
+func TestWithCallDepthIncremental(t *testing.T) {
+	calledWithCallDepth := 0
+	depthInput := 7
+
+	sink := &testCallDepthLogSink{}
+	sink.fnWithCallDepth = func(depth int) {
+		calledWithCallDepth++
+		if depth != 1 {
+			t.Errorf("unexpected depth input, got %d", depth)
+		}
+	}
+	logger := New(sink)
+
+	out := logger
+	for i := 0; i < depthInput; i++ {
+		out = out.WithCallDepth(1)
+	}
+	if calledWithCallDepth != depthInput {
+		t.Errorf("expected sink.WithCallDepth() to be called %d times, got %d", depthInput, calledWithCallDepth)
+	}
+	p := out.sink.(*testCallDepthLogSink)
+	if p == sink {
+		t.Errorf("expected output to be different from input, got in=%p, out=%p", sink, p)
+	}
+	if p.callDepth != depthInput {
+		t.Errorf("expected sink to have call depth %d, got %d", depthInput, p.callDepth)
+	}
 }
 
 func TestContext(t *testing.T) {
@@ -348,7 +383,7 @@ func TestContext(t *testing.T) {
 	}
 
 	out := FromContextOrDiscard(ctx)
-	if _, ok := out.Sink.(discardLogSink); !ok {
+	if _, ok := out.sink.(discardLogSink); !ok {
 		t.Errorf("expected a discardLogSink, got %#v", out)
 	}
 
@@ -357,11 +392,11 @@ func TestContext(t *testing.T) {
 	lctx := NewContext(ctx, logger)
 	if out, err := FromContext(lctx); err != nil {
 		t.Errorf("unexpected error: %v", err)
-	} else if p := out.Sink.(*testLogSink); p != sink {
+	} 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)
 	}
 	out = FromContextOrDiscard(lctx)
-	if p := out.Sink.(*testLogSink); p != sink {
+	if p := out.sink.(*testLogSink); p != sink {
 		t.Errorf("expected output to be the same as input, got in=%p, out=%p", sink, p)
 	}
 }