From 93ad248377746696f54702fbd56cead7aeb4f8f5 Mon Sep 17 00:00:00 2001 From: Gustavo Gama Date: Sat, 30 Nov 2024 01:02:17 -0300 Subject: [PATCH] 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 | 2 +- pkg/timelock/timelock.go | 6 ++-- tests/integration/onchain_ops.go | 21 ++++++++++++++ tests/integration/timelock_test.go | 46 ++++++++++++++++++++++++++++-- tests/logger.go | 28 ++++++++++++++---- 5 files changed, 90 insertions(+), 13 deletions(-) diff --git a/pkg/timelock/scheduler.go b/pkg/timelock/scheduler.go index 324a1c3..625b9fe 100644 --- a/pkg/timelock/scheduler.go +++ b/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 } diff --git a/pkg/timelock/timelock.go b/pkg/timelock/timelock.go index 14f6951..9358c41 100644 --- a/pkg/timelock/timelock.go +++ b/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") } diff --git a/tests/integration/onchain_ops.go b/tests/integration/onchain_ops.go index 3646dde..5320772 100644 --- a/tests/integration/onchain_ops.go +++ b/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, diff --git a/tests/integration/timelock_test.go b/tests/integration/timelock_test.go index 9735d44..42a26e8 100644 --- a/tests/integration/timelock_test.go +++ b/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) }) } diff --git a/tests/logger.go b/tests/logger.go index 76f54a4..540c456 100644 --- a/tests/logger.go +++ b/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) + }) +}