From b51e891cf49de4bcf23b5216c5ba81a79b6f47b1 Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Mon, 11 Nov 2024 15:09:54 +0100 Subject: [PATCH] [common] Introduce testlogger as a workaround of poor lifecycle (#1398) * [common] Introduce testlogger as a workaround for a poor lifecycle --- internal/activity_task_handler_test.go | 13 +- internal/activity_test.go | 5 +- internal/auto_heartbeater_test.go | 11 +- internal/common/convert.go | 14 ++ internal/common/convert_test.go | 17 ++ internal/common/testlogger/testlogger.go | 163 ++++++++++++++++++ internal/common/testlogger/testlogger_test.go | 157 +++++++++++++++++ internal/error_test.go | 7 +- internal/internal_event_handlers_test.go | 5 +- internal/internal_poller_autoscaler_test.go | 5 +- internal/internal_task_handlers_test.go | 11 +- internal/internal_task_pollers_test.go | 7 +- internal/internal_worker_interfaces_test.go | 7 +- internal/internal_worker_test.go | 7 +- internal/internal_workers_test.go | 19 +- internal/internal_workflow_test.go | 5 +- internal/internal_workflow_testsuite_test.go | 7 +- internal/test_helpers_test.go | 5 +- internal/workflow_shadower_activities_test.go | 7 +- internal/workflow_shadower_worker_test.go | 15 +- 20 files changed, 427 insertions(+), 60 deletions(-) create mode 100644 internal/common/testlogger/testlogger.go create mode 100644 internal/common/testlogger/testlogger_test.go diff --git a/internal/activity_task_handler_test.go b/internal/activity_task_handler_test.go index ea6cf1873..3d424d5b4 100644 --- a/internal/activity_task_handler_test.go +++ b/internal/activity_task_handler_test.go @@ -27,6 +27,8 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/jonboulle/clockwork" "github.com/golang/mock/gomock" @@ -34,7 +36,6 @@ import ( "github.com/pborman/uuid" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" s "go.uber.org/cadence/.gen/go/shared" @@ -57,7 +58,7 @@ func TestActivityTaskHandler_Execute_deadline(t *testing.T) { for i, d := range deadlineTests { t.Run(fmt.Sprintf("testIndex: %v, testDetails: %v", i, d), func(t *testing.T) { - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) a := &testActivityDeadline{logger: logger} registry := newRegistry() registry.addActivityWithLock(a.ActivityType().Name, a) @@ -101,7 +102,7 @@ func TestActivityTaskHandler_Execute_deadline(t *testing.T) { } func TestActivityTaskHandler_Execute_worker_stop(t *testing.T) { - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) a := &testActivityDeadline{logger: logger} registry := newRegistry() @@ -150,7 +151,7 @@ func TestActivityTaskHandler_Execute_worker_stop(t *testing.T) { } func TestActivityTaskHandler_Execute_with_propagators(t *testing.T) { - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) now := time.Now() @@ -208,7 +209,7 @@ func TestActivityTaskHandler_Execute_with_propagators(t *testing.T) { } func TestActivityTaskHandler_Execute_with_propagator_failure(t *testing.T) { - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) now := time.Now() @@ -254,7 +255,7 @@ func TestActivityTaskHandler_Execute_with_propagator_failure(t *testing.T) { } func TestActivityTaskHandler_Execute_with_auto_heartbeat(t *testing.T) { - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) now := time.Now() diff --git a/internal/activity_test.go b/internal/activity_test.go index 23008dd98..10cd4a102 100644 --- a/internal/activity_test.go +++ b/internal/activity_test.go @@ -24,12 +24,13 @@ import ( "context" "testing" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/stretchr/testify/require" "github.com/stretchr/testify/suite" "go.uber.org/yarpc" "go.uber.org/zap" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" "go.uber.org/cadence/.gen/go/shared" @@ -56,7 +57,7 @@ func TestActivityTestSuite(t *testing.T) { func (s *activityTestSuite) SetupTest() { s.mockCtrl = gomock.NewController(s.T()) s.service = workflowservicetest.NewMockClient(s.mockCtrl) - s.logger = zaptest.NewLogger(s.T()) + s.logger = testlogger.NewZap(s.T()) } func (s *activityTestSuite) TearDownTest() { diff --git a/internal/auto_heartbeater_test.go b/internal/auto_heartbeater_test.go index 03b655a3d..a6c7b9eb2 100644 --- a/internal/auto_heartbeater_test.go +++ b/internal/auto_heartbeater_test.go @@ -26,10 +26,11 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/jonboulle/clockwork" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/shared" "go.uber.org/cadence/internal/common" @@ -51,7 +52,7 @@ func TestAutoHearbeater_Run(t *testing.T) { t.Run("worker stop channel", func(t *testing.T) { stopCh := make(chan struct{}) invoker := &MockServiceInvoker{} - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) clock := clockwork.NewFakeClock() hearbeater := newHeartbeater(stopCh, invoker, logger, clock, activityType, workflowExecution) @@ -62,7 +63,7 @@ func TestAutoHearbeater_Run(t *testing.T) { t.Run("context done", func(t *testing.T) { stopCh := make(chan struct{}) invoker := &MockServiceInvoker{} - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) clock := clockwork.NewFakeClock() hearbeater := newHeartbeater(stopCh, invoker, logger, clock, activityType, workflowExecution) @@ -75,7 +76,7 @@ func TestAutoHearbeater_Run(t *testing.T) { stopCh := make(chan struct{}) invoker := &MockServiceInvoker{} invoker.EXPECT().BackgroundHeartbeat().Return(nil).Once() - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) clock := clockwork.NewFakeClock() hearbeater := newHeartbeater(stopCh, invoker, logger, clock, activityType, workflowExecution) @@ -98,7 +99,7 @@ func TestAutoHearbeater_Run(t *testing.T) { stopCh := make(chan struct{}) invoker := &MockServiceInvoker{} invoker.EXPECT().BackgroundHeartbeat().Return(assert.AnError).Once() - logger := zaptest.NewLogger(t) + logger := testlogger.NewZap(t) clock := clockwork.NewFakeClock() hearbeater := newHeartbeater(stopCh, invoker, logger, clock, activityType, workflowExecution) diff --git a/internal/common/convert.go b/internal/common/convert.go index 2f30788c7..ffeb7501a 100644 --- a/internal/common/convert.go +++ b/internal/common/convert.go @@ -95,3 +95,17 @@ func QueryResultTypePtr(t s.QueryResultType) *s.QueryResultType { func PtrOf[T any](v T) *T { return &v } + +// ValueFromPtr returns the value from a pointer. +func ValueFromPtr[T any](v *T) T { + if v == nil { + return Zero[T]() + } + return *v +} + +// Zero returns the zero value of a type by return type. +func Zero[T any]() T { + var zero T + return zero +} diff --git a/internal/common/convert_test.go b/internal/common/convert_test.go index f09c90191..94e6fa3bf 100644 --- a/internal/common/convert_test.go +++ b/internal/common/convert_test.go @@ -55,3 +55,20 @@ func TestCeilHelpers(t *testing.T) { assert.Equal(t, int32(2), Int32Ceil(1.1)) assert.Equal(t, int64(2), Int64Ceil(1.1)) } + +func TestValueFromPtr(t *testing.T) { + assert.Equal(t, "a", ValueFromPtr(PtrOf("a"))) + assert.Equal(t, 1, ValueFromPtr(PtrOf(1))) + assert.Equal(t, int32(1), ValueFromPtr(PtrOf(int32(1)))) + assert.Equal(t, int64(1), ValueFromPtr(PtrOf(int64(1)))) + assert.Equal(t, 1.1, ValueFromPtr(PtrOf(1.1))) + assert.Equal(t, true, ValueFromPtr(PtrOf(true))) + assert.Equal(t, []string{"a"}, ValueFromPtr(PtrOf([]string{"a"}))) + assert.Equal(t, "" /* default value */, ValueFromPtr((*string)(nil))) +} + +func TestZero(t *testing.T) { + assert.Equal(t, "", Zero[string]()) + assert.Equal(t, 0, Zero[int]()) + assert.Equal(t, (*int)(nil), Zero[*int]()) +} diff --git a/internal/common/testlogger/testlogger.go b/internal/common/testlogger/testlogger.go new file mode 100644 index 000000000..b755c4ac1 --- /dev/null +++ b/internal/common/testlogger/testlogger.go @@ -0,0 +1,163 @@ +// Copyright (c) 2017-2021 Uber Technologies Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package testlogger + +import ( + "fmt" + "slices" + "strings" + "sync" + + "go.uber.org/cadence/internal/common" + + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest" + "go.uber.org/zap/zaptest/observer" +) + +type TestingT interface { + zaptest.TestingT + Cleanup(func()) // not currently part of zaptest.TestingT +} + +// NewZap makes a new test-oriented logger that prevents bad-lifecycle logs from failing tests. +func NewZap(t TestingT) *zap.Logger { + /* + HORRIBLE HACK due to async shutdown, both in our code and in libraries: + normally, logs produced after a test finishes will *intentionally* fail the test and/or + cause data to race on the test's internal `t.done` field. + + that's a good thing, it reveals possibly-dangerously-flawed lifecycle management. + + unfortunately some of our code and some libraries do not have good lifecycle management, + and this cannot easily be patched from the outside. + + so this logger cheats: after a test completes, it logs to stderr rather than TestingT. + EVERY ONE of these logs is bad and we should not produce them, but it's causing many + otherwise-useful tests to be flaky, and that's a larger interruption than is useful. + */ + logAfterComplete, err := zap.NewDevelopment() + require.NoError(t, err, "could not build a fallback zap logger") + replaced := &fallbackTestCore{ + mu: &sync.RWMutex{}, + t: t, + fallback: logAfterComplete.Core(), + testing: zaptest.NewLogger(t).Core(), + completed: common.PtrOf(false), + } + + t.Cleanup(replaced.UseFallback) // switch to fallback before ending the test + + return zap.New(replaced) +} + +// NewObserved makes a new test logger that both logs to `t` and collects logged +// events for asserting in tests. +func NewObserved(t TestingT) (*zap.Logger, *observer.ObservedLogs) { + obsCore, obs := observer.New(zapcore.DebugLevel) + z := NewZap(t) + z = z.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { + return zapcore.NewTee(core, obsCore) + })) + return z, obs +} + +type fallbackTestCore struct { + mu *sync.RWMutex + t TestingT + fallback zapcore.Core + testing zapcore.Core + completed *bool +} + +var _ zapcore.Core = (*fallbackTestCore)(nil) + +func (f *fallbackTestCore) UseFallback() { + f.mu.Lock() + defer f.mu.Unlock() + *f.completed = true +} + +func (f *fallbackTestCore) Enabled(level zapcore.Level) bool { + f.mu.RLock() + defer f.mu.RUnlock() + if f.completed != nil && *f.completed { + return f.fallback.Enabled(level) + } + return f.testing.Enabled(level) +} + +func (f *fallbackTestCore) With(fields []zapcore.Field) zapcore.Core { + f.mu.Lock() + defer f.mu.Unlock() + + // need to copy and defer, else the returned core will be used at an + // arbitrarily later point in time, possibly after the test has completed. + return &fallbackTestCore{ + mu: f.mu, + t: f.t, + fallback: f.fallback.With(fields), + testing: f.testing.With(fields), + completed: f.completed, + } +} + +func (f *fallbackTestCore) Check(entry zapcore.Entry, checked *zapcore.CheckedEntry) *zapcore.CheckedEntry { + f.mu.RLock() + defer f.mu.RUnlock() + // see other Check impls, all look similar. + // this defers the "where to log" decision to Write, as `f` is the core that will write. + if f.fallback.Enabled(entry.Level) { + return checked.AddCore(entry, f) + } + return checked // do not add any cores +} + +func (f *fallbackTestCore) Write(entry zapcore.Entry, fields []zapcore.Field) error { + f.mu.RLock() + defer f.mu.RUnlock() + + if common.ValueFromPtr(f.completed) { + entry.Message = fmt.Sprintf("COULD FAIL TEST %q, logged too late: %v", f.t.Name(), entry.Message) + + hasStack := slices.ContainsFunc(fields, func(field zapcore.Field) bool { + // no specific stack-trace type, so just look for probable fields. + return strings.Contains(strings.ToLower(field.Key), "stack") + }) + if !hasStack { + fields = append(fields, zap.Stack("log_stack")) + } + return f.fallback.Write(entry, fields) + } + return f.testing.Write(entry, fields) +} + +func (f *fallbackTestCore) Sync() error { + f.mu.RLock() + defer f.mu.RUnlock() + + if common.ValueFromPtr(f.completed) { + return f.fallback.Sync() + } + return f.testing.Sync() +} diff --git a/internal/common/testlogger/testlogger_test.go b/internal/common/testlogger/testlogger_test.go new file mode 100644 index 000000000..8fc94cf53 --- /dev/null +++ b/internal/common/testlogger/testlogger_test.go @@ -0,0 +1,157 @@ +// Copyright (c) 2017-2021 Uber Technologies Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package testlogger + +import ( + "fmt" + "os" + "sync" + "testing" + "time" + + "go.uber.org/cadence/internal/common" + + "go.uber.org/zap/zaptest" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" +) + +var ( + done = make(chan struct{}) + logged = make(chan struct{}) +) + +func TestMain(m *testing.M) { + code := m.Run() + // ensure synchronization between t.done and t.logf, else this test is extremely flaky. + // for details see: https://github.com/golang/go/issues/67701 + close(done) + select { + case <-logged: + os.Exit(code) + case <-time.After(time.Millisecond): // should be MUCH faster + _, _ = fmt.Fprintln(os.Stderr, "timed out waiting for test to log") + os.Exit(1) + } +} + +// Unfortunately a moderate hack, to work around our faulty lifecycle management, +// and some libraries with issues as well. +// Ideally this test WOULD fail, but that's much harder to assert "safely". +func TestLoggerShouldNotFailIfLoggedLate(t *testing.T) { + origLogger := NewZap(t) + // if With does not defer core selection, this will fail the test + // by sending the logs to t.Logf + withLogger := origLogger.With(zap.String("test", "testing")) // literally any tag + origLogger.Info("before is fine, orig") + withLogger.Info("before is fine, with") + go func() { + <-done + origLogger.Info("too late, orig") + withLogger.Info("too late, with") + close(logged) + }() +} + +func TestSubtestShouldNotFail(t *testing.T) { + // when complete, a subtest's too-late logs just get pushed to the parent, + // and do not fail any tests. they only fail when no running parent exists. + // + // if Go changes this behavior, this test could fail, otherwise AFAICT it + // should be stable. + assertDoesNotFail := func(name string, setup, log func(t *testing.T)) { + // need to wrap in something that will out-live the "real" test, + // to ensure there is a running parent test to push logs toward. + t.Run(name, func(t *testing.T) { + // same setup as TestMain but contained within this sub-test + var ( + done = make(chan struct{}) + logged = make(chan struct{}) + ) + t.Run("inner", func(t *testing.T) { + setup(t) + go func() { + <-done + // despite being too late, the parent test is still running + // so this does not fail the test. + log(t) + close(logged) + }() + time.AfterFunc(10*time.Millisecond, func() { + close(done) + }) + }) + <-logged + }) + } + + assertDoesNotFail("real", func(t *testing.T) { + // no setup needed + }, func(t *testing.T) { + t.Logf("too late but allowed") + }) + + var l *zap.Logger + assertDoesNotFail("wrapped", func(t *testing.T) { + l = NewZap(t) + }, func(t *testing.T) { + l.Info("too late but allowed") + }) +} + +func TestObserver(t *testing.T) { + l, obs := NewObserved(t) + l.Info("a log") + l.Info("some unrelated log") + assert.Len(t, obs.FilterMessage("a log").All(), 1, "did not find a log that was logged") +} + +func TestFallbackTestCore_Enabled(t *testing.T) { + fallbackCfg := zap.NewDevelopmentConfig() + fallbackCfg.Level = zap.NewAtomicLevelAt(zap.WarnLevel) + fallbackLogger, err := fallbackCfg.Build() + require.NoError(t, err) + + core := &fallbackTestCore{ + mu: &sync.RWMutex{}, + t: t, + fallback: fallbackLogger.Core(), + testing: zaptest.NewLogger(t).Core(), + completed: common.PtrOf(false), + } + // Debug is enabled in zaptest.Logger + assert.True(t, core.Enabled(zap.DebugLevel)) + core.UseFallback() + // Debug is disabled in fallbackLogger. + assert.False(t, core.Enabled(zap.DebugLevel)) +} + +func TestFallbackTestCore_Sync(t *testing.T) { + core := NewZap(t).Core().(*fallbackTestCore) + core.fallback = zap.NewNop().Core() + // Sync for testing logger must not fail. + assert.NoError(t, core.Sync(), "normal sync must not fail") + core.UseFallback() + // Sync for fallback logger must not fail. + assert.NoError(t, core.Sync(), "fallback sync must not fail") +} diff --git a/internal/error_test.go b/internal/error_test.go index 751060ea9..6f3bce617 100644 --- a/internal/error_test.go +++ b/internal/error_test.go @@ -25,8 +25,9 @@ import ( "fmt" "testing" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/stretchr/testify/require" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/shared" "go.uber.org/cadence/internal/common" @@ -62,7 +63,7 @@ var ( // Creates a new workflow environment with the correct logger configured. func newTestActivityEnv(t *testing.T) *TestActivityEnvironment { s := &WorkflowTestSuite{} - s.SetLogger(zaptest.NewLogger(t)) + s.SetLogger(testlogger.NewZap(t)) // same tally note env := s.NewTestActivityEnvironment() return env @@ -482,7 +483,7 @@ func Test_ContinueAsNewError(t *testing.T) { header: header, ctxProps: []ContextPropagator{NewStringMapPropagator([]string{"test"})}, } - s.SetLogger(zaptest.NewLogger(t)) + s.SetLogger(testlogger.NewZap(t)) wfEnv := s.NewTestWorkflowEnvironment() wfEnv.Test(t) wfEnv.RegisterWorkflowWithOptions(continueAsNewWorkflowFn, RegisterWorkflowOptions{ diff --git a/internal/internal_event_handlers_test.go b/internal/internal_event_handlers_test.go index 9a01302e4..5176b2ac5 100644 --- a/internal/internal_event_handlers_test.go +++ b/internal/internal_event_handlers_test.go @@ -24,9 +24,10 @@ import ( "encoding/json" "testing" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/opentracing/opentracing-go" "github.com/uber-go/tally" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/internal/common" @@ -932,7 +933,7 @@ func testWorkflowExecutionEventHandler(t *testing.T, registry *registry) *workfl return newWorkflowExecutionEventHandler( testWorkflowInfo, func(result []byte, err error) {}, - zaptest.NewLogger(t), + testlogger.NewZap(t), true, tally.NewTestScope("test", nil), registry, diff --git a/internal/internal_poller_autoscaler_test.go b/internal/internal_poller_autoscaler_test.go index 3e9757979..68514602f 100644 --- a/internal/internal_poller_autoscaler_test.go +++ b/internal/internal_poller_autoscaler_test.go @@ -26,9 +26,10 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/stretchr/testify/assert" "go.uber.org/atomic" - "go.uber.org/zap/zaptest" s "go.uber.org/cadence/.gen/go/shared" "go.uber.org/cadence/internal/common/autoscaler" @@ -169,7 +170,7 @@ func Test_pollerAutoscaler(t *testing.T) { DryRun: tt.args.isDryRun, TargetUtilization: float64(tt.args.targetMilliUsage) / 1000, }, - zaptest.NewLogger(t), + testlogger.NewZap(t), // hook function that collects number of iterations func() { autoscalerEpoch.Add(1) diff --git a/internal/internal_task_handlers_test.go b/internal/internal_task_handlers_test.go index aca8912fa..1db0c7bb5 100644 --- a/internal/internal_task_handlers_test.go +++ b/internal/internal_task_handlers_test.go @@ -32,6 +32,8 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/pborman/uuid" "github.com/stretchr/testify/require" @@ -39,7 +41,6 @@ import ( "go.uber.org/goleak" "go.uber.org/zap" "go.uber.org/zap/zapcore" - "go.uber.org/zap/zaptest" "go.uber.org/zap/zaptest/observer" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" @@ -118,11 +119,11 @@ func getWorkflowInfoWorkflowFunc(ctx Context, expectedLastCompletionResult strin // Test suite. func (t *TaskHandlersTestSuite) SetupTest() { - t.logger = zaptest.NewLogger(t.T()) + t.logger = testlogger.NewZap(t.T()) } func (t *TaskHandlersTestSuite) SetupSuite() { - t.logger = zaptest.NewLogger(t.T()) + t.logger = testlogger.NewZap(t.T()) registerWorkflows(t.registry) } @@ -1419,7 +1420,7 @@ func (t *TaskHandlersTestSuite) TestHeartBeatLogNotCanceled() { func (t *TaskHandlersTestSuite) TestHeartBeat_NilResponseWithError() { mockCtrl := gomock.NewController(t.T()) mockService := workflowservicetest.NewMockClient(mockCtrl) - logger := zaptest.NewLogger(t.T()) + logger := testlogger.NewZap(t.T()) entityNotExistsError := &s.EntityNotExistsError{} mockService.EXPECT().RecordActivityTaskHeartbeat(gomock.Any(), gomock.Any(), callOptions()...).Return(nil, entityNotExistsError) @@ -1446,7 +1447,7 @@ func (t *TaskHandlersTestSuite) TestHeartBeat_NilResponseWithError() { func (t *TaskHandlersTestSuite) TestHeartBeat_NilResponseWithDomainNotActiveError() { mockCtrl := gomock.NewController(t.T()) mockService := workflowservicetest.NewMockClient(mockCtrl) - logger := zaptest.NewLogger(t.T()) + logger := testlogger.NewZap(t.T()) domainNotActiveError := &s.DomainNotActiveError{} mockService.EXPECT().RecordActivityTaskHeartbeat(gomock.Any(), gomock.Any(), callOptions()...).Return(nil, domainNotActiveError) diff --git a/internal/internal_task_pollers_test.go b/internal/internal_task_pollers_test.go index c81fa7db2..ef73f3139 100644 --- a/internal/internal_task_pollers_test.go +++ b/internal/internal_task_pollers_test.go @@ -26,12 +26,13 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" "github.com/uber-go/tally" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" s "go.uber.org/cadence/.gen/go/shared" @@ -47,7 +48,7 @@ const ( func TestLocalActivityPanic(t *testing.T) { // regression: panics in local activities should not terminate the process - s := WorkflowTestSuite{logger: zaptest.NewLogger(t)} + s := WorkflowTestSuite{logger: testlogger.NewZap(t)} env := s.NewTestWorkflowEnvironment() wf := "panicky_local_activity" @@ -190,7 +191,7 @@ func buildWorkflowTaskPoller(t *testing.T) (*workflowTaskPoller, *workflowservic taskHandler: taskHandler, ldaTunnel: lda, metricsScope: &metrics.TaggedScope{Scope: tally.NewTestScope("test", nil)}, - logger: zaptest.NewLogger(t), + logger: testlogger.NewZap(t), stickyUUID: "", disableStickyExecution: false, StickyScheduleToStartTimeout: time.Millisecond, diff --git a/internal/internal_worker_interfaces_test.go b/internal/internal_worker_interfaces_test.go index 99e444a70..d0eb8347e 100644 --- a/internal/internal_worker_interfaces_test.go +++ b/internal/internal_worker_interfaces_test.go @@ -27,9 +27,10 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/stretchr/testify/suite" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" m "go.uber.org/cadence/.gen/go/shared" @@ -182,7 +183,7 @@ func (s *InterfacesTestSuite) TestInterface() { WorkerOptions: WorkerOptions{ MaxConcurrentActivityTaskPollers: 4, MaxConcurrentDecisionTaskPollers: 4, - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), }, } @@ -214,7 +215,7 @@ func (s *InterfacesTestSuite) TestInterface() { WorkerOptions: WorkerOptions{ MaxConcurrentActivityTaskPollers: 10, MaxConcurrentDecisionTaskPollers: 10, - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), }, } diff --git a/internal/internal_worker_test.go b/internal/internal_worker_test.go index 49981b36c..f23741e65 100644 --- a/internal/internal_worker_test.go +++ b/internal/internal_worker_test.go @@ -31,6 +31,8 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "go.uber.org/cadence/internal/common/debug" "github.com/golang/mock/gomock" @@ -41,7 +43,6 @@ import ( "github.com/uber-go/tally" "go.uber.org/yarpc" "go.uber.org/zap" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" "go.uber.org/cadence/.gen/go/shared" @@ -123,7 +124,7 @@ func (s *internalWorkerTestSuite) TearDownTest() { } func getTestLogger(t *testing.T) *zap.Logger { - return zaptest.NewLogger(t) + return testlogger.NewZap(t) } func (s *internalWorkerTestSuite) testDecisionTaskHandlerHelper(params workerExecutionParameters) { @@ -411,7 +412,7 @@ func createWorkerWithThrottle( // Configure worker options. workerOptions.WorkerActivitiesPerSecond = 20 workerOptions.TaskListActivitiesPerSecond = activitiesPerSecond - workerOptions.Logger = zaptest.NewLogger(t) + workerOptions.Logger = testlogger.NewZap(t) workerOptions.EnableSessionWorker = true // Start Worker. diff --git a/internal/internal_workers_test.go b/internal/internal_workers_test.go index 8b6e08049..757d44c06 100644 --- a/internal/internal_workers_test.go +++ b/internal/internal_workers_test.go @@ -26,13 +26,14 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/pborman/uuid" "github.com/stretchr/testify/suite" "go.uber.org/atomic" "go.uber.org/yarpc" "go.uber.org/zap" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" m "go.uber.org/cadence/.gen/go/shared" @@ -127,7 +128,7 @@ func (s *WorkersTestSuite) testActivityWorker(useLocallyDispatched bool) { TaskList: "testTaskList", WorkerOptions: WorkerOptions{ MaxConcurrentActivityTaskPollers: 5, - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, } overrides := &workerOverrides{activityTaskHandler: newSampleActivityTaskHandler(), useLocallyDispatchedActivityPoller: useLocallyDispatched} a := &greeterActivity{} @@ -173,7 +174,7 @@ func (s *WorkersTestSuite) TestActivityWorkerStop() { WorkerOptions{ MaxConcurrentActivityTaskPollers: 5, MaxConcurrentActivityExecutionSize: 2, - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), }, ), UserContext: ctx, @@ -212,7 +213,7 @@ func (s *WorkersTestSuite) TestPollForDecisionTask_InternalServiceError() { TaskList: "testDecisionTaskList", WorkerOptions: WorkerOptions{ MaxConcurrentDecisionTaskPollers: 5, - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, } overrides := &workerOverrides{workflowTaskHandler: newSampleWorkflowTaskHandler()} workflowWorker := newWorkflowWorkerInternal( @@ -336,7 +337,7 @@ func (s *WorkersTestSuite) TestLongRunningDecisionTask() { }).Times(2) options := WorkerOptions{ - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), DisableActivityWorker: true, Identity: "test-worker-identity", } @@ -502,7 +503,7 @@ func (s *WorkersTestSuite) TestQueryTask_WorkflowCacheEvicted() { s.service.EXPECT().PollForDecisionTask(gomock.Any(), gomock.Any(), callOptions()...).Return(&m.PollForDecisionTaskResponse{}, &m.InternalServiceError{}).AnyTimes() options := WorkerOptions{ - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), DisableActivityWorker: true, Identity: "test-worker-identity", DataConverter: dc, @@ -636,7 +637,7 @@ func (s *WorkersTestSuite) TestMultipleLocalActivities() { }).Times(1) options := WorkerOptions{ - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), DisableActivityWorker: true, Identity: "test-worker-identity", } @@ -748,7 +749,7 @@ func (s *WorkersTestSuite) TestLocallyDispatchedActivity() { }).Times(1) options := WorkerOptions{ - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), Identity: "test-worker-identity", } worker, err := newAggregatedWorker(s.service, domain, taskList, options) @@ -814,7 +815,7 @@ func (s *WorkersTestSuite) TestMultipleLocallyDispatchedActivity() { } options := WorkerOptions{ - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), Identity: "test-worker-identity", } diff --git a/internal/internal_workflow_test.go b/internal/internal_workflow_test.go index 62d4b1a31..36969922c 100644 --- a/internal/internal_workflow_test.go +++ b/internal/internal_workflow_test.go @@ -28,10 +28,11 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" "github.com/stretchr/testify/suite" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/internal/common/metrics" ) @@ -50,7 +51,7 @@ func (s *WorkflowUnitTest) SetupSuite() { } } func (s *WorkflowUnitTest) SetupTest() { - s.SetLogger(zaptest.NewLogger(s.T())) + s.SetLogger(testlogger.NewZap(s.T())) } func TestWorkflowUnitTest(t *testing.T) { diff --git a/internal/internal_workflow_testsuite_test.go b/internal/internal_workflow_testsuite_test.go index f964f58a3..c5a7b0aaf 100644 --- a/internal/internal_workflow_testsuite_test.go +++ b/internal/internal_workflow_testsuite_test.go @@ -31,12 +31,13 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" "github.com/stretchr/testify/suite" "go.uber.org/zap" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/shared" "go.uber.org/cadence/internal/common" @@ -67,7 +68,7 @@ func (s *WorkflowTestSuiteUnitTest) SetupSuite() { } func (s *WorkflowTestSuiteUnitTest) SetupTest() { - s.SetLogger(zaptest.NewLogger(s.T())) + s.SetLogger(testlogger.NewZap(s.T())) } func TestUnitTestSuite(t *testing.T) { @@ -3177,7 +3178,7 @@ func (s *WorkflowTestSuiteUnitTest) Test_Regression_ExecuteChildWorkflowWithCanc func TestRegression_LocalActivityErrorEncoding(t *testing.T) { // previously not encoded correctly s := WorkflowTestSuite{} - s.SetLogger(zaptest.NewLogger(t)) + s.SetLogger(testlogger.NewZap(t)) env := s.NewTestWorkflowEnvironment() sentinel := errors.New("sentinel error value") env.RegisterWorkflowWithOptions(func(ctx Context) error { diff --git a/internal/test_helpers_test.go b/internal/test_helpers_test.go index e8871cc9f..73d161dbe 100644 --- a/internal/test_helpers_test.go +++ b/internal/test_helpers_test.go @@ -23,8 +23,9 @@ package internal import ( "testing" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" - "go.uber.org/zap/zaptest" ) // A collection of cross-test helpers. @@ -33,7 +34,7 @@ import ( // Creates a new workflow environment with the correct logger / testing.T configured. func newTestWorkflowEnv(t *testing.T) *TestWorkflowEnvironment { s := WorkflowTestSuite{} - s.SetLogger(zaptest.NewLogger(t)) + s.SetLogger(testlogger.NewZap(t)) // tally is not set since metrics are not noisy by default, and the test-instance // is largely useless without access to the instance for snapshots. env := s.NewTestWorkflowEnvironment() diff --git a/internal/workflow_shadower_activities_test.go b/internal/workflow_shadower_activities_test.go index 88d052abd..5b83f5114 100644 --- a/internal/workflow_shadower_activities_test.go +++ b/internal/workflow_shadower_activities_test.go @@ -27,10 +27,11 @@ import ( "testing" "time" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/stretchr/testify/require" "github.com/stretchr/testify/suite" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" "go.uber.org/cadence/.gen/go/shadower" @@ -61,7 +62,7 @@ func (s *workflowShadowerActivitiesSuite) SetupTest() { s.controller = gomock.NewController(s.T()) s.mockService = workflowservicetest.NewMockClient(s.controller) - s.SetLogger(zaptest.NewLogger(s.T())) + s.SetLogger(testlogger.NewZap(s.T())) s.env = s.NewTestActivityEnvironment() s.testReplayer = NewWorkflowReplayer() @@ -73,7 +74,7 @@ func (s *workflowShadowerActivitiesSuite) SetupTest() { activityContext = context.WithValue(activityContext, workflowReplayerContextKey, s.testReplayer) s.env.SetWorkerOptions(WorkerOptions{ BackgroundActivityContext: activityContext, - Logger: zaptest.NewLogger(s.T()), + Logger: testlogger.NewZap(s.T()), }) s.env.RegisterActivityWithOptions(scanWorkflowActivity, RegisterActivityOptions{ Name: shadower.ScanWorkflowActivityName, diff --git a/internal/workflow_shadower_worker_test.go b/internal/workflow_shadower_worker_test.go index 29b38983c..bb55ee1a5 100644 --- a/internal/workflow_shadower_worker_test.go +++ b/internal/workflow_shadower_worker_test.go @@ -24,11 +24,12 @@ import ( "context" "testing" + "go.uber.org/cadence/internal/common/testlogger" + "github.com/golang/mock/gomock" "github.com/stretchr/testify/require" "github.com/stretchr/testify/suite" "go.uber.org/yarpc" - "go.uber.org/zap/zaptest" "go.uber.org/cadence/.gen/go/cadence/workflowserviceclient" "go.uber.org/cadence/.gen/go/cadence/workflowservicetest" @@ -70,7 +71,7 @@ func (s *shadowWorkerSuite) TestNewShadowWorker() { workerExecutionParameters{ TaskList: testTaskList, WorkerOptions: WorkerOptions{ - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, }, registry, ) @@ -102,7 +103,7 @@ func (s *shadowWorkerSuite) TestStartShadowWorker_Failed_InvalidShadowOption() { workerExecutionParameters{ TaskList: testTaskList, WorkerOptions: WorkerOptions{ - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, }, newRegistry(), ) @@ -122,7 +123,7 @@ func (s *shadowWorkerSuite) TestStartShadowWorker_Failed_DomainNotExist() { workerExecutionParameters{ TaskList: testTaskList, WorkerOptions: WorkerOptions{ - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, }, newRegistry(), ) @@ -141,7 +142,7 @@ func (s *shadowWorkerSuite) TestStartShadowWorker_Failed_TaskListNotSpecified() ShadowOptions{}, workerExecutionParameters{ WorkerOptions: WorkerOptions{ - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, }, newRegistry(), ) @@ -165,7 +166,7 @@ func (s *shadowWorkerSuite) TestStartShadowWorker_Failed_StartWorkflowError() { workerExecutionParameters{ TaskList: testTaskList, WorkerOptions: WorkerOptions{ - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, }, newRegistry(), ) @@ -209,7 +210,7 @@ func (s *shadowWorkerSuite) TestStartShadowWorker_Succeed() { workerExecutionParameters{ TaskList: testTaskList, WorkerOptions: WorkerOptions{ - Logger: zaptest.NewLogger(s.T())}, + Logger: testlogger.NewZap(s.T())}, }, newRegistry(), )