FileLogger for Testing (#1067)

MSevey · Manav-Aggarwal · tzdybal · web-flow · commit dbb3bb760a73 · 2023-07-25T15:25:31.000Z
## Overview Something I have found incredibly changing when debugging tests is the inability to use the verbose flag for doing some basic println debugging since the stdout is flooding with the logs of the node. To address this, I introduced a filelogger that can be used in testing to put the logs in a temp file and keep the stdout free for debugging. The tempfile can then still be used to investigate the logs if needed. This will also make debugging on github action easier since we can use the verbose flag for helpful errors and download the logfiles if needed. I'm probably missing some updates, but I did these when trying to help debug a test for Manav and so wanted to share. Closes #1079  ## Checklist  - [ ] New and updated code has appropriate documentation - [ ] New and updated code has new and/or updated testing - [ ] Required CI checks are passing - [ ] Visual proof for any user facing features like CLI or documentation updates - [ ] Linked issues closed with keywords --------- Co-authored-by: Manav Aggarwal <manavaggarwal1234@gmail.com> Co-authored-by: Tomasz Zdybał <tomek@zdybal.lap.pl>
diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml
@@ -32,25 +32,13 @@ jobs:
         with:
           go-version: ${{ inputs.GO_VERSION }}
       - name: Run unit test
-        run: make test-unit
+        run: make test
       - name: upload coverage report
         uses: codecov/codecov-action@v3.1.4
         with:
           token: ${{ secrets.CODECOV_TOKEN }}
           file: ./coverage.txt
 
-  unit_race_test:
-    name: Run Unit Tests with Race Detector
-    runs-on: ubuntu-latest
-    steps:
-      - uses: actions/checkout@v3
-      - name: set up go
-        uses: actions/setup-go@v4
-        with:
-          go-version: ${{ inputs.GO_VERSION }}
-      - name: execute test run
-        run: make test-unit-race
-
   integration_test:
     name: Run Integration Tests
     runs-on: ubuntu-latest
diff --git a/Makefile b/Makefile
@@ -1,6 +1,12 @@
 DOCKER := $(shell which docker)
 DOCKER_BUF := $(DOCKER) run --rm -v $(CURDIR):/workspace --workdir /workspace bufbuild/buf
 
+# Define pkgs, run, and cover vairables for test so that we can override them in
+# the terminal more easily.
+pkgs := $(shell go list ./...)
+run := .
+count := 1
+
 ## help: Show this help message
 help: Makefile
 	@echo " Choose a command run in "$(PROJECTNAME)":"
@@ -17,11 +23,19 @@ clean:
 cover:
 	@echo "--> Generating Code Coverage"
 	@go install github.com/ory/go-acc@latest
-	@go-acc -o coverage.txt `go list ./...`
+	@go-acc -o coverage.txt $(pkgs)
 .PHONY: cover
 
+## deps: Install dependencies
+deps:
+	@echo "--> Installing dependencies"
+	@go mod download
+	@make proto-gen
+	@go mod tidy
+.PHONY: deps
+
 ## lint: Run linters golangci-lint and markdownlint.
-lint:
+lint: vet
 	@echo "--> Running golangci-lint"
 	@golangci-lint run
 	@echo "--> Running markdownlint"
@@ -39,23 +53,17 @@ fmt:
 	@markdownlint --config .markdownlint.yaml '**/*.md' -f
 .PHONY: fmt
 
-## test-unit: Running unit tests
-test-unit:
-	@echo "--> Running unit tests"
-	@go test -covermode=atomic -coverprofile=coverage.txt `go list ./...`
-.PHONY: test-unit
+## vet: Run go vet
+vet: 
+	@echo "--> Running go vet"
+	@go vet $(pkgs)
+.PHONY: vet
 
-## test-unit-race: Running unit tests with data race detector
-test-unit-race:
-	@echo "--> Running unit tests with data race detector"
-	@go test -race -count=1 `go list ./...`
-.PHONY: test-unit-race
-
-## test-all: Run tests with and without data race
-test-all:
-	@$(MAKE) test-unit
-	@$(MAKE) test-unit-race
-.PHONY: test-all
+## test: Running unit tests
+test: vet
+	@echo "--> Running unit tests"
+	@go test -v -race -covermode=atomic -coverprofile=coverage.txt $(pkgs) -run $(run) -count=$(count)
+.PHONY: test
 
 ## proto-gen: Generate protobuf files. Requires docker.
 proto-gen:
diff --git a/README.md b/README.md
@@ -72,13 +72,7 @@ The Rollkit v0.9.0 release is compatible with [Arabica](https://docs.celestia.or
 
 ```sh
 # Run unit tests
-make test-unit
-
-# Run unit tests with the data race detector
-make test-unit-race
-
-# Run tests with and without the data race detector
-make test-all
+make test
 
 # Generate protobuf files (requires Docker)
 make proto-gen
diff --git a/block/manager.go b/block/manager.go
@@ -358,6 +358,11 @@ func (m *Manager) RetrieveLoop(ctx context.Context) {
 		select {
 		case <-waitCh:
 			for {
+				select {
+				case <-ctx.Done():
+					return
+				default:
+				}
 				daHeight := atomic.LoadUint64(&m.daHeight)
 				m.logger.Debug("retrieve", "daHeight", daHeight)
 				err := m.processNextDABlock(ctx)
@@ -382,10 +387,7 @@ func (m *Manager) processNextDABlock(ctx context.Context) error {
 	m.logger.Debug("trying to retrieve block from DA", "daHeight", daHeight)
 	for r := 0; r < maxRetries; r++ {
 		blockResp, fetchErr := m.fetchBlock(ctx, daHeight)
-		if fetchErr != nil {
-			err = multierr.Append(err, fetchErr)
-			time.Sleep(100 * time.Millisecond)
-		} else {
+		if fetchErr == nil {
 			if blockResp.Code == da.StatusNotFound {
 				m.logger.Debug("no block found", "daHeight", daHeight, "reason", blockResp.Message)
 				return nil
@@ -396,6 +398,15 @@ func (m *Manager) processNextDABlock(ctx context.Context) error {
 			}
 			return nil
 		}
+
+		// Track the error
+		err = multierr.Append(err, fetchErr)
+		// Delay before retrying
+		select {
+		case <-ctx.Done():
+			return err
+		case <-time.After(100 * time.Millisecond):
+		}
 	}
 	return err
 }
diff --git a/block/manager_test.go b/block/manager_test.go
@@ -15,6 +15,7 @@ import (
 	"github.com/rollkit/rollkit/config"
 	"github.com/rollkit/rollkit/da"
 	mockda "github.com/rollkit/rollkit/da/mock"
+	"github.com/rollkit/rollkit/log/test"
 	"github.com/rollkit/rollkit/store"
 	"github.com/rollkit/rollkit/types"
 )
@@ -52,15 +53,15 @@ func TestInitialState(t *testing.T) {
 		expectedChainID         string
 	}{
 		{
-			name:                    "empty store",
+			name:                    "empty_store",
 			store:                   emptyStore,
 			genesis:                 genesis,
 			expectedInitialHeight:   genesis.InitialHeight,
 			expectedLastBlockHeight: 0,
 			expectedChainID:         genesis.ChainID,
 		},
 		{
-			name:                    "state in store",
+			name:                    "state_in_store",
 			store:                   fullStore,
 			genesis:                 genesis,
 			expectedInitialHeight:   sampleState.InitialHeight,
@@ -78,7 +79,7 @@ func TestInitialState(t *testing.T) {
 	for _, c := range cases {
 		t.Run(c.name, func(t *testing.T) {
 			assert := assert.New(t)
-			logger := log.TestingLogger()
+			logger := test.NewFileLoggerCustom(t, test.TempLogFileName(t, c.name))
 			dalc := getMockDALC(logger)
 			defer func() {
 				require.NoError(t, dalc.Stop())
diff --git a/da/test/da_test.go b/da/test/da_test.go
@@ -77,7 +77,7 @@ func doTestLifecycle(t *testing.T, dalc da.DataAvailabilityLayerClient) {
 	if _, ok := dalc.(*celestia.DataAvailabilityLayerClient); ok {
 		conf, _ = json.Marshal(testConfig)
 	}
-	err := dalc.Init(testNamespaceID, conf, nil, test.NewLogger(t))
+	err := dalc.Init(testNamespaceID, conf, nil, test.NewFileLoggerCustom(t, test.TempLogFileName(t, "dalc")))
 	require.NoError(err)
 
 	err = dalc.Start()
@@ -147,7 +147,7 @@ func doTestRetrieve(t *testing.T, dalc da.DataAvailabilityLayerClient) {
 		conf, _ = json.Marshal(testConfig)
 	}
 	kvStore, _ := store.NewDefaultInMemoryKVStore()
-	err := dalc.Init(testNamespaceID, conf, kvStore, test.NewLogger(t))
+	err := dalc.Init(testNamespaceID, conf, kvStore, test.NewFileLoggerCustom(t, test.TempLogFileName(t, "dalc")))
 	require.NoError(err)
 
 	err = dalc.Start()
diff --git a/log/test/loggers.go b/log/test/loggers.go
@@ -2,12 +2,103 @@ package test
 
 import (
 	"fmt"
+	"os"
+	"strings"
 	"sync"
 	"testing"
+
+	"github.com/cometbft/cometbft/libs/log"
 )
 
 // TODO(tzdybal): move to some common place
 
+// FileLogger is a simple, thread-safe logger that logs to a tempFile and is
+// intended for use in testing.
+type FileLogger struct {
+	kv      []interface{}
+	logFile *os.File
+	T       *testing.T
+	mtx     *sync.Mutex
+}
+
+// TempLogFileName returns a filename for a log file that is unique to the test.
+func TempLogFileName(t *testing.T, suffix string) string {
+	return strings.ReplaceAll(t.Name(), "/", "_") + suffix + ".log"
+}
+
+// NewLogger create a Logger using the name of the test as the filename.
+func NewFileLogger(t *testing.T) *FileLogger {
+	// Use the test name but strip out any slashes since they are not
+	// allowed in filenames.
+	return NewFileLoggerCustom(t, TempLogFileName(t, ""))
+}
+
+// NewLoggerCustom create a Logger using the given filename.
+func NewFileLoggerCustom(t *testing.T, fileName string) *FileLogger {
+	logFile, err := os.CreateTemp("", fileName)
+	if err != nil {
+		panic(err)
+	}
+	t.Log("Test logs can be found:", logFile.Name())
+	t.Cleanup(func() {
+		_ = logFile.Close()
+	})
+	return &FileLogger{
+		kv:      []interface{}{},
+		logFile: logFile,
+		T:       t,
+		mtx:     new(sync.Mutex),
+	}
+}
+
+// Debug prints a debug message.
+func (f *FileLogger) Debug(msg string, keyvals ...interface{}) {
+	f.T.Helper()
+	f.mtx.Lock()
+	defer f.mtx.Unlock()
+	kvs := append(f.kv, keyvals...)
+	_, err := fmt.Fprintln(f.logFile, append([]interface{}{"DEBUG: " + msg}, kvs...)...)
+	if err != nil {
+		panic(err)
+	}
+}
+
+// Info prints an info message.
+func (f *FileLogger) Info(msg string, keyvals ...interface{}) {
+	f.T.Helper()
+	f.mtx.Lock()
+	defer f.mtx.Unlock()
+	kvs := append(f.kv, keyvals...)
+	_, err := fmt.Fprintln(f.logFile, append([]interface{}{"INFO: " + msg}, kvs...)...)
+	if err != nil {
+		panic(err)
+	}
+}
+
+// Error prints an error message.
+func (f *FileLogger) Error(msg string, keyvals ...interface{}) {
+	f.T.Helper()
+	f.mtx.Lock()
+	defer f.mtx.Unlock()
+	kvs := append(f.kv, keyvals...)
+	_, err := fmt.Fprintln(f.logFile, append([]interface{}{"ERROR: " + msg}, kvs...)...)
+	if err != nil {
+		panic(err)
+	}
+}
+
+// With returns a new Logger with the given keyvals added.
+func (f *FileLogger) With(keyvals ...interface{}) log.Logger {
+	f.mtx.Lock()
+	defer f.mtx.Unlock()
+	return &FileLogger{
+		kv:      append(f.kv, keyvals...),
+		logFile: f.logFile,
+		T:       f.T,
+		mtx:     new(sync.Mutex),
+	}
+}
+
 // Logger is a simple, yet thread-safe, logger intended for use in unit tests.
 type Logger struct {
 	mtx *sync.Mutex
diff --git a/node/full_node_integration_test.go b/node/full_node_integration_test.go
@@ -24,6 +24,7 @@ import (
 
 	"github.com/rollkit/rollkit/config"
 	mockda "github.com/rollkit/rollkit/da/mock"
+	"github.com/rollkit/rollkit/log/test"
 	"github.com/rollkit/rollkit/mocks"
 	"github.com/rollkit/rollkit/p2p"
 	"github.com/rollkit/rollkit/store"
@@ -444,7 +445,7 @@ func createNodes(aggCtx, ctx context.Context, num int, t *testing.T) ([]*FullNod
 	apps := make([]*mocks.Application, num)
 	dalc := &mockda.DataAvailabilityLayerClient{}
 	ds, _ := store.NewDefaultInMemoryKVStore()
-	_ = dalc.Init([8]byte{}, nil, ds, log.TestingLogger())
+	_ = dalc.Init([8]byte{}, nil, ds, test.NewFileLoggerCustom(t, test.TempLogFileName(t, "dalc")))
 	_ = dalc.Start()
 	node, app := createNode(aggCtx, 0, true, false, keys, t)
 	apps[0] = app
@@ -516,7 +517,7 @@ func createNode(ctx context.Context, n int, aggregator bool, isLight bool, keys
 		signingKey,
 		proxy.NewLocalClientCreator(app),
 		genesis,
-		log.TestingLogger().With("node", n))
+		test.NewFileLoggerCustom(t, test.TempLogFileName(t, fmt.Sprintf("node%v", n))).With("node", n))
 	require.NoError(err)
 	require.NotNil(node)
 
diff --git a/node/test_helpers.go b/node/test_helpers.go
@@ -21,22 +21,13 @@ type MockTester struct {
 	t *testing.T
 }
 
-func (m MockTester) Fail() {
-	fmt.Println("Failed")
-}
+func (m MockTester) Fail() {}
 
-func (m MockTester) FailNow() {
-	fmt.Println("MockTester FailNow called")
-}
+func (m MockTester) FailNow() {}
 
-func (m MockTester) Logf(format string, args ...interface{}) {
-	fmt.Println("MockTester Logf called")
-}
+func (m MockTester) Logf(format string, args ...interface{}) {}
 
-func (m MockTester) Errorf(format string, args ...interface{}) {
-	//fmt.Printf(format, args...)
-	fmt.Println("Errorf called")
-}
+func (m MockTester) Errorf(format string, args ...interface{}) {}
 
 func waitForFirstBlock(node *FullNode, useBlockExchange bool) error {
 	return waitForAtLeastNBlocks(node, 1, useBlockExchange)
diff --git a/p2p/client_test.go b/p2p/client_test.go
diff --git a/proto/gen.sh b/proto/gen.sh
