timelock: tests the operation store dump

Tests that dumping the operation store actually writes the
expected values to file.  Injects a time faker function and
refactors dumpOperationStore to improve testability.

pkg/timelock/scheduler.go

@@ -4,11 +4,13 @@ import (
 	"bufio"
 	"context"
 	"fmt"
+	"io"
 	"os"
 	"sort"
 	"sync"
 	"time"
 
+	"github.com/rs/zerolog"
 	"github.com/smartcontractkit/timelock-worker/pkg/timelock/contract"
 )
 
@@ -130,7 +132,10 @@ func (tw *Worker) isSchedulerBusy() bool {
 
 // dumpOperationStore dumps to the logger and to the log file the current scheduled unexecuted operations.
 // maps in go don't guarantee order, so that's why we have to find the earliest block.
-func (tw *Worker) dumpOperationStore() {
+//
+// TODO(mstreet3): dumpOperationStore accepts a now func to mock out the time during tests.  Consider
+// making a Clock interface to use in the Worker and use the Clock dependency instead.
+func (tw *Worker) dumpOperationStore(now func() time.Time) {
 	if len(tw.store) > 0 {
 		f, err := os.Create(logPath + logFile)
 		if err != nil {
@@ -140,35 +145,70 @@ func (tw *Worker) dumpOperationStore() {
 
 		tw.logger.Info().Msgf("generating logs with pending operations in %s", logPath+logFile)
 
-		w := bufio.NewWriter(f)
-		_, err = fmt.Fprintf(w, "Process stopped at %v\n", time.Now().In(time.UTC))
-		if err != nil {
-			tw.logger.Fatal().Msgf("error writing to buffer: %s", err.Error())
-		}
-
 		// Get the earliest block from all the operations stored by sorting them.
 		blocks := make([]int, 0)
 		for _, op := range tw.store {
 			blocks = append(blocks, int(op[0].Raw.BlockNumber))
 		}
 		sort.Ints(blocks)
 
-		for _, op := range tw.store {
-			if int(op[0].Raw.BlockNumber) == blocks[0] {
-				tw.logger.Info().Hex(fieldTXHash, op[0].Raw.TxHash[:]).Uint64(fieldBlockNumber, op[0].Raw.BlockNumber).Msgf("earliest unexecuted CallSchedule. Use this block number when spinning up the service again, with the environment variable or in timelock.env as FROM_BLOCK=%v, or using the flag --from-block=%v", op[0].Raw.BlockNumber, op[0].Raw.BlockNumber)
-				_, err = fmt.Fprintf(w, "Earliest CallSchedule pending ID: %x\tBlock Number: %v\n\tUse this block number to ensure all pending operations are properly executed.\n\tSet it as environment variable or in timelock.env with FROM_BLOCK=%v, or as a flag with --from-block=%v\n", op[0].Id, op[0].Raw.BlockNumber, op[0].Raw.BlockNumber, op[0].Raw.BlockNumber)
-				if err != nil {
-					tw.logger.Fatal().Msgf("error writing to buffer: %s", err.Error())
-				}
-			} else {
-				_, err = fmt.Fprintf(w, "CallSchedule pending ID: %x\tBlock Number: %v\n", op[0].Id, op[0].Raw.BlockNumber)
-				tw.logger.Info().Hex(fieldTXHash, op[0].Raw.TxHash[:]).Uint64(fieldBlockNumber, op[0].Raw.BlockNumber).Msgf("CallSchedule pending")
-				if err != nil {
-					tw.logger.Fatal().Msgf("error writing to buffer: %s", err.Error())
-				}
-			}
-		}
+		w := bufio.NewWriter(f)
+
+		writeOperationStore(w, tw.logger, tw.store, blocks[0], now)
 
 		w.Flush()
 	}
 }
+
+// writeOperationStore writes the operations to the writer.
+func writeOperationStore(
+	w io.Writer,
+	logger *zerolog.Logger,
+	store map[operationKey][]*contract.TimelockCallScheduled,
+	earliest int,
+	now func() time.Time,
+) {
+	var (
+		err error
+		op  *contract.TimelockCallScheduled
+		msg string
+	)
+
+	_, err = fmt.Fprintf(w, "Process stopped at %v\n", now().In(time.UTC))
+	if err != nil {
+		logger.Fatal().Msgf("error writing to buffer: %s", err.Error())
+	}
+
+	for _, record := range store {
+		op = record[0]
+
+		if int(op.Raw.BlockNumber) == earliest {
+			logLine := fmt.Sprintf("earliest unexecuted CallSchedule. Use this block number when "+
+				"spinning up the service again, with the environment variable or in timelock.env as FROM_BLOCK=%v, "+
+				"or using the flag --from-block=%v", op.Raw.BlockNumber, op.Raw.BlockNumber)
+			logger.Info().Hex(fieldTXHash, op.Raw.TxHash[:]).Uint64(fieldBlockNumber, op.Raw.BlockNumber).Msg(logLine)
+			msg = toEarliestRecord(op)
+		} else {
+			logger.Info().Hex(fieldTXHash, op.Raw.TxHash[:]).Uint64(fieldBlockNumber, op.Raw.BlockNumber).Msgf("CallSchedule pending")
+			msg = toSubsequentRecord(op)
+		}
+
+		_, err = fmt.Fprint(w, msg)
+		if err != nil {
+			logger.Fatal().Msgf("error writing to buffer: %s", err.Error())
+		}
+	}
+}
+
+// toEarliestRecord returns a string with the earliest record.
+func toEarliestRecord(op *contract.TimelockCallScheduled) string {
+	tmpl := "Earliest CallSchedule pending ID: %x\tBlock Number: %v\n" +
+		"\tUse this block number to ensure all pending operations are properly executed.  " +
+		"\tSet it as environment variable or in timelock.env with FROM_BLOCK=%v, or as a flag with --from-block=%v\n"
+	return fmt.Sprintf(tmpl, op.Id, op.Raw.BlockNumber, op.Raw.BlockNumber, op.Raw.BlockNumber)
+}
+
+// toSubsequentRecord returns a string for use with each subsequent record sent to a writer.
+func toSubsequentRecord(op *contract.TimelockCallScheduled) string {
+	return fmt.Sprintf("CallSchedule pending ID: %x\tBlock Number: %v\n", op.Id, op.Raw.BlockNumber)
+}

pkg/timelock/scheduler_test.go

@@ -1,10 +1,17 @@
 package timelock
 
 import (
+	"fmt"
+	"os"
 	"reflect"
+	"strings"
 	"testing"
 	"time"
 
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/core/types"
+	"github.com/rs/zerolog"
+	"github.com/smartcontractkit/timelock-worker/pkg/timelock/contract"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -76,3 +83,99 @@ func TestWorker_setSchedulerFree(t *testing.T) {
 	isBusy := testWorker.isSchedulerBusy()
 	assert.Equal(t, false, isBusy, "scheduler shouldn't be busy after setSchedulerFree()")
 }
+
+func Test_dumpOperationStore(t *testing.T) {
+	var (
+		fName         = logPath + logFile
+		logger        = zerolog.Nop()
+		earliestBlock = 42
+		opKeys        = generateOpKeys(t, []string{"1", "2"})
+
+		earliest = &contract.TimelockCallScheduled{
+			Id: opKeys[0],
+			Raw: types.Log{
+				TxHash:      common.HexToHash("txn-1"),
+				BlockNumber: uint64(earliestBlock),
+			},
+		}
+
+		following = &contract.TimelockCallScheduled{
+			Id: opKeys[1],
+			Raw: types.Log{
+				TxHash:      common.HexToHash("txn-2"),
+				BlockNumber: uint64(earliestBlock + 1),
+			},
+		}
+
+		store = map[operationKey][]*contract.TimelockCallScheduled{
+			opKeys[0]: {earliest},
+			opKeys[1]: {following},
+		}
+
+		worker = &Worker{
+			logger: &logger,
+			scheduler: scheduler{
+				store: store,
+			},
+		}
+	)
+
+	defer os.Remove(fName)
+
+	// setup fake time
+	dateString := "2021-11-22"
+	date, err := time.Parse("2006-01-02", dateString)
+	assert.NoError(t, err)
+
+	nowFunc := func() time.Time {
+		return date
+	}
+	wantPrefix := fmt.Sprintf("Process stopped at %v\n", nowFunc().In(time.UTC))
+
+	// Write the store to the file.
+	worker.dumpOperationStore(nowFunc)
+
+	// Read the file and compare the contents.
+	gotRead, err := os.ReadFile(fName)
+	assert.NoError(t, err)
+
+	// Assert that the contents of the file match the expected contents.
+	var wantRead []byte
+	wantRead = append(wantRead, []byte(wantPrefix)...)
+	wantRead = append(wantRead, []byte(toEarliestRecord(earliest))...)
+	wantRead = append(wantRead, []byte(toSubsequentRecord(following))...)
+	assert.Equal(t, wantRead, gotRead)
+}
+
+// openFile opens a file for reading and writing, and returns the file, its size, and an error if any.
+func openFile(name string) (file *os.File, size int64, err error) {
+	f, err := os.OpenFile(
+		name,
+		os.O_RDWR|os.O_CREATE,
+		0644,
+	)
+	if err != nil {
+		return nil, 0, err
+	}
+
+	fi, err := f.Stat()
+	if err != nil {
+		return nil, 0, err
+	}
+	return f, fi.Size(), nil
+}
+
+// generateOpKeys generates a slice of operation keys from a slice of strings.
+func generateOpKeys(t *testing.T, in []string) [][32]byte {
+	t.Helper()
+
+	opKeys := make([][32]byte, 0, len(in))
+	for _, id := range in {
+		padding := strings.Repeat("0", 32-len(id))
+		padded := fmt.Sprintf("%s%s", padding, id)
+		var key [32]byte
+		copy(key[:], padded)
+		opKeys = append(opKeys, key)
+	}
+	return opKeys
+}

pkg/timelock/timelock.go

@@ -263,7 +263,7 @@ func (tw *Worker) Listen(ctx context.Context) error {
 	defer sub.Unsubscribe()
 	defer ctx.Done()
 
-	tw.dumpOperationStore()
+	tw.dumpOperationStore(time.Now)
 
 	return nil
 }