fix: don't check the "done" state when processing a Cancelled event

The RBACTimelock contract does not mark an operation as `done` when it's
cancelled. So the `isDone(operationID)` check we had in the "Cancelled"
event handler actually prevented the timelock worker service from
properly removing the operation from the scheduler.

This PR simply removes the `isDone()` check and adds an integration test
to verify that we're properly de-scheduling the operation.

pkg/timelock/scheduler.go

@@ -132,7 +132,7 @@ func (tw *scheduler) addToScheduler(op *contracts.RBACTimelockCallScheduled) {
 
 // delFromScheduler deletes an operation safely from the store.
 func (tw *scheduler) delFromScheduler(op operationKey) {
-	tw.logger.Debug().Msgf("de-scheduling operation: %v", op)
+	tw.logger.Debug().Msgf("de-scheduling operation: %x", op)
 	tw.del <- op
 }
 

pkg/timelock/timelock.go

@@ -486,10 +486,8 @@ func (tw *Worker) handleLog(ctx context.Context, log types.Log) error {
 			return err
 		}
 
-		if isDone(ctx, tw.contract, cs.Id) {
-			tw.logger.Info().Hex(fieldTXHash, cs.Raw.TxHash[:]).Uint64(fieldBlockNumber, cs.Raw.BlockNumber).Msgf("%s received, cancelling operation", eventCancelled)
-			tw.scheduler.delFromScheduler(cs.Id)
-		}
+		tw.logger.Info().Hex(fieldTXHash, cs.Raw.TxHash[:]).Uint64(fieldBlockNumber, cs.Raw.BlockNumber).Msgf("%s received, cancelling operation", eventCancelled)
+		tw.scheduler.delFromScheduler(cs.Id)
 	default:
 		tw.logger.Info().Str("event", event.Name).Msgf("discarding event")
 	}

tests/integration/onchain_ops.go

@@ -141,6 +141,27 @@ func ExecuteBatch(
 	return transaction, receipt
 }
 
+func CancelBatch(
+	t *testing.T,
+	ctx context.Context, transactor *bind.TransactOpts, backend Backend,
+	timelockContract *contracts.RBACTimelock, operationID [32]byte,
+) (
+	*types.Transaction, *types.Receipt,
+) {
+	t.Helper()
+
+	transaction, err := timelockContract.Cancel(transactor, operationID)
+	require.NoError(t, err)
+
+	backend.Commit()
+	receipt, err := bind.WaitMined(ctx, backend, transaction)
+	require.NoError(t, err)
+	require.Equal(t, types.ReceiptStatusSuccessful, receipt.Status)
+	t.Logf("cancel batch transaction: %v", transaction.Hash())
+
+	return transaction, receipt
+}
+
 func SendTransaction(
 	t *testing.T, ctx context.Context, transactor *bind.TransactOpts, backend Backend,
 	account TestAccount, chainID *big.Int, value *big.Int, to common.Address, data []byte,

tests/integration/timelock_test.go

@@ -141,6 +141,48 @@ func (s *integrationTestSuite) TestTimelockWorkerDryRun() {
 	}
 }
 
