Repository: rs/zerolog
Pull request #369 (2021-09-30 23:45:00)

New TestWriter for logging to testing.TB
Implements a writer to wrap testing.TB for help in testing, https://github.com/rs/zerolog/issues/368.

The go testing log injects the callers filename and line number, which is incorrect for deeply nested functions. To get around this we allow to specify the frame depth and rewrite it. Not necessary but makes it pretty. Added an option for the ConsoleWriter to set the correct frame (although it's brittle to rewrites, not sure how to test better). 


Patch:
diff --git a/go.mod b/go.mod
index 8d98653..738c6f8 100644
--- a/go.mod
+++ b/go.mod
@@ -6,5 +6,5 @@ require (
 	github.com/coreos/go-systemd/v22 v22.3.2
 	github.com/pkg/errors v0.9.1
 	github.com/rs/xid v1.3.0
-	golang.org/x/tools v0.1.5
+	golang.org/x/tools v0.1.7
 )
diff --git a/go.sum b/go.sum
index 990e427..6edd214 100644
--- a/go.sum
+++ b/go.sum
@@ -5,29 +5,29 @@ github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/rs/xid v1.3.0 h1:6NjYksEUlhurdVehpc7S7dk6DAmcKv8V9gG0FsVN2U4=
 github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
-github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
+github.com/yuin/goldmark v1.4.0/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
 golang.org/x/mod v0.4.2 h1:Gz96sIWK3OalVv/I/qNygP42zyoKp3xptRVCWRFEBvo=
 golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
 golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
-golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM=
+golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
 golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210510120138-977fb7262007 h1:gG67DSER+11cZvqIMb8S8bt0vZtiN6xWYARwirrOSfE=
-golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e h1:WUoyKPm6nCo1BnNUvPGnFG3T5DUVem42yDJZZ4CNxMA=
+golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
-golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
+golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
-golang.org/x/tools v0.1.5 h1:ouewzE6p+/VEB31YYnTbEJdi8pFqKp4P4n85vwo3DHA=
-golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk=
+golang.org/x/tools v0.1.7 h1:6j8CgantCy3yc8JGBqkDLMKWqZ0RDU2g1HVgacojGWQ=
+golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE=
diff --git a/writer.go b/writer.go
index 98c932e..26f5e63 100644
--- a/writer.go
+++ b/writer.go
@@ -1,7 +1,12 @@
 package zerolog
 
 import (
+	"bytes"
 	"io"
+	"path"
+	"runtime"
+	"strconv"
+	"strings"
 	"sync"
 )
 
@@ -96,3 +101,54 @@ func MultiLevelWriter(writers ...io.Writer) LevelWriter {
 	}
 	return multiLevelWriter{lwriters}
 }
+
+// TestingLog is the logging interface of testing.TB.
+type TestingLog interface {
+	Log(args ...interface{})
+	Logf(format string, args ...interface{})
+	Helper()
+}
+
+// TestWriter is a writer that writes to testing.TB.
+type TestWriter struct {
+	T TestingLog
+
+	// Frame skips caller frames to capture the original file and line numbers.
+	Frame int
+}
+
+// NewTestWriter creates a writer that logs to the testing.TB.
+func NewTestWriter(t TestingLog) TestWriter {
+	return TestWriter{T: t}
+}
+
+// Write to testing.TB.
+func (t TestWriter) Write(p []byte) (n int, err error) {
+	t.T.Helper()
+
+	n = len(p)
+
+	// Strip trailing newline because t.Log always adds one.
+	p = bytes.TrimRight(p, "\n")
+
+	// Try to correct the log file and line number to the caller.
+	if t.Frame > 0 {
+		_, origFile, origLine, _ := runtime.Caller(1)
+		_, frameFile, frameLine, ok := runtime.Caller(1 + t.Frame)
+		if ok {
+			erase := strings.Repeat("\b", len(path.Base(origFile))+len(strconv.Itoa(origLine))+3)
+			t.T.Logf("%s%s:%d: %s", erase, path.Base(frameFile), frameLine, p)
+			return n, err
+		}
+	}
+	t.T.Log(string(p))
+
+	return n, err
+}
+
+// ConsoleTestWriter creates an option that correctly sets the file frame depth for testing.TB log.
+func ConsoleTestWriter(t TestingLog) func(w *ConsoleWriter) {
+	return func(w *ConsoleWriter) {
+		w.Out = TestWriter{T: t, Frame: 6}
+	}
+}


