Use a test-logger in tests rather than stdout (cadence-workflow#3976)

Currently, on failure, e.g. matchingEngine_test.go tests spew out *ridiculous* amounts of text. This happens because Go cannot tell which logs are related to the failed test(s), so it does what it can: show all stdout. Unfortunately, stdout blends logs from parallel tests, and it's hard or impossible to find the ones relevant to the failure simply by reading. So: stop doing that. Zap has a `zaptest` package for this purpose. I'm not sure how many other places may need to be changed, but this helps the ones I'm looking at at the moment.
shashaneRanasinghe · Feb 17, 2021 · c5334af · c5334af
1 parent 7882518
commit c5334af
Show file tree

Hide file tree

Showing 24 changed files with 115 additions and 118 deletions.
diff --git a/canary/workflow_test.go b/canary/workflow_test.go
@@ -31,6 +31,7 @@ import (
 	"go.uber.org/cadence/mocks"
 	"go.uber.org/cadence/testsuite"
 	"go.uber.org/cadence/worker"
+	"go.uber.org/zap/zaptest"
 )
 
 type (
@@ -51,7 +52,9 @@ func TestWorkflowTestSuite(t *testing.T) {
 }
 
 func (s *workflowTestSuite) SetupTest() {
+	s.SetLogger(zaptest.NewLogger(s.T()))
 	s.env = s.NewTestWorkflowEnvironment()
+	s.env.Test(s.T())
 }
 
 func (s *workflowTestSuite) TearDownTest() {

diff --git a/common/cache/domainCache_test.go b/common/cache/domainCache_test.go
@@ -72,7 +72,7 @@ func (s *domainCacheSuite) TearDownSuite() {
 func (s *domainCacheSuite) SetupTest() {
 	s.Assertions = require.New(s.T())
 
-	s.logger = loggerimpl.NewDevelopmentForTest(s.Suite)
+	s.logger = loggerimpl.NewLoggerForTest(s.Suite)
 	s.clusterMetadata = &mocks.ClusterMetadata{}
 	s.metadataMgr = &mocks.MetadataManager{}
 	metricsClient := metrics.NewClient(tally.NoopScope, metrics.History)

diff --git a/common/domain/dlqMessageHandler_test.go b/common/domain/dlqMessageHandler_test.go
@@ -29,7 +29,6 @@ import (
 	"github.com/pborman/uuid"
 	"github.com/stretchr/testify/require"
 	"github.com/stretchr/testify/suite"
-	"go.uber.org/zap"
 
 	"github.com/uber/cadence/common"
 	"github.com/uber/cadence/common/log/loggerimpl"
@@ -65,12 +64,10 @@ func (s *dlqMessageHandlerSuite) SetupTest() {
 	s.Assertions = require.New(s.T())
 	s.controller = gomock.NewController(s.T())
 
-	zapLogger, err := zap.NewDevelopment()
-	s.Require().NoError(err)
 	s.mockReplicationTaskExecutor = NewMockReplicationTaskExecutor(s.controller)
 	s.mockReplicationQueue = NewMockReplicationQueue(s.controller)
 
-	logger := loggerimpl.NewLogger(zapLogger)
+	logger := loggerimpl.NewLoggerForTest(s.Suite)
 	s.dlqMessageHandler = NewDLQMessageHandler(
 		s.mockReplicationTaskExecutor,
 		s.mockReplicationQueue,

diff --git a/common/domain/transmissionTaskHandler_test.go b/common/domain/transmissionTaskHandler_test.go
@@ -59,7 +59,7 @@ func (s *transmissionTaskSuite) SetupTest() {
 	s.kafkaProducer = &mocks.KafkaProducer{}
 	s.domainReplicator = NewDomainReplicator(
 		s.kafkaProducer,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 	).(*domainReplicatorImpl)
 }
 

diff --git a/common/log/loggerimpl/logger.go b/common/log/loggerimpl/logger.go
@@ -27,6 +27,7 @@ import (
 
 	"github.com/stretchr/testify/suite"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest"
 
 	"github.com/uber/cadence/common/log"
 	"github.com/uber/cadence/common/log/tag"
@@ -50,13 +51,9 @@ func NewNopLogger() log.Logger {
 	}
 }
 
-// NewDevelopmentForTest is a helper to create new development logger in unit test
-func NewDevelopmentForTest(s suite.Suite) log.Logger {
-	logger, err := NewDevelopment()
-	if err != nil {
-		panic(err)
-	}
-	return logger
+// NewLoggerForTest is a helper to create new development logger in unit test
+func NewLoggerForTest(s suite.Suite) log.Logger {
+	return NewLogger(zaptest.NewLogger(s.T()))
 }
 
 // NewDevelopment returns a logger at debug level and log into STDERR

diff --git a/common/ndc/history_resender_test.go b/common/ndc/history_resender_test.go
@@ -86,7 +86,7 @@ func (s *historyResenderSuite) SetupTest() {
 	s.mockHistoryClient = history.NewMockClient(s.controller)
 	s.mockDomainCache = cache.NewMockDomainCache(s.controller)
 
-	s.logger = loggerimpl.NewDevelopmentForTest(s.Suite)
+	s.logger = loggerimpl.NewLoggerForTest(s.Suite)
 	s.mockClusterMetadata = &mocks.ClusterMetadata{}
 	s.mockClusterMetadata.On("IsGlobalDomainEnabled").Return(true)
 

diff --git a/common/task/fifoTaskScheduler_test.go b/common/task/fifoTaskScheduler_test.go
@@ -63,7 +63,7 @@ func (s *fifoTaskSchedulerSuite) SetupTest() {
 
 	s.queueSize = 2
 	s.scheduler = NewFIFOTaskScheduler(
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		metrics.NewClient(tally.NoopScope, metrics.Common),
 		&FIFOTaskSchedulerOptions{
 			QueueSize:       s.queueSize,

diff --git a/common/task/parallelTaskProcessor_test.go b/common/task/parallelTaskProcessor_test.go
@@ -66,7 +66,7 @@ func (s *parallelTaskProcessorSuite) SetupTest() {
 	s.controller = gomock.NewController(s.T())
 
 	s.processor = NewParallelTaskProcessor(
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		metrics.NewClient(tally.NoopScope, metrics.Common),
 		&ParallelTaskProcessorOptions{
 			QueueSize:   0,
@@ -274,7 +274,7 @@ func (s *parallelTaskProcessorSuite) TestProcessorContract() {
 	}
 
 	processor := NewParallelTaskProcessor(
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		metrics.NewClient(tally.NoopScope, metrics.Common),
 		&ParallelTaskProcessorOptions{
 			QueueSize:   100,

diff --git a/common/task/weightedRoundRobinTaskScheduler_test.go b/common/task/weightedRoundRobinTaskScheduler_test.go
@@ -288,7 +288,7 @@ func (s *weightedRoundRobinTaskSchedulerSuite) newTestWeightedRoundRobinTaskSche
 	options *WeightedRoundRobinTaskSchedulerOptions,
 ) *weightedRoundRobinTaskSchedulerImpl {
 	scheduler, err := NewWeightedRoundRobinTaskScheduler(
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		metrics.NewClient(tally.NoopScope, metrics.Common),
 		options,
 	)

diff --git a/service/history/events/cache_test.go b/service/history/events/cache_test.go
@@ -68,7 +68,7 @@ func (s *eventsCacheSuite) TearDownSuite() {
 func (s *eventsCacheSuite) SetupTest() {
 	s.Assertions = require.New(s.T())
 
-	s.logger = loggerimpl.NewDevelopmentForTest(s.Suite)
+	s.logger = loggerimpl.NewLoggerForTest(s.Suite)
 	// Have to define our overridden assertions in the test setup. If we did it earlier, s.T() will return nil
 	s.Assertions = require.New(s.T())
 	s.mockHistoryManager = &mocks.HistoryV2Manager{}

diff --git a/service/history/historyEngine2_test.go b/service/history/historyEngine2_test.go
@@ -168,7 +168,7 @@ func (s *engine2Suite) TestRecordDecisionTaskStartedSuccessStickyExpired() {
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		we.GetRunID(),
 		constants.TestLocalDomainEntry,
 	)
@@ -240,7 +240,7 @@ func (s *engine2Suite) TestRecordDecisionTaskStartedSuccessStickyEnabled() {
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		we.GetRunID(),
 		constants.TestLocalDomainEntry,
 	)
@@ -863,7 +863,7 @@ func (s *engine2Suite) TestRespondDecisionTaskCompletedRecordMarkerDecision() {
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		we.GetRunID(),
 		constants.TestLocalDomainEntry,
 	)
@@ -1189,7 +1189,7 @@ func (s *engine2Suite) TestSignalWithStartWorkflowExecution_JustSignal() {
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		runID,
 		constants.TestLocalDomainEntry,
 	)
@@ -1325,7 +1325,7 @@ func (s *engine2Suite) TestSignalWithStartWorkflowExecution_WorkflowNotRunning()
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		runID,
 		constants.TestLocalDomainEntry,
 	)
@@ -1375,7 +1375,7 @@ func (s *engine2Suite) TestSignalWithStartWorkflowExecution_Start_DuplicateReque
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		runID,
 		constants.TestLocalDomainEntry,
 	)
@@ -1433,7 +1433,7 @@ func (s *engine2Suite) TestSignalWithStartWorkflowExecution_Start_WorkflowAlread
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		runID,
 		constants.TestLocalDomainEntry,
 	)

diff --git a/service/history/historyEngine3_eventsv2_test.go b/service/history/historyEngine3_eventsv2_test.go
@@ -164,7 +164,7 @@ func (s *engine3Suite) TestRecordDecisionTaskStartedSuccessStickyEnabled() {
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		we.GetRunID(),
 		constants.TestLocalDomainEntry,
 	)
@@ -291,7 +291,7 @@ func (s *engine3Suite) TestSignalWithStartWorkflowExecution_JustSignal() {
 
 	msBuilder := execution.NewMutableStateBuilderWithEventV2(
 		s.historyEngine.shard,
-		loggerimpl.NewDevelopmentForTest(s.Suite),
+		loggerimpl.NewLoggerForTest(s.Suite),
 		runID,
 		constants.TestLocalDomainEntry,
 	)