Depth bomb

README.md

@@ -72,4 +72,191 @@ BenchmarkLoggers/dummy-4                 1239873             893.2 ns/op
 BenchmarkLoggers/console-4                483354              2338 ns/op             128 B/op          1 allocs/op
 BenchmarkLoggers/std-text-4               368828              3141 ns/op             132 B/op          3 allocs/op
 BenchmarkLoggers/std-json-4               393322              2909 ns/op             248 B/op          4 allocs/op
+```
+
+## Indentation
+Indentation of functions can occasionally be useful for delineating
+calls by indenting callees more than callers.
+This can sometimes help interpret logs during development.
+
+The specific case of runaway recursion shows up clearly as the messages
+march repeatedly across the screen.
+
+Indentation is configured using `console.HandlerOptins.Indent` which uses the following type:
+```go
+// Indentation configures indentation for message and attribute data.
+// If both Prefix and Tab strings are empty ("") indentation will not occur. 
+// When indenting, the message is prepended by the Prefix string (if not empty)
+// followed by the depth level iterations of the Tab string.
+// The depth level is provided by an attribute named by the Key string.
+// This should be either an integer or a pointer to a DepthLevel object.
+type Indentation struct {
+// Prefix string used before indentation (optional).
+Prefix string
+
+// Tab represents the additional indentation per depth level.
+// It is probably better to not use an actual tab character here,
+// but instead use some number of spaces.
+Tab    string
+
+// Key is the attribute key that will hold the depth number.
+// When not provided the key is set to "depth".
+Key    string
+}}
+```
+A convenience function can be used instead of
+filling out the `console.HandlerOptins.Indent` object manually for simple cases:
+```go
+// DefaultIndentation returns an Indentation struct with the specified tag string,
+// no Prefix string, and Key set to the default indentation key.
+// Other configurations (e.g. featuring a Prefix or non-default Key)
+// must be set manually.
+func DefaultIndentation(tab string) Indentation
+```
+
+### Example
+
+```go
+package main
+
+import (
+	"log/slog"
+	"os"
+
+	"github.com/phsym/console-slog"
+)
+
+func main() {
+	slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{
+		Level:  slog.LevelDebug,
+		Indent: console.DefaultIndentation("  "),
+	})))
+	slog.Info("factorial", "result", factorial(7, 0))
+}
+
+func factorial(number, depth int64) int64 {
+	slog.Debug("factorial", "number", number, "depth", depth)
+	var result int64
+	if number < 2 {
+		result = 1
+	} else {
+		result = number * factorial(number-1, depth+1)
+	}
+	slog.Debug("factorial", "result", result, "depth", depth)
+	return result
+}
+```
+
+![factorial-indent](./doc/img/factorial-indent.png)
+
+Where passing the depth number as an argument is contraindicated or just plain irritating
+it is possible to use the following object for the depth value in logging statements:
+```go
+// DepthValuer represents an indentation depth object (an int64).
+// These objects can be incremented on entry to a function and decremented in a defer statement.
+// This object is not thread safe. Using it as a global variable (the mostly likely usage)
+// in a multithreaded application will result in unpredictable values in different threads.
+type DepthValuer struct {
+	depth int
+}
+
+// LogValue implements the slog.LogValuer interface.
+func (dv *DepthValuer) LogValue() slog.Value {
+	return slog.IntValue(int(dv.depth))
+}
+
+// Increment the depth value.
+// Use this at the head of a function or important code block.
+func (dv *DepthValuer) Increment() {
+	dv.depth += 1
+}
+
+// Decrement the depth value.
+// Use this after an important code block or as a defer statement in a function.
+func (dv *DepthValuer) Decrement() {
+	dv.depth -= 1
+}
+```
+
+The use case for `DepthValuer` is to invoke its `Increment()` function at the start of a function,
+followed by a `defer` of its `Decrement()` object.
+All logging calls in the function need to append the `Indentation.Key` and a pointer to the `DepthValuer`.
+
+_It is not possible_ to add this attribute via a `WithAttrs()` call as the value is
+only evaluated once and cached by the `console.Handler` for performance reasons.
+The `Indentation.Key` and `DepthValuer` pointer must be specified in each logging call.
+
+This mechanism should be usable in code blocks but `defer` doesn't work in this case.
+The programmer is responsible for making certain that the `Decrement()` call is made in all situations.
+
+### Example:
+```go
+package main
+
+import (
+	"log/slog"
+	"os"
+
+	"github.com/phsym/console-slog"
+)
+
+var depthValuer = &console.DepthValuer{}
+
+func main() {
+	slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{
+		Level:  slog.LevelDebug,
+		Indent: console.DefaultIndentation("  "),
+	})))
+	slog.Info("factorial", "result", factorial(7))
+}
+
+func factorial(number int64) int64 {
+	depthValuer.Increment()
+	defer depthValuer.Decrement()
+	slog.Debug("factorial", "number", number, "depth", depthValuer)
+	var result int64
+	if number < 2 {
+		result = 1
+	} else {
+		result = number * factorial(number-1)
+	}
+	slog.Debug("factorial", "result", result, "depth", depthValuer)
+	return result
+}
+```
+### Performances
+See [benchmark file](./bench_test.go) for details.
+
+Benchmark results comparing console numbers with and without indentation testing:
+```
+goos: linux
+goarch: amd64
+pkg: github.com/phsym/console-slog
+cpu: Intel(R) Core(TM) i7-7820HQ CPU @ 2.90GHz
+enchmark                                          iter       time/iter   bytes alloc        allocs
+---------                                          ----       ---------   -----------        ------
+BenchmarkHandlers/dummy-8                     167386000      7.28 ns/op        0 B/op   0 allocs/op
+BenchmarkHandlers/console-8                      773392   1490.00 ns/op        0 B/op   0 allocs/op
+BenchmarkHandlers/console-indent-8               724384   1601.00 ns/op        0 B/op   0 allocs/op
+BenchmarkHandlers/std-text-8                     682894   1676.00 ns/op        2 B/op   1 allocs/op
+BenchmarkHandlers/std-json-8                     793027   1501.00 ns/op      120 B/op   3 allocs/op
+BenchmarkHandlersIndent/dummy-8               166353291      7.38 ns/op        0 B/op   0 allocs/op
+BenchmarkHandlersIndent/console-8                644863   1657.00 ns/op        0 B/op   0 allocs/op
+BenchmarkHandlersIndent/console-indent-8         699098   1754.00 ns/op        0 B/op   0 allocs/op
+BenchmarkHandlersIndent/std-text-8               608865   1781.00 ns/op        2 B/op   1 allocs/op
+BenchmarkHandlersIndent/std-json-8               696843   1574.00 ns/op      120 B/op   3 allocs/op
+BenchmarkLoggersIndent/dummy-8                  2955999    406.40 ns/op      128 B/op   1 allocs/op
+BenchmarkLoggersIndent/console-8                 543122   1953.00 ns/op      128 B/op   1 allocs/op
+BenchmarkLoggersIndent/console-indent-8          540606   2033.00 ns/op      128 B/op   1 allocs/op
+BenchmarkLoggersIndent/std-text-8                484188   2158.00 ns/op      130 B/op   2 allocs/op
+BenchmarkLoggersIndent/std-json-8                562014   1996.00 ns/op      248 B/op   4 allocs/op
+BenchmarkHandlersFactorial/dummy-8              8170125    145.30 ns/op       16 B/op   2 allocs/op
+BenchmarkHandlersFactorial/console-8            7995117    144.20 ns/op       16 B/op   2 allocs/op
+BenchmarkHandlersFactorial/console-indent-8     8149261    145.80 ns/op       16 B/op   2 allocs/op
+BenchmarkHandlersFactorial/std-text-8           7979374    144.70 ns/op       16 B/op   2 allocs/op
+BenchmarkHandlersFactorial/std-json-8           8365809    144.20 ns/op       16 B/op   2 allocs/op
+BenchmarkBuffer/std-8                         160528912      7.57 ns/op        0 B/op   0 allocs/op
+BenchmarkBuffer/buffer-8                      297744796      4.11 ns/op        0 B/op   0 allocs/op
+BenchmarkDuration/std-8                        30995145     38.00 ns/op        0 B/op   0 allocs/op
+BenchmarkDuration/append-8                     36095490     32.81 ns/op        0 B/op   0 allocs/op
 ```

bench_test.go

@@ -1,5 +1,8 @@
 package console
 
+// Run with go test -bench=. -test.benchmem | prettybench
+// Get pretty bench with go install github.com/cespare/prettybench@latest
+
 import (
 	"context"
 	"errors"
@@ -22,6 +25,7 @@ var handlers = []struct {
 }{
 	{"dummy", &DummyHandler{}},
 	{"console", NewHandler(io.Discard, &HandlerOptions{Level: slog.LevelDebug, AddSource: false})},
+	{"console-indent", NewHandler(io.Discard, &HandlerOptions{Level: slog.LevelDebug, Indent: DefaultIndentation("  ")})},
 	{"std-text", slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false})},
 	{"std-json", slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false})},
 }
@@ -63,10 +67,34 @@ func BenchmarkHandlers(b *testing.B) {
 	}
 }
 
-func BenchmarkLoggers(b *testing.B) {
+func BenchmarkHandlersIndent(b *testing.B) {
+	ctx := context.Background()
+	rec := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0)
+	rec.AddAttrs(attrs...)
+	rec.AddAttrs(slog.Attr{
+		Key:   "depth",
+		Value: slog.IntValue(5),
+	})
+
+	for _, tc := range handlers {
+		b.Run(tc.name, func(b *testing.B) {
+			l := tc.hdl.WithAttrs(attrs).WithGroup("test").WithAttrs(attrs)
+			// Warm-up
+			_ = l.Handle(ctx, rec)
+			b.ResetTimer()
+			for i := 0; i < b.N; i++ {
+				_ = l.Handle(ctx, rec)
+			}
+		})
+	}
+}
+
+func BenchmarkLoggersIndent(b *testing.B) {
 	for _, tc := range handlers {
 		ctx := context.Background()
 		b.Run(tc.name, func(b *testing.B) {
+			attrsIndent := attrs
+			attrsIndent = append(attrsIndent, slog.Int64("depth", 5))
 			l := slog.New(tc.hdl).With(attrsAny...).WithGroup("test").With(attrsAny...)
 			// Warm-up
 			l.LogAttrs(ctx, slog.LevelInfo, "hello", attrs...)
@@ -77,3 +105,29 @@ func BenchmarkLoggers(b *testing.B) {
 		})
 	}
 }
+
+// BenchmarkHandlersFactorial tests the performance of the DepthValuer.
+func BenchmarkHandlersFactorial(b *testing.B) {
+	for _, tc := range handlers {
+		b.Run(tc.name, func(b *testing.B) {
+			b.ResetTimer()
+			for i := 0; i < b.N; i++ {
+				factorial(slog.New(tc.hdl), 7)
+			}
+		})
+	}
+}
+
+var depthValuer = &DepthValuer{}
+
+func factorial(logger *slog.Logger, number int) int {
+	depthValuer.Increment()
+	depthValuer.Decrement()
+	slog.Debug("factorial", "number", number, "depth", depthValuer)
+	if number <= 1 {
+		return 1
+	}
+	result := number * factorial(logger, number-1)
+	slog.Debug("factorial", "result", result, "depth", depthValuer)
+	return result
+}

examples/indent/main.go

@@ -0,0 +1,28 @@
+package main
+
+import (
+	"log/slog"
+	"os"
+
+	"github.com/phsym/console-slog"
+)
+
+func main() {
+	slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{
+		Level:  slog.LevelDebug,
+		Indent: console.DefaultIndentation("  "),
+	})))
+	slog.Info("factorial", "result", factorial(7, 0))
+}
+
+func factorial(number, depth int64) int64 {
+	slog.Debug("factorial", "number", number, "depth", depth)
+	var result int64
+	if number < 2 {
+		result = 1
+	} else {
+		result = number * factorial(number-1, depth+1)
+	}
+	slog.Debug("factorial", "result", result, "depth", depth)
+	return result
+}

examples/indentValuer/main.go

@@ -0,0 +1,32 @@
+package main
+
+import (
+	"log/slog"
+	"os"
+
+	"github.com/phsym/console-slog"
+)
+
+var depthValuer = &console.DepthValuer{}
+
+func main() {
+	slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{
+		Level:  slog.LevelDebug,
+		Indent: console.DefaultIndentation("  "),
+	})))
+	slog.Info("factorial", "result", factorial(7))
+}
+
+func factorial(number int64) int64 {
+	depthValuer.Increment()
+	defer depthValuer.Decrement()
+	slog.Debug("factorial", "number", number, "depth", depthValuer)
+	var result int64
+	if number < 2 {
+		result = 1
+	} else {
+		result = number * factorial(number-1)
+	}
+	slog.Debug("factorial", "result", result, "depth", depthValuer)
+	return result
+}