From 7e2e7dd9cc0334b87e683e3b14ec2e26c573ddfa Mon Sep 17 00:00:00 2001
From: Tim Hockin <thockin@google.com>
Date: Wed, 22 Dec 2021 17:00:13 -0800
Subject: [PATCH] funcr: Add a Callback type which defers arg eval

This can be used to defer expensive argument processing (large strings,
allocations, etc) when they might not be logged, such as high V levels.
When they ARE logged, the `Callback` is executed and the result value
(which is itself evaluated for Stringer and so on) is logged.
---
 funcr/example_test.go | 39 +++++++++++++++++++++++++--------------
 funcr/funcr.go        |  9 +++++++++
 funcr/funcr_test.go   |  4 ++++
 3 files changed, 38 insertions(+), 14 deletions(-)

diff --git a/funcr/example_test.go b/funcr/example_test.go
index 53373a2..b6245ba 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"
@@ -57,6 +58,28 @@ func ExampleUnderlier() {
 	// Output: hello world
 }
 
+func ExamplePseudoStruct() {
+	var log logr.Logger = funcr.NewJSON(
+		func(obj string) { fmt.Println(obj) },
+		funcr.Options{})
+	kv := []interface{}{
+		"field1", 12345,
+		"field2", true,
+	}
+	log.Info("the message", "key", funcr.PseudoStruct(kv))
+	// Output: {"logger":"","level":0,"msg":"the message","key":{"field1":12345,"field2":true}}
+}
+
+func ExampleCallback() {
+	var log logr.Logger = funcr.NewJSON(func(obj string) {
+		fmt.Println(obj)
+	}, funcr.Options{})
+	long := "I have of late but wherefore I know not lost all my mirth"
+
+	log.Info("the message", "key", funcr.Callback(func() interface{} { return strings.Fields(long)[5:9] }))
+	// Output: {"logger":"","level":0,"msg":"the message","key":["wherefore","I","know","not"]}
+}
+
 func ExampleOptions() {
 	var log logr.Logger = funcr.NewJSON(
 		func(obj string) { fmt.Println(obj) },
@@ -68,8 +91,8 @@ func ExampleOptions() {
 	log.V(1).Info("V(1) message", "key", "value")
 	log.V(2).Info("V(2) message", "key", "value")
 	// Output:
-	// {"logger":"","caller":{"file":"example_test.go","line":67},"level":0,"msg":"V(0) message","key":"value"}
-	// {"logger":"","caller":{"file":"example_test.go","line":68},"level":1,"msg":"V(1) message","key":"value"}
+	// {"logger":"","caller":{"file":"example_test.go","line":90},"level":0,"msg":"V(0) message","key":"value"}
+	// {"logger":"","caller":{"file":"example_test.go","line":91},"level":1,"msg":"V(1) message","key":"value"}
 }
 
 func ExampleOptions_renderHooks() {
@@ -100,18 +123,6 @@ func ExampleOptions_renderHooks() {
 	// Output: {"log:logger":"MyLogger","log:level":0,"log:msg":"the message","labels":{"savedKey1":"savedVal1","savedKey2":"savedVal2"},"key":"value"}
 }
 
-func ExamplePseudoStruct() {
-	var log logr.Logger = funcr.NewJSON(
-		func(obj string) { fmt.Println(obj) },
-		funcr.Options{})
-	kv := []interface{}{
-		"field1", 12345,
-		"field2", true,
-	}
-	log.Info("the message", "key", funcr.PseudoStruct(kv))
-	// Output: {"logger":"","level":0,"msg":"the message","key":{"field1":12345,"field2":true}}
-}
-
 func ExampleOptions_maxLogDepth() {
 	type List struct {
 		Next *List
diff --git a/funcr/funcr.go b/funcr/funcr.go
index b23ab96..fa61a1d 100644
--- a/funcr/funcr.go
+++ b/funcr/funcr.go
@@ -247,6 +247,11 @@ const (
 // PseudoStruct is a list of key-value pairs that gets logged as a struct.
 type PseudoStruct []interface{}
 
+// Callback is a function which gets called only when it is actually logged.
+// This can be used to defer expensive operations when they might not be logged
+// (for example at higher V levels).
+type Callback func() interface{}
+
 // render produces a log line, ready to use.
 func (f Formatter) render(builtins, args []interface{}) string {
 	// Empirically bytes.Buffer is faster than strings.Builder for this.
@@ -352,6 +357,10 @@ func (f Formatter) prettyWithFlags(value interface{}, flags uint32, depth int) s
 		// Replace the value with what the type wants to get logged.
 		// That then gets handled below via reflection.
 		value = v.MarshalLog()
+	} else if v, ok := value.(Callback); ok {
+		// Replace the value with what the callsite wants to get logged.
+		// That then gets handled below via reflection.
+		value = v()
 	}
 
 	// Handle types that want to format themselves.
diff --git a/funcr/funcr_test.go b/funcr/funcr_test.go
index a6da5b6..bbdd9c7 100644
--- a/funcr/funcr_test.go
+++ b/funcr/funcr_test.go
@@ -510,6 +510,10 @@ func TestPretty(t *testing.T) {
 			},
 			exp: `{"[{\"S\":\"\\\"quoted\\\"\"},{\"S\":\"unquoted\"}]":1}`,
 		},
+		{
+			val: Callback(func() interface{} { return []int{8, 6, 7, 5, 3, 0, 9} }),
+			exp: `[8,6,7,5,3,0,9]`,
+		},
 	}
 
 	f := NewFormatter(Options{})