Skip to content

Commit e3f85bf

Browse files
protolambdaprotolambda
authored
log: support context-logging (#611)
* log: support context-logging * fork.yaml: document context logging extension * cmd: update logging testdata to match slog --------- Signed-off-by: protolambda <[email protected]>
1 parent d200eea commit e3f85bf

File tree

9 files changed

+291
-51
lines changed

9 files changed

+291
-51
lines changed

‎cmd/geth/testdata/logging/logtest-json.txt‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -48,5 +48,5 @@
4848
{"t":"2023-11-22T15:42:00.40835+08:00","lvl":"info","msg":"raw nil","res":null}
4949
{"t":"2023-11-22T15:42:00.408354+08:00","lvl":"info","msg":"(*uint64)(nil)","res":null}
5050
{"t":"2023-11-22T15:42:00.408361+08:00","lvl":"info","msg":"Using keys 't', 'lvl', 'time', 'level' and 'msg'","t":"t","time":"time","lvl":"lvl","level":"level","msg":"msg"}
51-
{"t":"2023-11-29T15:13:00.195655931+01:00","lvl":"info","msg":"Odd pair (1 attr)","key":null,"LOG_ERROR":"Normalized odd number of arguments by adding nil"}
52-
{"t":"2023-11-29T15:13:00.195681832+01:00","lvl":"info","msg":"Odd pair (3 attr)","key":"value","key2":null,"LOG_ERROR":"Normalized odd number of arguments by adding nil"}
51+
{"t":"2023-11-29T15:13:00.195655931+01:00","lvl":"info","msg":"Odd pair (1 attr)","!BADKEY":"key"}
52+
{"t":"2023-11-29T15:13:00.195681832+01:00","lvl":"info","msg":"Odd pair (3 attr)","key":"value","!BADKEY":"key2"}

‎cmd/geth/testdata/logging/logtest-logfmt.txt‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -48,5 +48,5 @@ t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=nil-custom-struct res=<nil>
4848
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="raw nil" res=<nil>
4949
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg=(*uint64)(nil) res=<nil>
5050
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Using keys 't', 'lvl', 'time', 'level' and 'msg'" t=t time=time lvl=lvl level=level msg=msg
51-
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Odd pair (1 attr)" key=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"
52-
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Odd pair (3 attr)" key=value key2=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"
51+
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Odd pair (1 attr)" !BADKEY=key
52+
t=xxxx-xx-xxTxx:xx:xx+xxxx lvl=info msg="Odd pair (3 attr)" key=value !BADKEY=key2

‎cmd/geth/testdata/logging/logtest-terminal.txt‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -49,5 +49,5 @@ INFO [xx-xx|xx:xx:xx.xxx] nil-custom-struct res=<nil>
4949
INFO [xx-xx|xx:xx:xx.xxx] raw nil res=<nil>
5050
INFO [xx-xx|xx:xx:xx.xxx] (*uint64)(nil) res=<nil>
5151
INFO [xx-xx|xx:xx:xx.xxx] Using keys 't', 'lvl', 'time', 'level' and 'msg' t=t time=time lvl=lvl level=level msg=msg
52-
INFO [xx-xx|xx:xx:xx.xxx] Odd pair (1 attr) key=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"
53-
INFO [xx-xx|xx:xx:xx.xxx] Odd pair (3 attr) key=value key2=<nil> LOG_ERROR="Normalized odd number of arguments by adding nil"
52+
INFO [xx-xx|xx:xx:xx.xxx] Odd pair (1 attr) "!BADKEY"=key
53+
INFO [xx-xx|xx:xx:xx.xxx] Odd pair (3 attr) key=value "!BADKEY"=key2

‎fork.yaml‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -327,6 +327,13 @@ def:
327327
- title: "Geth extras"
328328
description: Extend the tools available in geth to improve external testing and tooling.
329329
sub:
330+
- title: Logger improvements
331+
description: |
332+
Extend the logger with context-logging support. And improve testlog Crit handling.
333+
globs:
334+
- "log/logger.go"
335+
- "log/root.go"
336+
- "internal/testlog/testlog.go"
330337
- title: JSON-RPC recording
331338
description: |
332339
Extend server and client with configurable JSON-RPC message recording.

‎internal/testlog/testlog.go‎

Lines changed: 83 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,7 @@ const (
3838
type T interface {
3939
Logf(format string, args ...any)
4040
Helper()
41+
FailNow()
4142
}
4243

4344
// logger implements log.Logger such that all output goes to the unit test log via
@@ -104,65 +105,132 @@ func (l *logger) Handler() slog.Handler {
104105
return l.l.Handler()
105106
}
106107

107-
func (l *logger) Write(level slog.Level, msg string, ctx ...interface{}) {}
108+
func (l *logger) Write(level slog.Level, msg string, args ...interface{}) {
109+
l.t.Helper()
110+
l.mu.Lock()
111+
defer l.mu.Unlock()
112+
l.l.Write(level, msg, args...)
113+
l.flush()
114+
}
115+
116+
func (l *logger) WriteCtx(ctx context.Context, level slog.Level, msg string, args ...interface{}) {
117+
l.t.Helper()
118+
l.mu.Lock()
119+
defer l.mu.Unlock()
120+
l.l.WriteCtx(ctx, level, msg, args...)
121+
l.flush()
122+
}
108123

109124
func (l *logger) Enabled(ctx context.Context, level slog.Level) bool {
110125
return l.l.Enabled(ctx, level)
111126
}
112127

113-
func (l *logger) Trace(msg string, ctx ...interface{}) {
128+
func (l *logger) Trace(msg string, args ...interface{}) {
129+
l.t.Helper()
130+
l.mu.Lock()
131+
defer l.mu.Unlock()
132+
l.l.Trace(msg, args...)
133+
l.flush()
134+
}
135+
136+
func (l *logger) Log(level slog.Level, msg string, args ...interface{}) {
137+
l.t.Helper()
138+
l.mu.Lock()
139+
defer l.mu.Unlock()
140+
l.l.Log(level, msg, args...)
141+
l.flush()
142+
}
143+
144+
func (l *logger) Debug(msg string, args ...interface{}) {
145+
l.t.Helper()
146+
l.mu.Lock()
147+
defer l.mu.Unlock()
148+
l.l.Debug(msg, args...)
149+
l.flush()
150+
}
151+
152+
func (l *logger) Info(msg string, args ...interface{}) {
153+
l.t.Helper()
154+
l.mu.Lock()
155+
defer l.mu.Unlock()
156+
l.l.Info(msg, args...)
157+
l.flush()
158+
}
159+
160+
func (l *logger) Warn(msg string, args ...interface{}) {
161+
l.t.Helper()
162+
l.mu.Lock()
163+
defer l.mu.Unlock()
164+
l.l.Warn(msg, args...)
165+
l.flush()
166+
}
167+
168+
func (l *logger) Error(msg string, args ...interface{}) {
114169
l.t.Helper()
115170
l.mu.Lock()
116171
defer l.mu.Unlock()
117-
l.l.Trace(msg, ctx...)
172+
l.l.Error(msg, args...)
118173
l.flush()
119174
}
120175

121-
func (l *logger) Log(level slog.Level, msg string, ctx ...interface{}) {
176+
func (l *logger) Crit(msg string, args ...interface{}) {
177+
l.t.Helper()
178+
l.mu.Lock()
179+
defer l.mu.Unlock()
180+
l.l.Log(log.LevelCrit, msg, args...) // Bypass the os.Exit by not using the Crit function.
181+
l.flush() // flush critical info to test-logs before exiting
182+
l.t.FailNow()
183+
}
184+
185+
func (l *logger) SetContext(ctx context.Context) {
186+
// no-op: test-logger does not use default contexts.
187+
}
188+
189+
func (l *logger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) {
122190
l.t.Helper()
123191
l.mu.Lock()
124192
defer l.mu.Unlock()
125-
l.l.Log(level, msg, ctx...)
193+
l.l.LogAttrs(ctx, level, msg, attrs...)
126194
l.flush()
127195
}
128196

129-
func (l *logger) Debug(msg string, ctx ...interface{}) {
197+
func (l *logger) TraceContext(ctx context.Context, msg string, args ...any) {
130198
l.t.Helper()
131199
l.mu.Lock()
132200
defer l.mu.Unlock()
133-
l.l.Debug(msg, ctx...)
201+
l.l.TraceContext(ctx, msg, args...)
134202
l.flush()
135203
}
136204

137-
func (l *logger) Info(msg string, ctx ...interface{}) {
205+
func (l *logger) DebugContext(ctx context.Context, msg string, args ...any) {
138206
l.t.Helper()
139207
l.mu.Lock()
140208
defer l.mu.Unlock()
141-
l.l.Info(msg, ctx...)
209+
l.l.DebugContext(ctx, msg, args...)
142210
l.flush()
143211
}
144212

145-
func (l *logger) Warn(msg string, ctx ...interface{}) {
213+
func (l *logger) InfoContext(ctx context.Context, msg string, args ...any) {
146214
l.t.Helper()
147215
l.mu.Lock()
148216
defer l.mu.Unlock()
149-
l.l.Warn(msg, ctx...)
217+
l.l.InfoContext(ctx, msg, args...)
150218
l.flush()
151219
}
152220

153-
func (l *logger) Error(msg string, ctx ...interface{}) {
221+
func (l *logger) WarnContext(ctx context.Context, msg string, args ...any) {
154222
l.t.Helper()
155223
l.mu.Lock()
156224
defer l.mu.Unlock()
157-
l.l.Error(msg, ctx...)
225+
l.l.WarnContext(ctx, msg, args...)
158226
l.flush()
159227
}
160228

161-
func (l *logger) Crit(msg string, ctx ...interface{}) {
229+
func (l *logger) ErrorContext(ctx context.Context, msg string, args ...any) {
162230
l.t.Helper()
163231
l.mu.Lock()
164232
defer l.mu.Unlock()
165-
l.l.Crit(msg, ctx...)
233+
l.l.ErrorContext(ctx, msg, args...)
166234
l.flush()
167235
}
168236

‎internal/testlog/testlog_test.go‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,8 @@ import (
77
"strings"
88
"testing"
99

10+
"github.com/stretchr/testify/require"
11+
1012
"github.com/ethereum/go-ethereum/log"
1113
)
1214

@@ -33,6 +35,10 @@ func (t *mockT) Logf(format string, args ...any) {
3335
}
3436
}
3537

38+
func (t *mockT) FailNow() {
39+
panic("mock FailNow")
40+
}
41+
3642
func TestLogging(t *testing.T) {
3743
tests := []struct {
3844
name string
@@ -65,3 +71,20 @@ func TestLogging(t *testing.T) {
6571
}
6672
}
6773
}
74+
75+
// TestCrit tests that Crit does not os.Exit in testing, and instead fails the test,
76+
// while properly flushing the log output of the critical log.
77+
func TestCrit(t *testing.T) {
78+
outp := bytes.Buffer{}
79+
mt := &mockT{&outp}
80+
l := Logger(mt, log.LevelInfo)
81+
l.Info("hello world", "a", 1)
82+
require.PanicsWithValue(t, "mock FailNow", func() {
83+
l.Crit("bye", "b", 2)
84+
})
85+
got := outp.String()
86+
expected := ` hello world a=1
87+
bye b=2
88+
`
89+
require.Equal(t, expected, got)
90+
}

0 commit comments

Comments
 (0)