From 9ec9816b55a8f15bae36d33791e19d8d9903d134 Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Fri, 8 Nov 2024 14:14:33 +0100 Subject: [PATCH 1/8] [common] Introduce testlogger as a workaround of poor lifecycle --- internal/activity_task_handler_test.go | 13 +- internal/activity_test.go | 5 +- internal/auto_heartbeater_test.go | 11 +- internal/common/testlogger/testlogger.go | 143 ++++++++++++++++ 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 +- 18 files changed, 376 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/testlogger/testlogger.go b/internal/common/testlogger/testlogger.go new file mode 100644 index 000000000..ac1203120 --- /dev/null +++ b/internal/common/testlogger/testlogger.go @@ -0,0 +1,143 @@ +// 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" + + "github.com/stretchr/testify/require" + "go.uber.org/atomic" + "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{ + t: t, + fallback: logAfterComplete.Core(), + testing: zaptest.NewLogger(t).Core(), + completed: &atomic.Bool{}, + } + + 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 { + t TestingT + fallback zapcore.Core + testing zapcore.Core + completed *atomic.Bool +} + +var _ zapcore.Core = (*fallbackTestCore)(nil) + +func (f *fallbackTestCore) UseFallback() { + f.completed.Store(true) +} + +func (f *fallbackTestCore) Enabled(level zapcore.Level) bool { + if f.completed.Load() { + return f.fallback.Enabled(level) + } + return f.testing.Enabled(level) +} + +func (f *fallbackTestCore) With(fields []zapcore.Field) zapcore.Core { + // 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{ + 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 { + // 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 { + if f.completed.Load() { + 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 { + if f.completed.Load() { + 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..5f5bc3de2 --- /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" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/atomic" + "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.Second): // 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{ + t: t, + fallback: fallbackLogger.Core(), + testing: testlogger.NewZap(t).Core(), + completed: &atomic.Bool{}, + } + // 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 := &fallbackTestCore{ + t: t, + fallback: testlogger.NewZap(t).Core(), + testing: testlogger.NewZap(t).Core(), + completed: &atomic.Bool{}, + } + // 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(), ) From 83e76d245ab8781418dc407ec7025a819f1a879a Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Fri, 8 Nov 2024 14:38:48 +0100 Subject: [PATCH 2/8] maybe fix autoscaler tests --- internal/internal_worker_test.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/internal/internal_worker_test.go b/internal/internal_worker_test.go index f23741e65..8fb7e21a8 100644 --- a/internal/internal_worker_test.go +++ b/internal/internal_worker_test.go @@ -413,6 +413,10 @@ func createWorkerWithThrottle( workerOptions.WorkerActivitiesPerSecond = 20 workerOptions.TaskListActivitiesPerSecond = activitiesPerSecond workerOptions.Logger = testlogger.NewZap(t) + if workerOptions.FeatureFlags.PollerAutoScalerEnabled { + // Autoscaller can cause concurrent writes in the test logger, so it is unsafe to use. + workerOptions.Logger = zap.NewNop() + } workerOptions.EnableSessionWorker = true // Start Worker. From 2287430425d57585faf3e167072116027b39bfca Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Fri, 8 Nov 2024 14:54:35 +0100 Subject: [PATCH 3/8] fix tests --- internal/common/testlogger/testlogger_test.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/internal/common/testlogger/testlogger_test.go b/internal/common/testlogger/testlogger_test.go index 5f5bc3de2..841affa46 100644 --- a/internal/common/testlogger/testlogger_test.go +++ b/internal/common/testlogger/testlogger_test.go @@ -22,6 +22,7 @@ package testlogger import ( "fmt" + "go.uber.org/zap/zaptest" "os" "testing" "time" @@ -131,7 +132,7 @@ func TestFallbackTestCore_Enabled(t *testing.T) { core := &fallbackTestCore{ t: t, fallback: fallbackLogger.Core(), - testing: testlogger.NewZap(t).Core(), + testing: zaptest.NewLogger(t).Core(), completed: &atomic.Bool{}, } // Debug is enabled in zaptest.Logger @@ -145,8 +146,8 @@ func TestFallbackTestCore_Sync(t *testing.T) { core := &fallbackTestCore{ t: t, - fallback: testlogger.NewZap(t).Core(), - testing: testlogger.NewZap(t).Core(), + fallback: zaptest.NewLogger(t).Core(), + testing: zaptest.NewLogger(t).Core(), completed: &atomic.Bool{}, } // Sync for testing logger must not fail. From f7eb168ef668ec29833f905e0cb3510b47868421 Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Fri, 8 Nov 2024 14:57:21 +0100 Subject: [PATCH 4/8] make test logs thread safe --- internal/common/testlogger/testlogger.go | 5 +++++ internal/internal_worker_test.go | 4 ---- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/internal/common/testlogger/testlogger.go b/internal/common/testlogger/testlogger.go index ac1203120..85dddd74d 100644 --- a/internal/common/testlogger/testlogger.go +++ b/internal/common/testlogger/testlogger.go @@ -24,6 +24,7 @@ import ( "fmt" "slices" "strings" + "sync" "github.com/stretchr/testify/require" "go.uber.org/atomic" @@ -80,6 +81,7 @@ func NewObserved(t TestingT) (*zap.Logger, *observer.ObservedLogs) { } type fallbackTestCore struct { + sync.Mutex t TestingT fallback zapcore.Core testing zapcore.Core @@ -132,6 +134,9 @@ func (f *fallbackTestCore) Write(entry zapcore.Entry, fields []zapcore.Field) er } return f.fallback.Write(entry, fields) } + // Ensure no concurrent writes to the test logger. + f.Lock() + defer f.Unlock() return f.testing.Write(entry, fields) } diff --git a/internal/internal_worker_test.go b/internal/internal_worker_test.go index 8fb7e21a8..f23741e65 100644 --- a/internal/internal_worker_test.go +++ b/internal/internal_worker_test.go @@ -413,10 +413,6 @@ func createWorkerWithThrottle( workerOptions.WorkerActivitiesPerSecond = 20 workerOptions.TaskListActivitiesPerSecond = activitiesPerSecond workerOptions.Logger = testlogger.NewZap(t) - if workerOptions.FeatureFlags.PollerAutoScalerEnabled { - // Autoscaller can cause concurrent writes in the test logger, so it is unsafe to use. - workerOptions.Logger = zap.NewNop() - } workerOptions.EnableSessionWorker = true // Start Worker. From 56e6dde088527d863bc8127dea81aecd47fc6898 Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Fri, 8 Nov 2024 17:16:24 +0100 Subject: [PATCH 5/8] fmt --- internal/common/testlogger/testlogger_test.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/internal/common/testlogger/testlogger_test.go b/internal/common/testlogger/testlogger_test.go index 841affa46..e29db3139 100644 --- a/internal/common/testlogger/testlogger_test.go +++ b/internal/common/testlogger/testlogger_test.go @@ -22,11 +22,12 @@ package testlogger import ( "fmt" - "go.uber.org/zap/zaptest" "os" "testing" "time" + "go.uber.org/zap/zaptest" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/atomic" From 27b16db198e3ac18e552ba6e21d6def79dde14b0 Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Mon, 11 Nov 2024 11:48:47 +0100 Subject: [PATCH 6/8] switched to RWMutex to ensure switch to fallback on the test stop --- internal/common/convert.go | 14 ++++++++ internal/common/convert_test.go | 16 +++++++++ internal/common/testlogger/testlogger.go | 36 +++++++++++++------ internal/common/testlogger/testlogger_test.go | 19 +++++----- 4 files changed, 63 insertions(+), 22 deletions(-) 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..a88b4d020 100644 --- a/internal/common/convert_test.go +++ b/internal/common/convert_test.go @@ -55,3 +55,19 @@ 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"}))) +} + +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 index 85dddd74d..a48ddc656 100644 --- a/internal/common/testlogger/testlogger.go +++ b/internal/common/testlogger/testlogger.go @@ -22,12 +22,12 @@ package testlogger import ( "fmt" + "go.uber.org/cadence/internal/common" "slices" "strings" "sync" "github.com/stretchr/testify/require" - "go.uber.org/atomic" "go.uber.org/zap" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" @@ -58,10 +58,11 @@ func NewZap(t TestingT) *zap.Logger { 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: &atomic.Bool{}, + completed: common.PtrOf(false), } t.Cleanup(replaced.UseFallback) // switch to fallback before ending the test @@ -81,30 +82,38 @@ func NewObserved(t TestingT) (*zap.Logger, *observer.ObservedLogs) { } type fallbackTestCore struct { - sync.Mutex + mu *sync.RWMutex t TestingT fallback zapcore.Core testing zapcore.Core - completed *atomic.Bool + completed *bool } var _ zapcore.Core = (*fallbackTestCore)(nil) func (f *fallbackTestCore) UseFallback() { - f.completed.Store(true) + f.mu.Lock() + defer f.mu.Unlock() + *f.completed = true } func (f *fallbackTestCore) Enabled(level zapcore.Level) bool { - if f.completed.Load() { + 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), @@ -113,6 +122,8 @@ func (f *fallbackTestCore) With(fields []zapcore.Field) zapcore.Core { } 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) { @@ -122,7 +133,10 @@ func (f *fallbackTestCore) Check(entry zapcore.Entry, checked *zapcore.CheckedEn } func (f *fallbackTestCore) Write(entry zapcore.Entry, fields []zapcore.Field) error { - if f.completed.Load() { + 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 { @@ -134,14 +148,14 @@ func (f *fallbackTestCore) Write(entry zapcore.Entry, fields []zapcore.Field) er } return f.fallback.Write(entry, fields) } - // Ensure no concurrent writes to the test logger. - f.Lock() - defer f.Unlock() return f.testing.Write(entry, fields) } func (f *fallbackTestCore) Sync() error { - if f.completed.Load() { + 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 index e29db3139..5409ea4b8 100644 --- a/internal/common/testlogger/testlogger_test.go +++ b/internal/common/testlogger/testlogger_test.go @@ -22,7 +22,9 @@ package testlogger import ( "fmt" + "go.uber.org/cadence/internal/common" "os" + "sync" "testing" "time" @@ -30,7 +32,6 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" - "go.uber.org/atomic" "go.uber.org/zap" ) @@ -47,7 +48,7 @@ func TestMain(m *testing.M) { select { case <-logged: os.Exit(code) - case <-time.After(time.Second): // should be MUCH faster + case <-time.After(time.Millisecond): // should be MUCH faster _, _ = fmt.Fprintln(os.Stderr, "timed out waiting for test to log") os.Exit(1) } @@ -131,10 +132,11 @@ func TestFallbackTestCore_Enabled(t *testing.T) { require.NoError(t, err) core := &fallbackTestCore{ + mu: &sync.RWMutex{}, t: t, fallback: fallbackLogger.Core(), testing: zaptest.NewLogger(t).Core(), - completed: &atomic.Bool{}, + completed: common.PtrOf(false), } // Debug is enabled in zaptest.Logger assert.True(t, core.Enabled(zap.DebugLevel)) @@ -144,16 +146,11 @@ func TestFallbackTestCore_Enabled(t *testing.T) { } func TestFallbackTestCore_Sync(t *testing.T) { - - core := &fallbackTestCore{ - t: t, - fallback: zaptest.NewLogger(t).Core(), - testing: zaptest.NewLogger(t).Core(), - completed: &atomic.Bool{}, - } + 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") + assert.NoError(t, core.Sync(), "fallback sync must not fail") } From d2b87f45e6f20f28c9d643a58e65f315bf66b221 Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Mon, 11 Nov 2024 14:03:08 +0100 Subject: [PATCH 7/8] fmt --- internal/common/testlogger/testlogger.go | 3 ++- internal/common/testlogger/testlogger_test.go | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/internal/common/testlogger/testlogger.go b/internal/common/testlogger/testlogger.go index a48ddc656..b755c4ac1 100644 --- a/internal/common/testlogger/testlogger.go +++ b/internal/common/testlogger/testlogger.go @@ -22,11 +22,12 @@ package testlogger import ( "fmt" - "go.uber.org/cadence/internal/common" "slices" "strings" "sync" + "go.uber.org/cadence/internal/common" + "github.com/stretchr/testify/require" "go.uber.org/zap" "go.uber.org/zap/zapcore" diff --git a/internal/common/testlogger/testlogger_test.go b/internal/common/testlogger/testlogger_test.go index 5409ea4b8..8fc94cf53 100644 --- a/internal/common/testlogger/testlogger_test.go +++ b/internal/common/testlogger/testlogger_test.go @@ -22,12 +22,13 @@ package testlogger import ( "fmt" - "go.uber.org/cadence/internal/common" "os" "sync" "testing" "time" + "go.uber.org/cadence/internal/common" + "go.uber.org/zap/zaptest" "github.com/stretchr/testify/assert" From e209ff6afb8d8139d7b0b6f2cb26dec50c44a6cd Mon Sep 17 00:00:00 2001 From: Ilya Ozherelyev Date: Mon, 11 Nov 2024 14:04:58 +0100 Subject: [PATCH 8/8] add a nil case to ValueFromPtr --- internal/common/convert_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/internal/common/convert_test.go b/internal/common/convert_test.go index a88b4d020..94e6fa3bf 100644 --- a/internal/common/convert_test.go +++ b/internal/common/convert_test.go @@ -64,6 +64,7 @@ func TestValueFromPtr(t *testing.T) { 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) {