+func (s *integrationTestSuite) TestTimelockWorkerCancelledEvent() {
+	// --- arrange ---
+	ctx, cancel := context.WithCancel(s.Ctx)
+	defer cancel()
+
+	account := NewTestAccount(s.T())
+	_, err := s.GethContainer.CreateAccount(ctx, account.HexAddress, account.HexPrivateKey, 1)
+	s.Require().NoError(err)
+	s.Logf("new account created: %v", account)
+
+	gethURL := s.GethContainer.HTTPConnStr(s.T(), ctx)
+	backend := NewRPCBackend(s.T(), ctx, gethURL)
+	transactor := s.KeyedTransactor(account.PrivateKey, nil)
+	logger := timelockTests.NewTestLogger(zerolog.Nop())
+
+	timelockAddress, _, _, timelockContract := DeployTimelock(s.T(), ctx, transactor, backend,
+		account.Address, big.NewInt(1))
+	callProxyAddress, _, _, _ := DeployCallProxy(s.T(), ctx, transactor, backend, timelockAddress)
+
+	go runTimelockWorker(s.T(), ctx, gethURL, timelockAddress.String(), callProxyAddress.String(),
+		account.HexPrivateKey, big.NewInt(0), int64(1), int64(1), false, logger.Logger())
+
+	calls := []contracts.RBACTimelockCall{{
+		Target: common.HexToAddress("0x000000000000000000000000000000000000000"),
+		Value:  big.NewInt(1),
+		Data:   hexutil.MustDecode("0x0123456789abcdef"),
+	}}
+	predecessor := common.Hash{}
+	salt := common.Hash{}
+	operationID := common.HexToHash("371141ec10c0cc52996bed94240931136172d0b46bdc4bceaea1ef76675c1237")
+
+	// --- act ---
+	ScheduleBatch(s.T(), ctx, transactor, backend, timelockContract, calls, predecessor, salt, big.NewInt(1))
+	CancelBatch(s.T(), ctx, transactor, backend, timelockContract, operationID)
+
+	// --- assert ---
+	messages := logger.Messages(s.T())
+	s.Require().Contains(messages, "Cancelled received, cancelling operation")
+	s.Require().Contains(messages, "de-scheduling operation: 371141ec10c0cc52996bed94240931136172d0b46bdc4bceaea1ef76675c1237")
+	s.Require().Contains(messages, "de-scheduled operation: 371141ec10c0cc52996bed94240931136172d0b46bdc4bceaea1ef76675c1237")
+}
+
 // ----- helpers -----
 
 func runTimelockWorker(
@@ -179,8 +221,8 @@ func assertCapturedLogMessages(t *testing.T, logger timelockTests.TestLogger) {
 }
 
 func selectMatchingMessage(logger timelockTests.TestLogger, pattern *regexp.Regexp) []string {
-	return lo.Filter(logger.Messages(), func(loggedMessage string, _ int) bool {
-		return pattern.MatchString(loggedMessage)
+	return lo.Filter(logger.Entries(), func(loggedEntry string, _ int) bool {
+		return pattern.MatchString(loggedEntry)
 	})
 }
 

tests/logger.go

@@ -1,18 +1,23 @@
 package tests
 
 import (
+	"encoding/json"
 	"io"
 	"sync"
+	"testing"
 
 	"github.com/rs/zerolog"
+	"github.com/samber/lo"
+	"github.com/stretchr/testify/require"
 )
 
 type TestLogger interface {
 	Write(p []byte) (n int, err error)
 	Logger() *zerolog.Logger
-	NumMessages() int
-	LastMessage() string
-	Messages() []string
+	NumEntries() int
+	LastEntry() string
+	Entries() []string
+	Messages(t *testing.T) []string
 }
 
 type testLogger struct {
@@ -46,23 +51,34 @@ func (tl testLogger) Write(p []byte) (n int, err error) {
 	return tl.writer.Write(p)
 }
 
-func (tl testLogger) NumMessages() int {
+func (tl testLogger) NumEntries() int {
 	tl.mutex.Lock()
 	defer tl.mutex.Unlock()
 
 	return len(*tl.messages)
 }
 
-func (tl testLogger) LastMessage() string {
+func (tl testLogger) LastEntry() string {
 	tl.mutex.Lock()
 	defer tl.mutex.Unlock()
 
 	return (*tl.messages)[len(*tl.messages)-1]
 }
 
-func (tl testLogger) Messages() []string {
+func (tl testLogger) Entries() []string {
 	tl.mutex.Lock()
 	defer tl.mutex.Unlock()
 
 	return append([]string{}, *tl.messages...)
 }
+
+func (tl testLogger) Messages(t *testing.T) []string {
+	t.Helper()
+	return lo.Map(tl.Entries(), func(message string, _ int) string {
+		var entry map[string]any
+		err := json.Unmarshal([]byte(message), &entry)
+		require.NoError(t, err)
+
+		return entry["message"].(string)
+	})
+}