|
| 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 | + "sync" |
| 28 | + |
| 29 | + "go.uber.org/cadence/internal/common" |
| 30 | + |
| 31 | + "github.com/stretchr/testify/require" |
| 32 | + "go.uber.org/zap" |
| 33 | + "go.uber.org/zap/zapcore" |
| 34 | + "go.uber.org/zap/zaptest" |
| 35 | + "go.uber.org/zap/zaptest/observer" |
| 36 | +) |
| 37 | + |
| 38 | +type TestingT interface { |
| 39 | + zaptest.TestingT |
| 40 | + Cleanup(func()) // not currently part of zaptest.TestingT |
| 41 | +} |
| 42 | + |
| 43 | +// NewZap makes a new test-oriented logger that prevents bad-lifecycle logs from failing tests. |
| 44 | +func NewZap(t TestingT) *zap.Logger { |
| 45 | + /* |
| 46 | + HORRIBLE HACK due to async shutdown, both in our code and in libraries: |
| 47 | + normally, logs produced after a test finishes will *intentionally* fail the test and/or |
| 48 | + cause data to race on the test's internal `t.done` field. |
| 49 | +
|
| 50 | + that's a good thing, it reveals possibly-dangerously-flawed lifecycle management. |
| 51 | +
|
| 52 | + unfortunately some of our code and some libraries do not have good lifecycle management, |
| 53 | + and this cannot easily be patched from the outside. |
| 54 | +
|
| 55 | + so this logger cheats: after a test completes, it logs to stderr rather than TestingT. |
| 56 | + EVERY ONE of these logs is bad and we should not produce them, but it's causing many |
| 57 | + otherwise-useful tests to be flaky, and that's a larger interruption than is useful. |
| 58 | + */ |
| 59 | + logAfterComplete, err := zap.NewDevelopment() |
| 60 | + require.NoError(t, err, "could not build a fallback zap logger") |
| 61 | + replaced := &fallbackTestCore{ |
| 62 | + mu: &sync.RWMutex{}, |
| 63 | + t: t, |
| 64 | + fallback: logAfterComplete.Core(), |
| 65 | + testing: zaptest.NewLogger(t).Core(), |
| 66 | + completed: common.PtrOf(false), |
| 67 | + } |
| 68 | + |
| 69 | + t.Cleanup(replaced.UseFallback) // switch to fallback before ending the test |
| 70 | + |
| 71 | + return zap.New(replaced) |
| 72 | +} |
| 73 | + |
| 74 | +// NewObserved makes a new test logger that both logs to `t` and collects logged |
| 75 | +// events for asserting in tests. |
| 76 | +func NewObserved(t TestingT) (*zap.Logger, *observer.ObservedLogs) { |
| 77 | + obsCore, obs := observer.New(zapcore.DebugLevel) |
| 78 | + z := NewZap(t) |
| 79 | + z = z.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { |
| 80 | + return zapcore.NewTee(core, obsCore) |
| 81 | + })) |
| 82 | + return z, obs |
| 83 | +} |
| 84 | + |
| 85 | +type fallbackTestCore struct { |
| 86 | + mu *sync.RWMutex |
| 87 | + t TestingT |
| 88 | + fallback zapcore.Core |
| 89 | + testing zapcore.Core |
| 90 | + completed *bool |
| 91 | +} |
| 92 | + |
| 93 | +var _ zapcore.Core = (*fallbackTestCore)(nil) |
| 94 | + |
| 95 | +func (f *fallbackTestCore) UseFallback() { |
| 96 | + f.mu.Lock() |
| 97 | + defer f.mu.Unlock() |
| 98 | + *f.completed = true |
| 99 | +} |
| 100 | + |
| 101 | +func (f *fallbackTestCore) Enabled(level zapcore.Level) bool { |
| 102 | + f.mu.RLock() |
| 103 | + defer f.mu.RUnlock() |
| 104 | + if f.completed != nil && *f.completed { |
| 105 | + return f.fallback.Enabled(level) |
| 106 | + } |
| 107 | + return f.testing.Enabled(level) |
| 108 | +} |
| 109 | + |
| 110 | +func (f *fallbackTestCore) With(fields []zapcore.Field) zapcore.Core { |
| 111 | + f.mu.Lock() |
| 112 | + defer f.mu.Unlock() |
| 113 | + |
| 114 | + // need to copy and defer, else the returned core will be used at an |
| 115 | + // arbitrarily later point in time, possibly after the test has completed. |
| 116 | + return &fallbackTestCore{ |
| 117 | + mu: f.mu, |
| 118 | + t: f.t, |
| 119 | + fallback: f.fallback.With(fields), |
| 120 | + testing: f.testing.With(fields), |
| 121 | + completed: f.completed, |
| 122 | + } |
| 123 | +} |
| 124 | + |
| 125 | +func (f *fallbackTestCore) Check(entry zapcore.Entry, checked *zapcore.CheckedEntry) *zapcore.CheckedEntry { |
| 126 | + f.mu.RLock() |
| 127 | + defer f.mu.RUnlock() |
| 128 | + // see other Check impls, all look similar. |
| 129 | + // this defers the "where to log" decision to Write, as `f` is the core that will write. |
| 130 | + if f.fallback.Enabled(entry.Level) { |
| 131 | + return checked.AddCore(entry, f) |
| 132 | + } |
| 133 | + return checked // do not add any cores |
| 134 | +} |
| 135 | + |
| 136 | +func (f *fallbackTestCore) Write(entry zapcore.Entry, fields []zapcore.Field) error { |
| 137 | + f.mu.RLock() |
| 138 | + defer f.mu.RUnlock() |
| 139 | + |
| 140 | + if common.ValueFromPtr(f.completed) { |
| 141 | + entry.Message = fmt.Sprintf("COULD FAIL TEST %q, logged too late: %v", f.t.Name(), entry.Message) |
| 142 | + |
| 143 | + hasStack := slices.ContainsFunc(fields, func(field zapcore.Field) bool { |
| 144 | + // no specific stack-trace type, so just look for probable fields. |
| 145 | + return strings.Contains(strings.ToLower(field.Key), "stack") |
| 146 | + }) |
| 147 | + if !hasStack { |
| 148 | + fields = append(fields, zap.Stack("log_stack")) |
| 149 | + } |
| 150 | + return f.fallback.Write(entry, fields) |
| 151 | + } |
| 152 | + return f.testing.Write(entry, fields) |
| 153 | +} |
| 154 | + |
| 155 | +func (f *fallbackTestCore) Sync() error { |
| 156 | + f.mu.RLock() |
| 157 | + defer f.mu.RUnlock() |
| 158 | + |
| 159 | + if common.ValueFromPtr(f.completed) { |
| 160 | + return f.fallback.Sync() |
| 161 | + } |
| 162 | + return f.testing.Sync() |
| 163 | +} |
0 commit comments