|
| 1 | +// Copyright (c) 2017-2021 Uber Technologies Inc. |
| 2 | +// |
| 3 | +// Permission is hereby granted, free of charge, to any person obtaining a copy |
| 4 | +// of this software and associated documentation files (the "Software"), to deal |
| 5 | +// in the Software without restriction, including without limitation the rights |
| 6 | +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell |
| 7 | +// copies of the Software, and to permit persons to whom the Software is |
| 8 | +// furnished to do so, subject to the following conditions: |
| 9 | +// |
| 10 | +// The above copyright notice and this permission notice shall be included in |
| 11 | +// all copies or substantial portions of the Software. |
| 12 | +// |
| 13 | +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR |
| 14 | +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, |
| 15 | +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE |
| 16 | +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER |
| 17 | +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, |
| 18 | +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN |
| 19 | +// THE SOFTWARE. |
| 20 | + |
| 21 | +package testlogger |
| 22 | + |
| 23 | +import ( |
| 24 | + "fmt" |
| 25 | + "slices" |
| 26 | + "strings" |
| 27 | + |
| 28 | + "github.com/stretchr/testify/require" |
| 29 | + "go.uber.org/atomic" |
| 30 | + "go.uber.org/zap" |
| 31 | + "go.uber.org/zap/zapcore" |
| 32 | + "go.uber.org/zap/zaptest" |
| 33 | + "go.uber.org/zap/zaptest/observer" |
| 34 | +) |
| 35 | + |
| 36 | +type TestingT interface { |
| 37 | + zaptest.TestingT |
| 38 | + Cleanup(func()) // not currently part of zaptest.TestingT |
| 39 | +} |
| 40 | + |
| 41 | +// NewZap makes a new test-oriented logger that prevents bad-lifecycle logs from failing tests. |
| 42 | +func NewZap(t TestingT) *zap.Logger { |
| 43 | + /* |
| 44 | + HORRIBLE HACK due to async shutdown, both in our code and in libraries: |
| 45 | + normally, logs produced after a test finishes will *intentionally* fail the test and/or |
| 46 | + cause data to race on the test's internal `t.done` field. |
| 47 | +
|
| 48 | + that's a good thing, it reveals possibly-dangerously-flawed lifecycle management. |
| 49 | +
|
| 50 | + unfortunately some of our code and some libraries do not have good lifecycle management, |
| 51 | + and this cannot easily be patched from the outside. |
| 52 | +
|
| 53 | + so this logger cheats: after a test completes, it logs to stderr rather than TestingT. |
| 54 | + EVERY ONE of these logs is bad and we should not produce them, but it's causing many |
| 55 | + otherwise-useful tests to be flaky, and that's a larger interruption than is useful. |
| 56 | + */ |
| 57 | + logAfterComplete, err := zap.NewDevelopment() |
| 58 | + require.NoError(t, err, "could not build a fallback zap logger") |
| 59 | + replaced := &fallbackTestCore{ |
| 60 | + t: t, |
| 61 | + fallback: logAfterComplete.Core(), |
| 62 | + testing: zaptest.NewLogger(t).Core(), |
| 63 | + completed: &atomic.Bool{}, |
| 64 | + } |
| 65 | + |
| 66 | + t.Cleanup(replaced.UseFallback) // switch to fallback before ending the test |
| 67 | + |
| 68 | + return zap.New(replaced) |
| 69 | +} |
| 70 | + |
| 71 | +// NewObserved makes a new test logger that both logs to `t` and collects logged |
| 72 | +// events for asserting in tests. |
| 73 | +func NewObserved(t TestingT) (*zap.Logger, *observer.ObservedLogs) { |
| 74 | + obsCore, obs := observer.New(zapcore.DebugLevel) |
| 75 | + z := NewZap(t) |
| 76 | + z = z.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { |
| 77 | + return zapcore.NewTee(core, obsCore) |
| 78 | + })) |
| 79 | + return z, obs |
| 80 | +} |
| 81 | + |
| 82 | +type fallbackTestCore struct { |
| 83 | + t TestingT |
| 84 | + fallback zapcore.Core |
| 85 | + testing zapcore.Core |
| 86 | + completed *atomic.Bool |
| 87 | +} |
| 88 | + |
| 89 | +var _ zapcore.Core = (*fallbackTestCore)(nil) |
| 90 | + |
| 91 | +func (f *fallbackTestCore) UseFallback() { |
| 92 | + f.completed.Store(true) |
| 93 | +} |
| 94 | + |
| 95 | +func (f *fallbackTestCore) Enabled(level zapcore.Level) bool { |
| 96 | + if f.completed.Load() { |
| 97 | + return f.fallback.Enabled(level) |
| 98 | + } |
| 99 | + return f.testing.Enabled(level) |
| 100 | +} |
| 101 | + |
| 102 | +func (f *fallbackTestCore) With(fields []zapcore.Field) zapcore.Core { |
| 103 | + // need to copy and defer, else the returned core will be used at an |
| 104 | + // arbitrarily later point in time, possibly after the test has completed. |
| 105 | + return &fallbackTestCore{ |
| 106 | + t: f.t, |
| 107 | + fallback: f.fallback.With(fields), |
| 108 | + testing: f.testing.With(fields), |
| 109 | + completed: f.completed, |
| 110 | + } |
| 111 | +} |
| 112 | + |
| 113 | +func (f *fallbackTestCore) Check(entry zapcore.Entry, checked *zapcore.CheckedEntry) *zapcore.CheckedEntry { |
| 114 | + // see other Check impls, all look similar. |
| 115 | + // this defers the "where to log" decision to Write, as `f` is the core that will write. |
| 116 | + if f.fallback.Enabled(entry.Level) { |
| 117 | + return checked.AddCore(entry, f) |
| 118 | + } |
| 119 | + return checked // do not add any cores |
| 120 | +} |
| 121 | + |
| 122 | +func (f *fallbackTestCore) Write(entry zapcore.Entry, fields []zapcore.Field) error { |
| 123 | + if f.completed.Load() { |
| 124 | + entry.Message = fmt.Sprintf("COULD FAIL TEST %q, logged too late: %v", f.t.Name(), entry.Message) |
| 125 | + |
| 126 | + hasStack := slices.ContainsFunc(fields, func(field zapcore.Field) bool { |
| 127 | + // no specific stack-trace type, so just look for probable fields. |
| 128 | + return strings.Contains(strings.ToLower(field.Key), "stack") |
| 129 | + }) |
| 130 | + if !hasStack { |
| 131 | + fields = append(fields, zap.Stack("log_stack")) |
| 132 | + } |
| 133 | + return f.fallback.Write(entry, fields) |
| 134 | + } |
| 135 | + return f.testing.Write(entry, fields) |
| 136 | +} |
| 137 | + |
| 138 | +func (f *fallbackTestCore) Sync() error { |
| 139 | + if f.completed.Load() { |
| 140 | + return f.fallback.Sync() |
| 141 | + } |
| 142 | + return f.testing.Sync() |
| 143 | +} |
0 commit comments