Test patch:
diff --git a/writer_test.go b/writer_test.go
index 6d55ad1..0c466b0 100644
--- a/writer_test.go
+++ b/writer_test.go
@@ -1,10 +1,12 @@
-// +build !binary_log
-// +build !windows
+//go:build !binary_log && !windows
+// +build !binary_log,!windows
 
 package zerolog
 
 import (
+	"bytes"
 	"errors"
+	"fmt"
 	"io"
 	"reflect"
 	"testing"
@@ -53,45 +55,45 @@ func TestResilientMultiWriter(t *testing.T) {
 		writers []io.Writer
 	}{
 		{
-			name:    "All valid writers",
+			name: "All valid writers",
 			writers: []io.Writer{
-				mockedWriter {
+				mockedWriter{
 					wantErr: false,
 				},
-				mockedWriter {
+				mockedWriter{
 					wantErr: false,
 				},
 			},
 		},
 		{
-			name:    "All invalid writers",
+			name: "All invalid writers",
 			writers: []io.Writer{
-				mockedWriter {
+				mockedWriter{
 					wantErr: true,
 				},
-				mockedWriter {
+				mockedWriter{
 					wantErr: true,
 				},
 			},
 		},
 		{
-			name:    "First invalid writer",
+			name: "First invalid writer",
 			writers: []io.Writer{
-				mockedWriter {
+				mockedWriter{
 					wantErr: true,
 				},
-				mockedWriter {
+				mockedWriter{
 					wantErr: false,
 				},
 			},
 		},
 		{
-			name:    "First valid writer",
+			name: "First valid writer",
 			writers: []io.Writer{
-				mockedWriter {
+				mockedWriter{
 					wantErr: false,
 				},
-				mockedWriter {
+				mockedWriter{
 					wantErr: true,
 				},
 			},
@@ -110,4 +112,66 @@ func TestResilientMultiWriter(t *testing.T) {
 		}
 		writeCalls = 0
 	}
-}
\ No newline at end of file
+}
+
+type testingLog struct {
+	testing.TB
+	buf bytes.Buffer
+}
+
+func (t *testingLog) Log(args ...interface{}) {
+	if _, err := t.buf.WriteString(fmt.Sprint(args...)); err != nil {
+		t.Error(err)
+	}
+}
+
+func (t *testingLog) Logf(format string, args ...interface{}) {
+	if _, err := t.buf.WriteString(fmt.Sprintf(format, args...)); err != nil {
+		t.Error(err)
+	}
+}
+
+func TestTestWriter(t *testing.T) {
+	tests := []struct {
+		name  string
+		write []byte
+		want  []byte
+	}{{
+		name:  "newline",
+		write: []byte("newline\n"),
+		want:  []byte("newline"),
+	}, {
+		name:  "oneline",
+		write: []byte("oneline"),
+		want:  []byte("oneline"),
+	}, {
+		name:  "twoline",
+		write: []byte("twoline\n\n"),
+		want:  []byte("twoline"),
+	}}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			tb := &testingLog{TB: t} // Capture TB log buffer.
+			w := TestWriter{T: tb}
+
+			n, err := w.Write(tt.write)
+			if err != nil {
+				t.Error(err)
+			}
+			if n != len(tt.write) {
+				t.Errorf("Expected %d write length but got %d", len(tt.write), n)
+			}
+			p := tb.buf.Bytes()
+			if !bytes.Equal(tt.want, p) {
+				t.Errorf("Expected %q, got %q.", tt.want, p)
+			}
+
+			log := New(NewConsoleWriter(ConsoleTestWriter(t)))
+			log.Info().Str("name", tt.name).Msg("Success!")
+
+			tb.buf.Reset()
+		})
+	}
+
+}