Repository: go-logr/logr
Pull request #68 (2021-08-12 06:51:58)

embed funcr, custom With* function example
This allows custom loggers to provide their own additional methods
while using most of the implementation from funcr.
    
That funcr had to be extended to support the helper concept in
testing.T didn't feel right because fnlogger then always implemented
the CallStackHelperLogSink interface even when the helper was
nil. This gets fixed by moving the implementation of that into the
testing logger, using the new embedding mechanism of funcr.
    
As a drive-by fix, the testing logger no longer prints a redundant ":"
when the prefix is empty.
    
The logr package describes how to implement a custom With* function. A
runable example for that gets added in funcr/example_test.go.


thockin: I don't understand what's going on with FnLogSink being a distinct type.  The first commit is what I expected.  I'm not clear on the second.
pohly: `FnLogSink` is what custom `LogSink` embed into their own struct. `fnlogger` is the internal implementation of the `LogSink` interface which uses `FnLogSink`. These two must be distinct types because, for example, `fnlogger.WithName` must not be inherited by custom implementations because it wouldn't do the right thing (it copies only the struct it knows about, not the full struct of the custom implementation).

Let me add a runable example. Perhaps that'll clarify this.


pohly: I ended up refactoring funcr differently. It's now split into a formatter and the full LogSink implementation.

I also addressed one aspect of PR #60 that didn't quite feel right but couldn't be solved differently at that time: adding the helper function to `funcr.Options` was both a small API break (struct not comparable anymore), not quite the right place (not a formatting option) and had the effect that `fnlogger` always implemented the additional interface even when not needed. I reverted that change and moved the implementation of the helper handling entirely under `testing`.

The downside is that more boilerplate code is needed there.

The original purpose of this PR, providing a code example for a custom With* function, is served by the example stdout logger in `funcr/example_test.go`. The previous example in funcr itself got removed.

pohly: > As a drive-by fix, the testing logger no longer prints a redundant ":" when the prefix is empty.

Output before:
```
$ go test -v ./testing
=== RUN   TestTestLogger
    test_test.go:28: : "level"=0 "msg"="info"
    test_test.go:29: : "level"=0 "msg"="V(0).info"
    test_test.go:31: : "msg"="error" "error"="error"
    test_test.go:32: : "level"=0 "msg"="hello world"
--- PASS: TestTestLogger (0.00s)
```

Output now:

```
=== RUN   TestLogger
    test_test.go:28: "level"=0 "msg"="info"
    test_test.go:29: "level"=0 "msg"="V(0).info"
    test_test.go:31: "msg"="error" "error"="error"
    test_test.go:32: testing: "level"=0 "msg"="with prefix"
    test_test.go:33: "level"=0 "msg"="hello world"
--- PASS: TestLogger (0.00s)
```

Patch:
diff --git a/funcr/funcr.go b/funcr/funcr.go
index 69972bc..048ca58 100644
--- a/funcr/funcr.go
+++ b/funcr/funcr.go
@@ -14,9 +14,15 @@ See the License for the specific language governing permissions and
 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
+// Package funcr implements formatting of structured log messages and
+// optionally captures the call site. This will not call String or
 // Error methods on values.
