node: output logs only for failed tests

node/pkg/accountant/accountant_test.go

@@ -24,6 +24,7 @@ import (
 	gossipv1 "github.com/certusone/wormhole/node/pkg/proto/gossip/v1"
 	"github.com/wormhole-foundation/wormhole/sdk/vaa"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest"
 )
 
 const (
@@ -323,7 +324,7 @@ func TestInterestingTransferShouldBeBlockedWhenEnforcingAccountant(t *testing.T)
 
 func TestForDeadlock(t *testing.T) {
 	ctx := context.Background()
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 	obsvReqWriteC := make(chan *gossipv1.ObservationRequest, 10)
 	acctChan := make(chan *common.MessagePublication, MsgChannelCapacity)
 	wormchainConn := MockAccountantWormchainConn{}

node/pkg/node/node_test.go

@@ -41,6 +41,7 @@ import (
 	"github.com/wormhole-foundation/wormhole/sdk/vaa"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest"
 	"go.uber.org/zap/zaptest/observer"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials/insecure"
@@ -211,9 +212,9 @@ func mockGuardianRunnable(testId uint, gs []*mockGuardian, mockGuardianIndex uin
 }
 
 // setupLogsCapture is a helper function for making a zap logger/observer combination for testing that certain logs have been made
-func setupLogsCapture(options ...zap.Option) (*zap.Logger, *observer.ObservedLogs, *LogSizeCounter) {
+func setupLogsCapture(t testing.TB, options ...zap.Option) (*zap.Logger, *observer.ObservedLogs, *LogSizeCounter) {
 	observedCore, observedLogs := observer.New(zap.InfoLevel)
-	consoleLogger, _ := zap.NewDevelopment(zap.IncreaseLevel(CONSOLE_LOG_LEVEL))
+	consoleLogger := zaptest.NewLogger(t, zaptest.Level(CONSOLE_LOG_LEVEL))
 	lc := NewLogSizeCounter(zap.InfoLevel)
 	parentLogger := zap.New(zapcore.NewTee(observedCore, consoleLogger.Core(), lc.Core()), options...)
 	return parentLogger, observedLogs, lc
@@ -578,7 +579,7 @@ func testConsensus(t *testing.T, testCases []testCase, numGuardians int) {
 	rootCtx, rootCtxCancel := context.WithTimeout(context.Background(), testTimeout)
 	defer rootCtxCancel()
 
-	zapLogger, zapObserver, _ := setupLogsCapture()
+	zapLogger, zapObserver, _ := setupLogsCapture(t)
 
 	supervisor.New(rootCtx, zapLogger, func(ctx context.Context) error {
 		logger := supervisor.Logger(ctx)
@@ -745,7 +746,8 @@ func testConsensus(t *testing.T, testCases []testCase, numGuardians int) {
 
 	<-rootCtx.Done()
 	assert.NotEqual(t, rootCtx.Err(), context.DeadlineExceeded)
-	zapLogger.Info("Test root context cancelled, exiting...")
+	zapLogger.Info("Test root context cancelled, waiting 10ms for everything to shut down properly...")
+	time.Sleep(time.Millisecond * 10)
 }
 
 type testCaseGuardianConfig struct {
@@ -843,7 +845,7 @@ func testGuardianConfigurations(t *testing.T, testCases []testCaseGuardianConfig
 		// The panic will be subsequently caught by the supervisor
 		fatalHook := make(fatalHook)
 		defer close(fatalHook)
-		zapLogger, zapObserver, _ := setupLogsCapture(zap.WithFatalHook(fatalHook))
+		zapLogger, zapObserver, _ := setupLogsCapture(t, zap.WithFatalHook(fatalHook))
 
 		supervisor.New(rootCtx, zapLogger, func(ctx context.Context) error {
 			// Create a sub-context with cancel function that we can pass to G.run.
@@ -1020,7 +1022,7 @@ func benchmarkConsensus(t *testing.B, name string, numGuardians int, numMessages
 		rootCtx, rootCtxCancel := context.WithTimeout(context.Background(), testTimeout)
 		defer rootCtxCancel()
 
-		zapLogger, zapObserver, setupLogsCapture := setupLogsCapture()
+		zapLogger, zapObserver, setupLogsCapture := setupLogsCapture(t)
 
 		supervisor.New(rootCtx, zapLogger, func(ctx context.Context) error {
 			logger := supervisor.Logger(ctx)

node/pkg/watchers/near/nearapi/nearapi_test.go

@@ -8,7 +8,7 @@ import (
 	"time"
 
 	mockserver "github.com/certusone/wormhole/node/pkg/watchers/near/nearapi/mock"
-	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest"
 
 	"github.com/certusone/wormhole/node/pkg/watchers/near/nearapi"
 	"github.com/stretchr/testify/assert"
@@ -52,7 +52,7 @@ func TestNearApi(t *testing.T) {
 	ctx, cancelFunc := context.WithTimeout(parentCtx, time.Second*5)
 	defer cancelFunc()
 
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	mockServer := mockserver.NewForwardingCachingServer(logger, "https://rpc.mainnet.near.org", "mock/apitest/", nil)
 	mockHttpServer := httptest.NewServer(mockServer)

node/pkg/watchers/near/watcher_test.go

@@ -18,6 +18,7 @@ import (
 	"github.com/stretchr/testify/assert"
 	"github.com/wormhole-foundation/wormhole/sdk/vaa"
 	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest"
 )
 
 const (
@@ -89,7 +90,7 @@ Stages of the test:
 4) Check that all re-observed messages are correct
 */
 func (testCase *testCase) run(ctx context.Context) error {
-	logger := supervisor.Logger(ctx)
+	logger := zaptest.NewLogger(testCase.t).Named("near.test")
 
 	// Run the mock server
 	mockServer := mockserver.NewForwardingCachingServer(logger, testCase.upstreamHost, testCase.cacheDir, testCase.latestFinalBlocks)
@@ -205,11 +206,14 @@ func (testCase *testCase) setupAndRun(logger *zap.Logger) {
 	rootCtxCancel()
 	assert.NotEqual(testCase.t, err, context.DeadlineExceeded) // throw an error if timeout
 	assert.NoError(testCase.t, err)
+
+	// wait 10ms for things to shut down gracefully
+	time.Sleep(time.Millisecond * 10)
 }
 
 // TestWatcherSimple() tests the most simple case: "final" API only retruns one block which contains a Wormhole transaction. No re-observation requests.
 func TestWatcherSimple(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")
 	txHashBytes, _ := hex.DecodeString("88029cf0e7432cec04c266a3e72903ee6650b4624c7f9c8e22b04d78e18e87f8")
@@ -244,7 +248,7 @@ func TestWatcherSimple(t *testing.T) {
 
 // TestWatcherSimple2() tests the case where the "final" API returns a sequence of real blocks which contain a single Wormhole transaction. No re-observation requests.
 func TestWatcherSimple2(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")
 	txHashBytes, _ := hex.DecodeString("88029cf0e7432cec04c266a3e72903ee6650b4624c7f9c8e22b04d78e18e87f8")
@@ -287,7 +291,7 @@ func TestWatcherSimple2(t *testing.T) {
 // TestWatcherReobservation() tests the simple re-observation case: The "final" endpoint returns
 // the same unrelated block and there is a re-observation request for past data.
 func TestWatcherReobservation(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")
 	txHashBytes, _ := hex.DecodeString("88029cf0e7432cec04c266a3e72903ee6650b4624c7f9c8e22b04d78e18e87f8")
@@ -329,7 +333,7 @@ func TestWatcherReobservation(t *testing.T) {
 // TestWatcherDelayedFinal() tests the case where a block cannot be finalized by a parent having it as
 // last_final_block and instead needs to be finalized by having it observed as finalized during polling
 func TestWatcherDelayedFinal(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")
 	txHashBytes, _ := hex.DecodeString("88029cf0e7432cec04c266a3e72903ee6650b4624c7f9c8e22b04d78e18e87f8")
@@ -374,7 +378,7 @@ func TestWatcherDelayedFinal(t *testing.T) {
 // last_final_block and instead needs to be finalized by having it observed as finalized during polling
 // additionally, there is a large gap between polls
 func TestWatcherDelayedFinalAndGaps(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")
 	txHashBytes, _ := hex.DecodeString("88029cf0e7432cec04c266a3e72903ee6650b4624c7f9c8e22b04d78e18e87f8")
@@ -421,7 +425,7 @@ func TestWatcherDelayedFinalAndGaps(t *testing.T) {
 "6eCgeVSC4Hwm8tAVy4qNQpnLs4S9EpzRjGtAipwZ632A", // 76538236 block 7: tx3 receipt
 */
 func TestWatcherSynthetic(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")
 
@@ -514,7 +518,7 @@ func TestWatcherSynthetic(t *testing.T) {
 "6eCgeVSC4Hwm8tAVy4qNQpnLs4S9EpzRjGtAipwZ632A", // 76538236 block 7: tx3 receipt
 */
 func TestWatcherUnfinalized(t *testing.T) {
-	logger, _ := zap.NewDevelopment()
+	logger := zaptest.NewLogger(t)
 
 	pl, _ := hex.DecodeString("0100000000000000000000000000000000000000000000000000000000000f42400000000000000000000000000000000000000000000000000000000000000000000f0108bc32f7de18a5f6e1e7d6ee7aff9f5fc858d0d87ac0da94dd8d2a5d267d6b00160000000000000000000000000000000000000000000000000000000000000000")