[common] Introduce testlogger as a workaround of poor lifecycle

internal/activity_task_handler_test.go

@@ -27,14 +27,15 @@ import (
 	"testing"
 	"time"
 
+	"go.uber.org/cadence/internal/common/testlogger"
+
 	"github.com/jonboulle/clockwork"
 
 	"github.com/golang/mock/gomock"
 	"github.com/opentracing/opentracing-go"
 	"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()
 

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() {

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)
 

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
+}

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]())
+}

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()
+}