+//
+// The simplest way to use it is via its implementation of a
+// github.com/go-logr/logr.LogSink with output through an arbitrary
+// "write" function. Alternatively, funcr can also be embedded inside
+// a custom LogSink implementation. This is useful when the LogSink
+// needs to implement additional methods.
 package funcr
 
 import (
@@ -47,20 +53,11 @@ type Underlier interface {
 
 func newSink(fn func(prefix, args string), opts Options) logr.LogSink {
 	l := &fnlogger{
-		prefix:       "",
-		values:       nil,
-		depth:        0,
-		write:        fn,
-		logCaller:    opts.LogCaller,
-		logTimestamp: opts.LogTimestamp,
-		verbosity:    opts.Verbosity,
-		helper:       opts.Helper,
-	}
-	if l.helper == nil {
-		// We have to have a valid function for GetCallStackHelper, so
-		// we might as well just cover the nil case once here.
-		l.helper = func() {}
+		Formatter: NewFormatter(opts),
+		write:     fn,
 	}
+	// For skipping fnlogger.Info and fnlogger.Error.
+	l.Formatter.AddCallDepth(1)
 	return l
 }
 
@@ -77,10 +74,6 @@ type Options struct {
 	// Verbosity tells funcr which V logs to be write.  Higher values enable
 	// more logs.
 	Verbosity int
-
-	// Helper is an optional function that funcr will call to mark its own
-	// stack frames as helper functions.
-	Helper func()
 }
 
 // MessageClass indicates which category or categories of messages to consider.
@@ -95,22 +88,46 @@ const (
 
 const timestampFmt = "2006-01-02 15:04:05.000000"
 
+// fnlogger inherits some of its LogSink implementation from Formatter
+// and just needs to add some glue code.
 type fnlogger struct {
-	prefix       string
-	values       []interface{}
-	depth        int
-	write        func(prefix, args string)
-	helper       func()
-	logCaller    MessageClass
-	logTimestamp bool
-	verbosity    int
+	Formatter
+	write func(prefix, args string)
+}
+
+func (l fnlogger) WithName(name string) logr.LogSink {
+	l.Formatter.AddName(name)
+	return &l
+}
+
+func (l fnlogger) WithValues(kvList ...interface{}) logr.LogSink {
+	l.Formatter.AddValues(kvList)
+	return &l
+}
+
+func (l fnlogger) WithCallDepth(depth int) logr.LogSink {
+	l.Formatter.AddCallDepth(depth)
+	return &l
+}
+
+func (l fnlogger) Info(level int, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatInfo(level, msg, kvList)
+	l.write(prefix, args)
+}
+
+func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatError(err, msg, kvList)
+	l.write(prefix, args)
+}
+
+func (l fnlogger) GetUnderlying() func(prefix, args string) {
+	return l.write
 }
 
 // Assert conformance to the interfaces.
 var _ logr.LogSink = &fnlogger{}
 var _ logr.CallDepthLogSink = &fnlogger{}
 var _ Underlier = &fnlogger{}
-var _ logr.CallStackHelperLogSink = &fnlogger{}
 
 func flatten(kvList ...interface{}) string {
 	if len(kvList)%2 != 0 {
@@ -276,9 +293,34 @@ type callerID struct {
 	Line int    `json:"line"`
 }
 
-func (l fnlogger) caller() callerID {
+// NewFormatter constructs a Formatter.
+func NewFormatter(opts Options) Formatter {
+	f := Formatter{
+		prefix:       "",
+		values:       nil,
+		depth:        0,
+		logCaller:    opts.LogCaller,
+		logTimestamp: opts.LogTimestamp,
+		verbosity:    opts.Verbosity,
+	}
+	return f
+}
+
+// Formatter is an opaque struct which can be embedded in a LogSink
+// implementation. It should be constructed with NewFormatter. Some of
+// its methods directly implement logr.LogSink.
+type Formatter struct {
+	prefix       string
+	values       []interface{}
+	depth        int
+	logCaller    MessageClass
+	logTimestamp bool
+	verbosity    int
+}
+
+func (f Formatter) caller() callerID {
 	// +1 for this frame, +1 for Info/Error.
-	_, file, line, ok := runtime.Caller(l.depth + 2)
+	_, file, line, ok := runtime.Caller(f.depth + 2)
 	if !ok {
 		return callerID{"<unknown>", 0}
 	}
@@ -286,37 +328,39 @@ func (l fnlogger) caller() callerID {
 }
 
 // Note that this receiver is a pointer, so depth can be saved.
-func (l *fnlogger) Init(info logr.RuntimeInfo) {
-	l.depth += info.CallDepth
+func (f *Formatter) Init(info logr.RuntimeInfo) {
+	f.depth += info.CallDepth
 }
 
-func (l fnlogger) Enabled(level int) bool {
-	return level <= l.verbosity
+func (f Formatter) Enabled(level int) bool {
+	return level <= f.verbosity
 }
 
-func (l fnlogger) Info(level int, msg string, kvList ...interface{}) {
+// FormatInfo flattens an Info log message into strings.
+// The prefix will be empty when no names were set.
+func (f Formatter) FormatInfo(level int, msg string, kvList []interface{}) (prefix, argsStr string) {
 	args := make([]interface{}, 0, 64) // using a constant here impacts perf
-	if l.logTimestamp {
+	if f.logTimestamp {
 		args = append(args, "ts", time.Now().Format(timestampFmt))
 	}
-	if l.logCaller == All || l.logCaller == Info {
-		args = append(args, "caller", l.caller())
+	if f.logCaller == All || f.logCaller == Info {
+		args = append(args, "caller", f.caller())
 	}
 	args = append(args, "level", level, "msg", msg)
-	args = append(args, l.values...)
+	args = append(args, f.values...)
 	args = append(args, kvList...)
-	argsStr := flatten(args...)
-	l.helper()
-	l.write(l.prefix, argsStr)
+	return f.prefix, flatten(args...)
 }
 
-func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
+// FormatInfo flattens an Error log message into strings.
+// The prefix will be empty when no names were set.
+func (f Formatter) FormatError(err error, msg string, kvList []interface{}) (prefix, argsStr string) {
 	args := make([]interface{}, 0, 64) // using a constant here impacts perf
-	if l.logTimestamp {
+	if f.logTimestamp {
 		args = append(args, "ts", time.Now().Format(timestampFmt))
 	}
-	if l.logCaller == All || l.logCaller == Error {
-		args = append(args, "caller", l.caller())
+	if f.logCaller == All || f.logCaller == Error {
+		args = append(args, "caller", f.caller())
 	}
 	args = append(args, "msg", msg)
 	var loggableErr interface{}
@@ -324,40 +368,27 @@ func (l fnlogger) Error(err error, msg string, kvList ...interface{}) {
 		loggableErr = err.Error()
 	}
 	args = append(args, "error", loggableErr)
-	args = append(args, l.values...)
+	args = append(args, f.values...)
 	args = append(args, kvList...)
-	argsStr := flatten(args...)
-	l.helper()
-	l.write(l.prefix, argsStr)
+	return f.prefix, flatten(args...)
 }
 
-// WithName returns a new Logger with the specified name appended.  funcr
+// AddName appends the specified name.  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 += "/"
+func (f *Formatter) AddName(name string) {
+	if len(f.prefix) > 0 {
+		f.prefix += "/"
 	}
-	l.prefix += name
-	return &l
+	f.prefix += name
 }
 
-func (l fnlogger) WithValues(kvList ...interface{}) logr.LogSink {
+func (f *Formatter) AddValues(kvList []interface{}) {
 	// Three slice args forces a copy.
-	n := len(l.values)
-	l.values = append(l.values[:n:n], kvList...)
-	return &l
-}
-
-func (l fnlogger) WithCallDepth(depth int) logr.LogSink {
-	l.depth += depth
-	return &l
-}
-
-func (l fnlogger) GetUnderlying() func(prefix, args string) {
-	return l.write
+	n := len(f.values)
+	f.values = append(f.values[:n:n], kvList...)
 }
 
-func (l fnlogger) GetCallStackHelper() func() {
-	return l.helper
+func (f *Formatter) AddCallDepth(depth int) {
+	f.depth += depth
 }


Test patch:
diff --git a/funcr/example_test.go b/funcr/example_test.go
index 6fae6a5..7aa2e2d 100644
--- a/funcr/example_test.go
+++ b/funcr/example_test.go
@@ -18,6 +18,7 @@ package funcr_test
 
 import (
 	"fmt"
+	"strings"
 
 	"github.com/go-logr/logr"
 	"github.com/go-logr/logr/funcr"
@@ -34,3 +35,81 @@ func ExampleUnderlier() {
 	}
 	// Output: hello world
 }
+
+// NewStdoutLogger returns a logr.Logger that prints to stdout.
+// It demonstrates how to implement a custom With* function which
+// controls whether INFO or ERROR are printed in front of the log
+// message.
+func NewStdoutLogger() logr.Logger {
+	l := &stdoutlogger{
+		Formatter: funcr.NewFormatter(funcr.Options{}),
+	}
+	return logr.New(l)
+}
+
+type stdoutlogger struct {
+	funcr.Formatter
+	logMsgType bool
+}
+
+func (l stdoutlogger) WithName(name string) logr.LogSink {
+	l.Formatter.AddName(name)
+	return &l
+}
+
+func (l stdoutlogger) WithValues(kvList ...interface{}) logr.LogSink {
+	l.Formatter.AddValues(kvList)
+	return &l
+}
+
+func (l stdoutlogger) WithCallDepth(depth int) logr.LogSink {
+	l.Formatter.AddCallDepth(depth)
+	return &l
+}
+
+func (l stdoutlogger) Info(level int, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatInfo(level, msg, kvList)
+	l.write("INFO", prefix, args)
+}
+
+func (l stdoutlogger) Error(err error, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatError(err, msg, kvList)
+	l.write("ERROR", prefix, args)
+}
+
+func (l stdoutlogger) write(msgType, prefix, args string) {
+	var parts []string
+	if l.logMsgType {
+		parts = append(parts, msgType)
+	}
+	if prefix != "" {
+		parts = append(parts, prefix)
+	}
+	parts = append(parts, args)
+	fmt.Println(strings.Join(parts, ": "))
+}
+
+// WithLogMsgType returns a copy of the logger with new settings for
+// logging the message type. It returns the original logger if the
+// underlying LogSink is not a stdoutlogger.
+func WithLogMsgType(log logr.Logger, logMsgType bool) logr.Logger {
+	if l, ok := log.GetSink().(*stdoutlogger); ok {
+		clone := *l
+		clone.logMsgType = logMsgType
+		log = log.WithSink(&clone)
+	}
+	return log
+}
+
+// Assert conformance to the interfaces.
+var _ logr.LogSink = &stdoutlogger{}
+var _ logr.CallDepthLogSink = &stdoutlogger{}
+
+func ExampleFormatter() {
+	l := NewStdoutLogger()
+	l.Info("no message type")
+	WithLogMsgType(l, true).Info("with message type")
+	// Output:
+	// "level"=0 "msg"="no message type"
+	// INFO: "level"=0 "msg"="with message type"
+}
diff --git a/testing/test.go b/testing/test.go
index 861357f..9978f8c 100644
--- a/testing/test.go
+++ b/testing/test.go
@@ -26,9 +26,65 @@ import (
 // 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.Helper()
-		t.Logf("%s: %s", prefix, args)
+	l := &testlogger{
+		Formatter: funcr.NewFormatter(funcr.Options{}),
+		t:         t,
 	}
-	return funcr.New(fn, funcr.Options{Helper: t.Helper})
+	return logr.New(l)
 }
+
+// Underlier exposes access to the underlying testing.T instance. Since
+// callers only have a logr.Logger, they have to know which
+// implementation is in use, so this interface is less of an
+// abstraction and more of a way to test type conversion.
+type Underlier interface {
+	GetUnderlying() *testing.T
+}
+
+type testlogger struct {
+	funcr.Formatter
+	t *testing.T
+}
+
+func (l testlogger) WithName(name string) logr.LogSink {
+	l.Formatter.AddName(name)
+	return &l
+}
+
+func (l testlogger) WithValues(kvList ...interface{}) logr.LogSink {
+	l.Formatter.AddValues(kvList)
+	return &l
+}
+
+func (l testlogger) GetCallStackHelper() func() {
+	return l.t.Helper
+}
+
+func (l testlogger) Info(level int, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatInfo(level, msg, kvList)
+	l.t.Helper()
+	if prefix != "" {
+		l.t.Logf("%s: %s", prefix, args)
+	} else {
+		l.t.Log(args)
+	}
+}
+
+func (l testlogger) Error(err error, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatError(err, msg, kvList)
+	l.t.Helper()
+	if prefix != "" {
+		l.t.Logf("%s: %s", prefix, args)
+	} else {
+		l.t.Log(args)
+	}
+}
+
+func (l testlogger) GetUnderlying() *testing.T {
+	return l.t
+}
+
+// Assert conformance to the interfaces.
+var _ logr.LogSink = &testlogger{}
+var _ logr.CallStackHelperLogSink = &testlogger{}
+var _ Underlier = &testlogger{}
diff --git a/testing/test_test.go b/testing/test_test.go
index e4678c3..6b69dad 100644
--- a/testing/test_test.go
+++ b/testing/test_test.go
@@ -23,12 +23,13 @@ import (
 	"github.com/go-logr/logr"
 )
 
-func TestTestLogger(t *testing.T) {
+func TestLogger(t *testing.T) {
 	log := NewTestLogger(t)
 	log.Info("info")
 	log.V(0).Info("V(0).info")
 	log.V(1).Info("v(1).info")
 	log.Error(fmt.Errorf("error"), "error")
+	log.WithName("testing").Info("with prefix")
 	Helper(log, "hello world")
 }