Skip to content

Commit e5a56ee

Browse files
authored
Add WithPanicHook logger option for panic log tests (#1416)
Add a `WithPanicHook` logger option that allows callers to specify custom behavior besides panicking on Panic/DPanic logs. This is similar to what we already have with the WithFatal hook implemented in #861. This will make it possible to unit test Panic log cases like the one we had with our periodic runner which was impossible because of unrecoverable panics in another go routine. Added unit tests and they pass. ``` $ make test ? go.uber.org/zap/internal [no test files] ? go.uber.org/zap/internal/bufferpool [no test files] ok go.uber.org/zap (cached) ? go.uber.org/zap/internal/readme [no test files] ok go.uber.org/zap/buffer (cached) ok go.uber.org/zap/internal/color (cached) ok go.uber.org/zap/internal/exit (cached) ok go.uber.org/zap/internal/pool (cached) ok go.uber.org/zap/internal/stacktrace (cached) ok go.uber.org/zap/internal/ztest (cached) ok go.uber.org/zap/zapcore (cached) ok go.uber.org/zap/zapgrpc (cached) ok go.uber.org/zap/zapio (cached) ok go.uber.org/zap/zaptest (cached) ok go.uber.org/zap/zaptest/observer (cached) ok go.uber.org/zap/exp/zapfield (cached) ok go.uber.org/zap/exp/zapslog (cached) ok go.uber.org/zap/benchmarks (cached) [no tests to run] ok go.uber.org/zap/zapgrpc/internal/test (cached) ``` Closes #1415
1 parent 0e2aa4e commit e5a56ee

File tree

3 files changed

+160
-18
lines changed

3 files changed

+160
-18
lines changed

logger.go

Lines changed: 21 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,7 @@ type Logger struct {
4343

4444
development bool
4545
addCaller bool
46+
onPanic zapcore.CheckWriteHook // default is WriteThenPanic
4647
onFatal zapcore.CheckWriteHook // default is WriteThenFatal
4748

4849
name string
@@ -345,27 +346,12 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
345346
// Set up any required terminal behavior.
346347
switch ent.Level {
347348
case zapcore.PanicLevel:
348-
ce = ce.After(ent, zapcore.WriteThenPanic)
349+
ce = ce.After(ent, terminalHookOverride(zapcore.WriteThenPanic, log.onPanic))
349350
case zapcore.FatalLevel:
350-
onFatal := log.onFatal
351-
// nil or WriteThenNoop will lead to continued execution after
352-
// a Fatal log entry, which is unexpected. For example,
353-
//
354-
// f, err := os.Open(..)
355-
// if err != nil {
356-
// log.Fatal("cannot open", zap.Error(err))
357-
// }
358-
// fmt.Println(f.Name())
359-
//
360-
// The f.Name() will panic if we continue execution after the
361-
// log.Fatal.
362-
if onFatal == nil || onFatal == zapcore.WriteThenNoop {
363-
onFatal = zapcore.WriteThenFatal
364-
}
365-
ce = ce.After(ent, onFatal)
351+
ce = ce.After(ent, terminalHookOverride(zapcore.WriteThenFatal, log.onFatal))
366352
case zapcore.DPanicLevel:
367353
if log.development {
368-
ce = ce.After(ent, zapcore.WriteThenPanic)
354+
ce = ce.After(ent, terminalHookOverride(zapcore.WriteThenPanic, log.onPanic))
369355
}
370356
}
371357

@@ -430,3 +416,20 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
430416

431417
return ce
432418
}
419+
420+
func terminalHookOverride(defaultHook, override zapcore.CheckWriteHook) zapcore.CheckWriteHook {
421+
// A nil or WriteThenNoop hook will lead to continued execution after
422+
// a Panic or Fatal log entry, which is unexpected. For example,
423+
//
424+
// f, err := os.Open(..)
425+
// if err != nil {
426+
// log.Fatal("cannot open", zap.Error(err))
427+
// }
428+
// fmt.Println(f.Name())
429+
//
430+
// The f.Name() will panic if we continue execution after the log.Fatal.
431+
if override == nil || override == zapcore.WriteThenNoop {
432+
return defaultHook
433+
}
434+
return override
435+
}

logger_test.go

Lines changed: 124 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -836,6 +836,130 @@ func TestLoggerFatalOnNoop(t *testing.T) {
836836
assert.Equal(t, 1, exitStub.Code, "must exit with status 1 for WriteThenNoop")
837837
}
838838

839+
func TestLoggerCustomOnPanic(t *testing.T) {
840+
tests := []struct {
841+
msg string
842+
level zapcore.Level
843+
opts []Option
844+
finished bool
845+
want []observer.LoggedEntry
846+
recoverValue any
847+
}{
848+
{
849+
msg: "panic with nil hook",
850+
level: PanicLevel,
851+
opts: opts(WithPanicHook(nil)),
852+
finished: false,
853+
want: []observer.LoggedEntry{
854+
{
855+
Entry: zapcore.Entry{Level: PanicLevel, Message: "foobar"},
856+
Context: []Field{},
857+
},
858+
},
859+
recoverValue: "foobar",
860+
},
861+
{
862+
msg: "panic with noop hook",
863+
level: PanicLevel,
864+
opts: opts(WithPanicHook(zapcore.WriteThenNoop)),
865+
finished: false,
866+
want: []observer.LoggedEntry{
867+
{
868+
Entry: zapcore.Entry{Level: PanicLevel, Message: "foobar"},
869+
Context: []Field{},
870+
},
871+
},
872+
recoverValue: "foobar",
873+
},
874+
{
875+
msg: "no panic with goexit hook",
876+
level: PanicLevel,
877+
opts: opts(WithPanicHook(zapcore.WriteThenGoexit)),
878+
finished: false,
879+
want: []observer.LoggedEntry{
880+
{
881+
Entry: zapcore.Entry{Level: PanicLevel, Message: "foobar"},
882+
Context: []Field{},
883+
},
884+
},
885+
recoverValue: nil,
886+
},
887+
{
888+
msg: "dpanic no panic in development mode with goexit hook",
889+
level: DPanicLevel,
890+
opts: opts(WithPanicHook(zapcore.WriteThenGoexit), Development()),
891+
finished: false,
892+
want: []observer.LoggedEntry{
893+
{
894+
Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"},
895+
Context: []Field{},
896+
},
897+
},
898+
recoverValue: nil,
899+
},
900+
{
901+
msg: "dpanic panic in development mode with noop hook",
902+
level: DPanicLevel,
903+
opts: opts(WithPanicHook(zapcore.WriteThenNoop), Development()),
904+
finished: false,
905+
want: []observer.LoggedEntry{
906+
{
907+
Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"},
908+
Context: []Field{},
909+
},
910+
},
911+
recoverValue: "foobar",
912+
},
913+
{
914+
msg: "dpanic no exit in production mode with goexit hook",
915+
level: DPanicLevel,
916+
opts: opts(WithPanicHook(zapcore.WriteThenPanic)),
917+
finished: true,
918+
want: []observer.LoggedEntry{
919+
{
920+
Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"},
921+
Context: []Field{},
922+
},
923+
},
924+
recoverValue: nil,
925+
},
926+
{
927+
msg: "dpanic no panic in production mode with panic hook",
928+
level: DPanicLevel,
929+
opts: opts(WithPanicHook(zapcore.WriteThenPanic)),
930+
finished: true,
931+
want: []observer.LoggedEntry{
932+
{
933+
Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"},
934+
Context: []Field{},
935+
},
936+
},
937+
recoverValue: nil,
938+
},
939+
}
940+
941+
for _, tt := range tests {
942+
t.Run(tt.msg, func(t *testing.T) {
943+
withLogger(t, InfoLevel, tt.opts, func(logger *Logger, logs *observer.ObservedLogs) {
944+
var finished bool
945+
recovered := make(chan any)
946+
go func() {
947+
defer func() {
948+
recovered <- recover()
949+
}()
950+
951+
logger.Log(tt.level, "foobar")
952+
finished = true
953+
}()
954+
955+
assert.Equal(t, tt.recoverValue, <-recovered, "unexpected value from recover()")
956+
assert.Equal(t, tt.finished, finished, "expect goroutine finished state doesn't match")
957+
assert.Equal(t, tt.want, logs.AllUntimed(), "unexpected logs")
958+
})
959+
})
960+
}
961+
}
962+
839963
func TestLoggerCustomOnFatal(t *testing.T) {
840964
tests := []struct {
841965
msg string

options.go

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -132,6 +132,21 @@ func IncreaseLevel(lvl zapcore.LevelEnabler) Option {
132132
})
133133
}
134134

135+
// WithPanicHook sets a CheckWriteHook to run on Panic/DPanic logs.
136+
// Zap will call this hook after writing a log statement with a Panic/DPanic level.
137+
//
138+
// For example, the following builds a logger that will exit the current
139+
// goroutine after writing a Panic/DPanic log message, but it will not start a panic.
140+
//
141+
// zap.New(core, zap.WithPanicHook(zapcore.WriteThenGoexit))
142+
//
143+
// This is useful for testing Panic/DPanic log output.
144+
func WithPanicHook(hook zapcore.CheckWriteHook) Option {
145+
return optionFunc(func(log *Logger) {
146+
log.onPanic = hook
147+
})
148+
}
149+
135150
// OnFatal sets the action to take on fatal logs.
136151
//
137152
// Deprecated: Use [WithFatalHook] instead.

0 commit comments

Comments
 (0)