From df4a1883309f8aef15464f1b3c276be5c2a65bf3 Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 17:43:22 +0000 Subject: [PATCH 1/8] feat(common): add exponential backoff, repeated error logger and batch-limit parsing (#1889) Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- common/backoff.go | 140 +++++++++++++++++++++++ common/backoff_test.go | 138 +++++++++++++++++++++++ common/errors.go | 54 +++++++++ common/errors_test.go | 53 +++++++++ common/repeated_error_logger.go | 96 ++++++++++++++++ common/repeated_error_logger_test.go | 161 +++++++++++++++++++++++++++ 6 files changed, 642 insertions(+) create mode 100644 common/backoff.go create mode 100644 common/backoff_test.go create mode 100644 common/repeated_error_logger.go create mode 100644 common/repeated_error_logger_test.go diff --git a/common/backoff.go b/common/backoff.go new file mode 100644 index 000000000..44c2079cd --- /dev/null +++ b/common/backoff.go @@ -0,0 +1,140 @@ +package common + +import ( + "context" + "fmt" + "math" + "math/rand/v2" + "time" +) + +// ExponentialBackoffConfig configures an ExponentialBackoff. +type ExponentialBackoffConfig struct { + // Initial is the delay of the first attempt; must be > 0 + Initial time.Duration + // Max is the hard upper bound of any returned delay; must be >= Initial + Max time.Duration + // Factor is the growth per attempt; must be > 1 + Factor float64 + // Jitter is the symmetric relative jitter in [0, 1); 0.2 means +-20% + Jitter float64 +} + +// Validate reports whether the configuration is usable, wrapping ErrInvalidConfig. +func (c ExponentialBackoffConfig) Validate() error { + if c.Initial <= 0 { + return fmt.Errorf("%w: backoff Initial must be > 0 (got %s)", ErrInvalidConfig, c.Initial) + } + if c.Max < c.Initial { + return fmt.Errorf("%w: backoff Max (%s) must be >= Initial (%s)", ErrInvalidConfig, c.Max, c.Initial) + } + if !(c.Factor > 1) || math.IsInf(c.Factor, 0) { + return fmt.Errorf("%w: backoff Factor must be > 1 (got %v)", ErrInvalidConfig, c.Factor) + } + if !(c.Jitter >= 0 && c.Jitter < 1) { + return fmt.Errorf("%w: backoff Jitter must be in [0, 1) (got %v)", ErrInvalidConfig, c.Jitter) + } + return nil +} + +// SleepFunc sleeps for d or until ctx is done, returning ctx.Err() in the latter case. +type SleepFunc func(ctx context.Context, d time.Duration) error + +// ExponentialBackoff yields capped, jittered exponential delays. Not safe for concurrent use. +type ExponentialBackoff struct { + cfg ExponentialBackoffConfig + attempt int + randFloat func() float64 + sleep SleepFunc +} + +// ExponentialBackoffOption customises an ExponentialBackoff (mainly for tests). +type ExponentialBackoffOption func(*ExponentialBackoff) + +// WithBackoffRandFloat replaces the jitter source; fn must return values in [0, 1). +func WithBackoffRandFloat(fn func() float64) ExponentialBackoffOption { + return func(b *ExponentialBackoff) { + if fn != nil { + b.randFloat = fn + } + } +} + +// WithBackoffSleeper replaces the function used by Sleep to wait. +func WithBackoffSleeper(fn SleepFunc) ExponentialBackoffOption { + return func(b *ExponentialBackoff) { + if fn != nil { + b.sleep = fn + } + } +} + +// NewExponentialBackoff creates an ExponentialBackoff after validating cfg. +func NewExponentialBackoff( + cfg ExponentialBackoffConfig, opts ...ExponentialBackoffOption, +) (*ExponentialBackoff, error) { + if err := cfg.Validate(); err != nil { + return nil, err + } + b := &ExponentialBackoff{ + cfg: cfg, + randFloat: rand.Float64, + sleep: SleepContext, + } + for _, opt := range opts { + opt(b) + } + return b, nil +} + +// Next returns the delay for the current attempt and advances the attempt counter. +// +// base = min(Initial * Factor^attempt, Max) +// delay = base * (1 + Jitter*(2*r-1)), r in [0,1) +// delay = min(delay, Max) +func (b *ExponentialBackoff) Next() time.Duration { + maxF := float64(b.cfg.Max) + base := float64(b.cfg.Initial) * math.Pow(b.cfg.Factor, float64(b.attempt)) + if base > maxF || math.IsInf(base, 0) || math.IsNaN(base) { + base = maxF + } + if b.attempt < math.MaxInt32 { + b.attempt++ + } + delay := base * (1 + b.cfg.Jitter*(2*b.randFloat()-1)) + if delay > maxF { + delay = maxF + } + return time.Duration(delay) +} + +// Sleep calls Next and sleeps that long; it returns the delay and ctx.Err() if interrupted. +func (b *ExponentialBackoff) Sleep(ctx context.Context) (time.Duration, error) { + d := b.Next() + return d, b.sleep(ctx, d) +} + +// Reset sets the attempt counter back to 0. +func (b *ExponentialBackoff) Reset() { + b.attempt = 0 +} + +// Attempts returns the number of Next calls since construction or the last Reset. +func (b *ExponentialBackoff) Attempts() int { + return b.attempt +} + +// SleepContext sleeps for d using a timer, returning early with ctx.Err() when ctx is done. +func SleepContext(ctx context.Context, d time.Duration) error { + if err := ctx.Err(); err != nil { + return err + } + timer := time.NewTimer(d) + defer timer.Stop() + select { + case <-ctx.Done(): + return ctx.Err() + case <-timer.C: + return nil + } +} diff --git a/common/backoff_test.go b/common/backoff_test.go new file mode 100644 index 000000000..d622cc24d --- /dev/null +++ b/common/backoff_test.go @@ -0,0 +1,138 @@ +package common + +import ( + "context" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func testBackoffConfig(jitter float64) ExponentialBackoffConfig { + return ExponentialBackoffConfig{Initial: 100 * time.Millisecond, Max: time.Second, Factor: 2, Jitter: jitter} +} + +func TestExponentialBackoffConfig_Validate(t *testing.T) { + tests := []struct { + name string + cfg ExponentialBackoffConfig + wantErr bool + }{ + {"valid", testBackoffConfig(0.2), false}, + {"zero jitter", testBackoffConfig(0), false}, + {"initial zero", ExponentialBackoffConfig{Initial: 0, Max: time.Second, Factor: 2}, true}, + {"max below initial", ExponentialBackoffConfig{Initial: time.Second, Max: time.Millisecond, Factor: 2}, true}, + {"factor one", ExponentialBackoffConfig{Initial: time.Millisecond, Max: time.Second, Factor: 1}, true}, + {"jitter one", ExponentialBackoffConfig{Initial: time.Millisecond, Max: time.Second, Factor: 2, Jitter: 1}, true}, + {"jitter negative", ExponentialBackoffConfig{Initial: time.Millisecond, Max: time.Second, Factor: 2, Jitter: -0.1}, true}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + err := tt.cfg.Validate() + _, ctorErr := NewExponentialBackoff(tt.cfg) + if tt.wantErr { + require.ErrorIs(t, err, ErrInvalidConfig) + require.ErrorIs(t, ctorErr, ErrInvalidConfig) + return + } + require.NoError(t, err) + require.NoError(t, ctorErr) + }) + } +} + +func TestExponentialBackoff_GrowthCapReset(t *testing.T) { + b, err := NewExponentialBackoff(testBackoffConfig(0), WithBackoffRandFloat(func() float64 { return 0.5 })) + require.NoError(t, err) + + expected := []time.Duration{100, 200, 400, 800, 1000, 1000, 1000} + for i, e := range expected { + require.Equal(t, e*time.Millisecond, b.Next(), "attempt %d", i) + require.Equal(t, i+1, b.Attempts()) + } + + b.Reset() + require.Zero(t, b.Attempts()) + require.Equal(t, 100*time.Millisecond, b.Next()) +} + +func TestExponentialBackoff_HugeAttemptDoesNotOverflow(t *testing.T) { + b, err := NewExponentialBackoff(testBackoffConfig(0), WithBackoffRandFloat(func() float64 { return 0.5 })) + require.NoError(t, err) + b.attempt = 1 << 20 + require.Equal(t, time.Second, b.Next()) +} + +func TestExponentialBackoff_JitterBounds(t *testing.T) { + const jitter = 0.2 + tests := []struct { + name string + r float64 + }{ + {"lowest", 0}, + {"middle", 0.5}, + {"highest", 0.999999}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + b, err := NewExponentialBackoff(testBackoffConfig(jitter), WithBackoffRandFloat(func() float64 { return tt.r })) + require.NoError(t, err) + for i := 0; i < 8; i++ { + base := float64(100*time.Millisecond) * float64(int(1)< float64(time.Second) { + base = float64(time.Second) + } + lo := time.Duration(base * (1 - jitter)) + hi := time.Duration(base * (1 + jitter)) + if hi > time.Second { + hi = time.Second + } + got := b.Next() + require.GreaterOrEqual(t, got, lo-time.Nanosecond, "attempt %d", i) + require.LessOrEqual(t, got, hi, "attempt %d", i) + } + }) + } +} + +func TestExponentialBackoff_SleepUsesInjectedSleeper(t *testing.T) { + var slept []time.Duration + b, err := NewExponentialBackoff(testBackoffConfig(0), + WithBackoffRandFloat(func() float64 { return 0.5 }), + WithBackoffSleeper(func(_ context.Context, d time.Duration) error { + slept = append(slept, d) + return nil + })) + require.NoError(t, err) + + for i := 0; i < 3; i++ { + d, err := b.Sleep(context.Background()) + require.NoError(t, err) + require.Equal(t, slept[i], d) + } + require.Equal(t, []time.Duration{100 * time.Millisecond, 200 * time.Millisecond, 400 * time.Millisecond}, slept) +} + +func TestExponentialBackoff_SleepCtxCancelled(t *testing.T) { + b, err := NewExponentialBackoff(ExponentialBackoffConfig{Initial: time.Hour, Max: time.Hour, Factor: 2}) + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + go func() { + time.Sleep(10 * time.Millisecond) + cancel() + }() + + start := time.Now() + _, err = b.Sleep(ctx) + require.ErrorIs(t, err, context.Canceled) + require.Less(t, time.Since(start), time.Second) +} + +func TestSleepContext(t *testing.T) { + require.NoError(t, SleepContext(context.Background(), time.Millisecond)) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + require.ErrorIs(t, SleepContext(ctx, time.Hour), context.Canceled) +} diff --git a/common/errors.go b/common/errors.go index 782b5f861..3deac302d 100644 --- a/common/errors.go +++ b/common/errors.go @@ -1,8 +1,12 @@ package common import ( + "errors" + "net/http" "regexp" "strings" + + "github.com/ethereum/go-ethereum/rpc" ) const maxRangeMatchGroups = 2 @@ -16,6 +20,17 @@ var ( reEthGetLogsLimited = regexp.MustCompile(`eth_getLogs is limited to a\s+([\d,]+)\s+range`) // Matches "query exceeds max block range 100000" reQueryExceedsMaxBlockRange = regexp.MustCompile(`query exceeds max block range\s+(\d+)`) + + // Matches "too many batch requests, max is 40" + reTooManyBatchRequests = regexp.MustCompile(`too many batch requests, max is\s*(\d+)`) + // Matches "batch limit 100 exceeded" + reBatchLimitExceeded = regexp.MustCompile(`batch limit (\d+) exceeded`) + // Matches "batch of more than 100 requests" + reBatchOfMoreThan = regexp.MustCompile(`(?i)batch of more than (\d+) requests`) + // Matches batch-limit messages that do not carry the limit (the caller must reduce the size by itself) + reBatchLimitKeyword = regexp.MustCompile( + `(?i)(batch too large|too many batch requests|batch size (limit|too large|exceeded)|` + + `batch (request )?limit|batch request (was )?too large)`) ) // ParseMaxRangeFromError extracts the max range value from error message @@ -48,3 +63,42 @@ func ParseMaxRangeFromError(errMsg string) (uint64, bool) { return maxRange, true } + +// ParseMaxBatchSizeFromError extracts a provider's maximum JSON-RPC batch size from an error message. +// Expected formats: +// - "too many batch requests, max is 40" +// - "batch limit 100 exceeded" +// - "batch of more than 100 requests" +// +// It returns false when no pattern matches or when the parsed value is 0. +func ParseMaxBatchSizeFromError(errMsg string) (uint64, bool) { + for _, re := range []*regexp.Regexp{reTooManyBatchRequests, reBatchLimitExceeded, reBatchOfMoreThan} { + matches := re.FindStringSubmatch(errMsg) + if len(matches) < maxRangeMatchGroups { + continue + } + maxSize, err := ParseUint64HexOrDecimal(matches[1]) + if err != nil || maxSize == 0 { + return 0, false + } + return maxSize, true + } + return 0, false +} + +// IsBatchLimitError reports whether err means that a JSON-RPC batch was too large for the provider. +// HTTP 429 is deliberately not considered a batch-limit error. +func IsBatchLimitError(err error) bool { + if err == nil { + return false + } + msg := err.Error() + if _, ok := ParseMaxBatchSizeFromError(msg); ok { + return true + } + if reBatchLimitKeyword.MatchString(msg) { + return true + } + var httpErr rpc.HTTPError + return errors.As(err, &httpErr) && httpErr.StatusCode == http.StatusRequestEntityTooLarge +} diff --git a/common/errors_test.go b/common/errors_test.go index f5af8d543..7cce2a190 100644 --- a/common/errors_test.go +++ b/common/errors_test.go @@ -5,6 +5,7 @@ import ( "fmt" "testing" + "github.com/ethereum/go-ethereum/rpc" "github.com/stretchr/testify/require" ) @@ -168,3 +169,55 @@ func TestParseMaxRangeFromError_WrappedErrors(t *testing.T) { require.Equal(t, uint64(2500), result) }) } + +func TestParseMaxBatchSizeFromError(t *testing.T) { + tests := []struct { + name string + msg string + expected uint64 + ok bool + }{ + {"issue string", "400 Bad Request: too many batch requests, max is 40", 40, true}, + {"no space after is", "too many batch requests, max is100", 100, true}, + {"batch limit exceeded", "batch limit 100 exceeded", 100, true}, + {"batch of more than", "Batch of more than 50 requests is not allowed", 50, true}, + {"zero limit", "too many batch requests, max is 0", 0, false}, + {"keyword without number", "batch too large", 0, false}, + {"unrelated", "connection refused", 0, false}, + {"empty", "", 0, false}, + {"overflow", "too many batch requests, max is 99999999999999999999999", 0, false}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got, ok := ParseMaxBatchSizeFromError(tt.msg) + require.Equal(t, tt.ok, ok) + require.Equal(t, tt.expected, got) + }) + } +} + +func TestIsBatchLimitError(t *testing.T) { + tests := []struct { + name string + err error + expected bool + }{ + {"nil", nil, false}, + {"issue string", errors.New("400 Bad Request: too many batch requests, max is 40"), true}, + {"wrapped HTTPError with limit", + fmt.Errorf("wrap: %w", rpc.HTTPError{StatusCode: 400, Status: "400 Bad Request", + Body: []byte("too many batch requests, max is 40")}), true}, + {"geth batch too large", errors.New("batch too large"), true}, + {"keyword without number", errors.New("too many batch requests"), true}, + {"HTTP 413", fmt.Errorf("wrap: %w", rpc.HTTPError{StatusCode: 413, Status: "413 Request Entity Too Large"}), true}, + {"HTTP 429", rpc.HTTPError{StatusCode: 429, Status: "429 Too Many Requests"}, false}, + {"connection refused", errors.New("connection refused"), false}, + {"response too large", errors.New("response too large"), false}, + {"max is 0", errors.New("some error, max is 0"), false}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + require.Equal(t, tt.expected, IsBatchLimitError(tt.err)) + }) + } +} diff --git a/common/repeated_error_logger.go b/common/repeated_error_logger.go new file mode 100644 index 000000000..d25e50bbc --- /dev/null +++ b/common/repeated_error_logger.go @@ -0,0 +1,96 @@ +package common + +import ( + "regexp" + "sync" + "time" + + "github.com/agglayer/aggkit/log" +) + +// reVariablePart matches the parts of an error message that usually change between attempts of the same +// failure (block numbers, ranges, hashes, request ids), so they do not make each retry a "distinct" error. +var reVariablePart = regexp.MustCompile(`0x[0-9a-fA-F]+|\d+`) + +// RepeatedErrorLogger bounds the log volume of an error that may repeat indefinitely in a retry loop. +// Messages are compared after replacing numbers and hex strings, so errors that only differ in them are +// considered the same. The first occurrence of a distinct message is logged at Warn, repeats at Debug, +// and a Warn summary carrying the number of occurrences is emitted once per window. +type RepeatedErrorLogger struct { + log Logger + prefix string + window time.Duration + now func() time.Time + mu sync.Mutex + lastMsg string // normalised key of the last error + lastErr string // text of the last error, for the Reset summary + hasLast bool + suppressed int + lastWarn time.Time +} + +// NewRepeatedErrorLogger creates a RepeatedErrorLogger. A nil logger is replaced by a no-op logger. +func NewRepeatedErrorLogger(logger Logger, prefix string, window time.Duration) *RepeatedErrorLogger { + if logger == nil { + logger = log.NewLoggerNil() + } + return &RepeatedErrorLogger{ + log: logger, + prefix: prefix, + window: window, + now: time.Now, + } +} + +// WithClock replaces the clock (tests); it returns the receiver. +func (l *RepeatedErrorLogger) WithClock(now func() time.Time) *RepeatedErrorLogger { + l.mu.Lock() + defer l.mu.Unlock() + if now != nil { + l.now = now + } + return l +} + +// Log records one occurrence of err. A nil err is ignored. +func (l *RepeatedErrorLogger) Log(err error) { + if err == nil { + return + } + l.mu.Lock() + defer l.mu.Unlock() + + key := reVariablePart.ReplaceAllString(err.Error(), "#") + now := l.now() + l.lastErr = err.Error() + switch { + case !l.hasLast || key != l.lastMsg: + l.log.Warnf("%s: %v", l.prefix, err) + l.lastMsg, l.hasLast = key, true + l.suppressed = 0 + l.lastWarn = now + case now.Sub(l.lastWarn) >= l.window: + l.log.Warnf("%s: %v (repeated %d times in the last %s)", + l.prefix, err, l.suppressed+1, now.Sub(l.lastWarn).Truncate(time.Second)) + l.suppressed = 0 + l.lastWarn = now + default: + l.log.Debugf("%s: %v", l.prefix, err) + l.suppressed++ + } +} + +// Reset forgets the current error (call after a success) so the next error is logged at Warn again. +// If occurrences were suppressed since the last Warn, it emits one Warn summary with their count; +// otherwise it logs nothing. +func (l *RepeatedErrorLogger) Reset() { + l.mu.Lock() + defer l.mu.Unlock() + if l.hasLast && l.suppressed > 0 { + l.log.Warnf("%s: %q repeated %d more times in the last %s before recovering", + l.prefix, l.lastErr, l.suppressed, l.now().Sub(l.lastWarn).Truncate(time.Second)) + } + l.hasLast = false + l.lastMsg = "" + l.suppressed = 0 +} diff --git a/common/repeated_error_logger_test.go b/common/repeated_error_logger_test.go new file mode 100644 index 000000000..c0e3e0857 --- /dev/null +++ b/common/repeated_error_logger_test.go @@ -0,0 +1,161 @@ +package common + +import ( + "errors" + "fmt" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +type loggedLine struct { + level string + msg string +} + +// captureLogger implements Logger, recording only the Warn/Debug lines used by RepeatedErrorLogger. +type captureLogger struct { + mu sync.Mutex + lines []loggedLine +} + +func (c *captureLogger) add(level, format string, args ...interface{}) { + c.mu.Lock() + defer c.mu.Unlock() + c.lines = append(c.lines, loggedLine{level, fmt.Sprintf(format, args...)}) +} + +func (c *captureLogger) levels() []string { + c.mu.Lock() + defer c.mu.Unlock() + res := make([]string, 0, len(c.lines)) + for _, l := range c.lines { + res = append(res, l.level) + } + return res +} + +func (c *captureLogger) Panicf(string, ...interface{}) {} +func (c *captureLogger) Fatalf(string, ...interface{}) {} +func (c *captureLogger) Info(...interface{}) {} +func (c *captureLogger) Infof(string, ...interface{}) {} +func (c *captureLogger) Error(...interface{}) {} +func (c *captureLogger) Errorf(string, ...interface{}) {} +func (c *captureLogger) Warn(args ...interface{}) { c.add("warn", "%s", fmt.Sprint(args...)) } +func (c *captureLogger) Warnf(f string, a ...interface{}) { + c.add("warn", f, a...) +} +func (c *captureLogger) Debug(args ...interface{}) { c.add("debug", "%s", fmt.Sprint(args...)) } +func (c *captureLogger) Debugf(f string, a ...interface{}) { + c.add("debug", f, a...) +} + +func TestRepeatedErrorLogger_LevelSequence(t *testing.T) { + logger := &captureLogger{} + now := time.Unix(1000, 0) + rl := NewRepeatedErrorLogger(logger, "step", time.Minute).WithClock(func() time.Time { return now }) + errA := errors.New("boom") + + // First occurrence: Warn; repeats inside the window: Debug. + rl.Log(errA) + for i := 0; i < 3; i++ { + now = now.Add(10 * time.Second) + rl.Log(errA) + } + require.Equal(t, []string{"warn", "debug", "debug", "debug"}, logger.levels()) + + // Window elapsed: summary Warn with the count (3 suppressed + this one). + now = now.Add(40 * time.Second) + rl.Log(errA) + levels := logger.levels() + require.Equal(t, "warn", levels[len(levels)-1]) + require.True(t, strings.Contains(logger.lines[len(logger.lines)-1].msg, "repeated 4 times in the last 1m10s"), + logger.lines[len(logger.lines)-1].msg) + + // Next repeat is Debug again. + now = now.Add(time.Second) + rl.Log(errA) + require.Equal(t, "debug", logger.levels()[len(logger.lines)-1]) + + // A distinct message is a Warn immediately. + rl.Log(errors.New("other")) + require.Equal(t, "warn", logger.levels()[len(logger.lines)-1]) + + // After Reset the same message is a Warn again, and Reset itself is silent. + n := len(logger.lines) + rl.Reset() + require.Len(t, logger.lines, n) + rl.Log(errors.New("other")) + require.Equal(t, "warn", logger.levels()[n]) +} + +func TestRepeatedErrorLogger_WarnCountEqualsWindows(t *testing.T) { + logger := &captureLogger{} + now := time.Unix(0, 0) + rl := NewRepeatedErrorLogger(logger, "p", time.Minute).WithClock(func() time.Time { return now }) + err := errors.New("same") + for i := 0; i < 301; i++ { // 5 minutes at one call per second + rl.Log(err) + now = now.Add(time.Second) + } + warns := 0 + for _, l := range logger.levels() { + if l == "warn" { + warns++ + } + } + require.Equal(t, 1+5, warns) +} + +func TestRepeatedErrorLogger_NilCases(t *testing.T) { + logger := &captureLogger{} + NewRepeatedErrorLogger(logger, "p", time.Minute).Log(nil) + require.Empty(t, logger.lines) + + require.NotPanics(t, func() { + NewRepeatedErrorLogger(nil, "p", time.Minute).Log(errors.New("x")) + }) +} + +func TestRepeatedErrorLogger_VaryingNumbersAreTheSameError(t *testing.T) { + logger := &captureLogger{} + now := time.Unix(0, 0) + rl := NewRepeatedErrorLogger(logger, "p", time.Minute).WithClock(func() time.Time { return now }) + + rl.Log(errors.New("cannot update ToBlock: block 123457 (0xabc1) not found")) + now = now.Add(time.Second) + rl.Log(errors.New("cannot update ToBlock: block 123458 (0xdef2) not found")) + now = now.Add(time.Second) + rl.Log(errors.New("cannot update ToBlock: block 123459 (0x1234) not found")) + require.Equal(t, []string{"warn", "debug", "debug"}, logger.levels()) + + // A really different message is still a Warn. + rl.Log(errors.New("connection refused")) + require.Equal(t, "warn", logger.levels()[3]) +} + +func TestRepeatedErrorLogger_ResetEmitsSummaryOfSuppressed(t *testing.T) { + logger := &captureLogger{} + now := time.Unix(0, 0) + rl := NewRepeatedErrorLogger(logger, "p", time.Minute).WithClock(func() time.Time { return now }) + err := errors.New("boom") + + rl.Log(err) // warn + rl.Log(err) // debug (suppressed 1) + rl.Log(err) // debug (suppressed 2) + n := len(logger.lines) + now = now.Add(5 * time.Second) + rl.Reset() + require.Len(t, logger.lines, n+1) + require.Equal(t, "warn", logger.levels()[n]) + require.Contains(t, logger.lines[n].msg, "repeated 2 more times") + + // Nothing suppressed: Reset stays silent. + rl.Log(err) + n = len(logger.lines) + rl.Reset() + require.Len(t, logger.lines, n) +} From cb22fe9682409a2b57dff9d4e1f6ac9e036bd2ee Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 17:45:55 +0000 Subject: [PATCH 2/8] fix(etherman): adapt header batch size to the provider batch limit (#1889) Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- config/config_test.go | 2 + config/default.go | 2 + docs/common_config.md | 3 + etherman/batch_requests.go | 80 +++++++- etherman/batch_size_adaptive_test.go | 289 +++++++++++++++++++++++++++ etherman/batch_size_limiter.go | 52 +++++ etherman/config/network.go | 14 ++ etherman/config/network_test.go | 60 ++++++ etherman/default_eth_client.go | 4 +- 9 files changed, 498 insertions(+), 8 deletions(-) create mode 100644 etherman/batch_size_adaptive_test.go create mode 100644 etherman/batch_size_limiter.go diff --git a/config/config_test.go b/config/config_test.go index 98727c0f7..f4f10b4d3 100644 --- a/config/config_test.go +++ b/config/config_test.go @@ -63,8 +63,10 @@ func TestLoadDefaultConfig(t *testing.T) { Mode: ethermanconfig.RPCModeBasic, HashFromJSON: true, BatchBlockHeaderRetrieval: true, + BatchRequestMaxSize: ethermanconfig.DefaultBatchRequestMaxSize, }, cfg.Common.L2RPC) require.True(t, cfg.L1NetworkConfig.RPC.BatchBlockHeaderRetrieval) + require.Equal(t, ethermanconfig.DefaultBatchRequestMaxSize, cfg.L1NetworkConfig.RPC.BatchRequestMaxSize) require.Equal(t, cfg.Profiling.ProfilingEnabled, false) require.Equal(t, cfg.Profiling.ProfilingHost, "localhost") require.Equal(t, cfg.Profiling.ProfilingPort, 6060) diff --git a/config/default.go b/config/default.go index ae32bca37..4715995de 100644 --- a/config/default.go +++ b/config/default.go @@ -53,6 +53,7 @@ defaultDBQueryTimeout = "5m" BackoffMultiplier = 2.0 HashFromJSON = true BatchBlockHeaderRetrieval = true + BatchRequestMaxSize = 1000 ` // DefaultValues is the default configuration @@ -85,6 +86,7 @@ BlocksChunkSize = {{L1Config.BlocksChunkSize}} BackoffMultiplier = 2.0 HashFromJSON = true BatchBlockHeaderRetrieval = true + BatchRequestMaxSize = 1000 [L2NetworkConfig] # InitialLER: optional override for the initial Local Exit Root (0x000...000 is a valid value). diff --git a/docs/common_config.md b/docs/common_config.md index a16b3737a..7c1c570c3 100644 --- a/docs/common_config.md +++ b/docs/common_config.md @@ -194,6 +194,7 @@ request per IP ever. Its default stays `10`. | `Mode` | `string` | `""` | Client mode: `""` or `"basic"` for standard nodes, `"op"` for Optimism nodes | | `HashFromJSON` | `bool` | `false` | When `true`, fetches block hashes via JSON-RPC (`eth_getBlockByNumber`). When `false`, computes them locally from the RLP-encoded header (go-ethereum default). Enable this for nodes where RLP hashing does not match the canonical block hash | | `BatchBlockHeaderRetrieval` | `bool` | `true` | When `true`, uses JSON-RPC batch requests to fetch block headers in bulk (faster). Disable if the node does not support batch calls | +| `BatchRequestMaxSize` | `int` | `1000` | Initial maximum number of requests per JSON-RPC batch when fetching block headers. The client lowers it automatically when the provider rejects a batch as too large. `0` means the default (`1000`); negative values are invalid | | `RetryMode` | `string` | `"backoff"` | Retry strategy: `"backoff"` for exponential backoff, `"delays"` for fixed delay list, `""` for no retries | | `MaxRetries` | `int` | `5` | Maximum number of retry attempts | | `InitialBackoff` | `duration` | `5s` | Initial wait time before the first retry (backoff mode) | @@ -209,6 +210,7 @@ URL = "http://localhost:8545" Mode = "basic" HashFromJSON = false BatchBlockHeaderRetrieval = true +BatchRequestMaxSize = 1000 RetryMode = "backoff" MaxRetries = 5 InitialBackoff = "5s" @@ -220,6 +222,7 @@ URL = "http://localhost:8123" Mode = "basic" HashFromJSON = true BatchBlockHeaderRetrieval = true +BatchRequestMaxSize = 1000 RetryMode = "delays" MaxRetries = 6 Delays = ["1s", "2s", "5s", "10s", "30s", "60s"] diff --git a/etherman/batch_requests.go b/etherman/batch_requests.go index 489cca863..58defbeb1 100644 --- a/etherman/batch_requests.go +++ b/etherman/batch_requests.go @@ -3,9 +3,11 @@ package etherman import ( "context" "fmt" + "sort" "sync" aggkitcommon "github.com/agglayer/aggkit/common" + ethermanconfig "github.com/agglayer/aggkit/etherman/config" aggkittypes "github.com/agglayer/aggkit/types" "github.com/ethereum/go-ethereum/common" ethtypes "github.com/ethereum/go-ethereum/core/types" @@ -58,7 +60,7 @@ func (b *blockRawEth) ToBlockHeader() (*aggkittypes.BlockHeader, error) { } // https://www.alchemy.com/docs/reference/batch-requests -const batchRequestLimitHTTP = 1000 +const batchRequestLimitHTTP = ethermanconfig.DefaultBatchRequestMaxSize // BlockHeadersResult is an alias for aggkittypes.BlockHeadersResult for backward compatibility. type BlockHeadersResult = aggkittypes.BlockHeadersResult @@ -90,12 +92,66 @@ func RetrieveBlockHeadersBatch(ctx context.Context, rpcClient aggkittypes.RPCClienter, blockNumbers []uint64, maxConcurrency int) (*BlockHeadersResult, error) { - return retrieveBlockHeadersInBatchParallel( - ctx, - log, - func(ctx context.Context, blocks []uint64) (*BlockHeadersResult, error) { - return retrieveBlockHeadersInBatch(ctx, log, rpcClient, blocks) - }, blockNumbers, batchRequestLimitHTTP, maxConcurrency) + return retrieveBlockHeadersBatchAdaptive(ctx, log, rpcClient, + newBatchSizeLimiter(batchRequestLimitHTTP), blockNumbers, maxConcurrency) +} + +// retrieveBlockHeadersBatchAdaptive retrieves block headers using batch requests whose size is bounded by limiter. +// When the provider rejects a batch as too large, the limiter is lowered and only the rejected block numbers +// are requested again; headers already retrieved are kept. +func retrieveBlockHeadersBatchAdaptive(ctx context.Context, + log aggkitcommon.Logger, + rpcClient aggkittypes.RPCClienter, + limiter *batchSizeLimiter, + blockNumbers []uint64, + maxConcurrency int) (*BlockHeadersResult, error) { + var mu sync.Mutex + remaining := blockNumbers + finalResult := NewBlockHeadersResult() + + for { + if err := ctx.Err(); err != nil { + return nil, err + } + chunks := splitBlockNumbersIntoChunks(remaining, limiter.Size()) + var rejected []uint64 + + g, gctx := errgroup.WithContext(ctx) + g.SetLimit(maxConcurrency) + for _, chunk := range chunks { + g.Go(func() error { + chunkResult, err := retrieveBlockHeadersInBatch(gctx, log, rpcClient, chunk) + if err == nil { + mu.Lock() + defer mu.Unlock() + finalResult.Merge(chunkResult) + return nil + } + if aggkitcommon.IsBatchLimitError(err) && len(chunk) > 1 { + oldSize, newSize, changed := limiter.shrinkAfterRejection(len(chunk), err) + if changed { + log.Warnf("etherman: provider rejected a JSON-RPC batch of %d requests, "+ + "reducing batch size %d -> %d: %v", len(chunk), oldSize, newSize, err) + } + mu.Lock() + defer mu.Unlock() + rejected = append(rejected, chunk...) + return nil + } + return fmt.Errorf("RetrieveBlockHeadersInBatchParallel: %w", err) + }) + } + if err := g.Wait(); err != nil { + return nil, err + } + if len(rejected) == 0 { + log.Debugf("retrieveRPCBlockHeadersInParallel: Retrieved %d/%d block headers", + len(finalResult.Headers), len(blockNumbers)) + return finalResult, nil + } + sort.Slice(rejected, func(i, j int) bool { return rejected[i] < rejected[j] }) + remaining = rejected + } } // RetrieveBlockHeadersLegacy retrieves block headers for the given block numbers using individual requests @@ -154,6 +210,16 @@ func retrieveBlockHeadersInBatch(ctx context.Context, // Catastrophic error: the whole batch call failed return nil, fmt.Errorf("retrieveRPCBlockHeadersInBatch(%d): BatchCallContext error: %w", len(blockNumbers), err) } + // go-ethereum rejects an oversized batch per element with a nil top-level error: lift it to a batch error. + // A single-element batch cannot be shrunk further, so its error stays a per-block error below. + if len(batch) > 1 { + for _, elem := range batch { + if elem.Error != nil && aggkitcommon.IsBatchLimitError(elem.Error) { + return nil, fmt.Errorf("retrieveRPCBlockHeadersInBatch(%d): batch rejected by provider: %w", + len(blockNumbers), elem.Error) + } + } + } // Process each element individually, collecting successes and failures for i, elem := range batch { diff --git a/etherman/batch_size_adaptive_test.go b/etherman/batch_size_adaptive_test.go new file mode 100644 index 000000000..26f55a258 --- /dev/null +++ b/etherman/batch_size_adaptive_test.go @@ -0,0 +1,289 @@ +package etherman + +import ( + "context" + "errors" + "fmt" + "net/http" + "sort" + "sync" + "testing" + + ethermanconfig "github.com/agglayer/aggkit/etherman/config" + "github.com/agglayer/aggkit/log" + "github.com/ethereum/go-ethereum/rpc" + "github.com/stretchr/testify/require" +) + +// limitedRPCClient is a fake RPCClienter that rejects batches larger than maxBatch. +type limitedRPCClient struct { + maxBatch int + // reject returns the top-level error for an oversized batch; if elementShape is true the + // rejection is reported per element (go-ethereum server-side limit) with a nil top-level error. + rejectErr error + elementShape bool + + mu sync.Mutex + sizes []int + oversize []int +} + +func (f *limitedRPCClient) Call(any, string, ...any) error { return errors.New("not implemented") } + +func (f *limitedRPCClient) CallContext(context.Context, any, string, ...any) error { + return errors.New("not implemented") +} + +func (f *limitedRPCClient) BatchCallContext(_ context.Context, b []rpc.BatchElem) error { + f.mu.Lock() + f.sizes = append(f.sizes, len(b)) + over := len(b) > f.maxBatch + if over { + f.oversize = append(f.oversize, len(b)) + } + f.mu.Unlock() + if over { + if f.elementShape { + for i := range b { + if i == 0 { + b[i].Error = errors.New("batch too large") + } else { + b[i].Error = errors.New("missing batch response") + } + } + return nil + } + return f.rejectErr + } + for i := range b { + arg := fmt.Sprint(b[i].Args[0]) + raw, ok := b[i].Result.(*blockRawEth) + if !ok { + return errors.New("unexpected result type") + } + raw.Number = arg + raw.Hash = fmt.Sprintf("0x%064x", i+1) + raw.Timestamp = "0x1" + raw.ParentHash = fmt.Sprintf("0x%064x", i) + } + return nil +} + +func (f *limitedRPCClient) reset() { + f.mu.Lock() + defer f.mu.Unlock() + f.sizes = nil + f.oversize = nil +} + +func (f *limitedRPCClient) maxSeenSince() int { + f.mu.Lock() + defer f.mu.Unlock() + m := 0 + for _, s := range f.sizes { + m = max(m, s) + } + return m +} + +func distinctDescending(values []int) []int { + set := make(map[int]struct{}, len(values)) + for _, v := range values { + set[v] = struct{}{} + } + res := make([]int, 0, len(set)) + for v := range set { + res = append(res, v) + } + sort.Sort(sort.Reverse(sort.IntSlice(res))) + return res +} + +func blockNumbersRange(n int) []uint64 { + res := make([]uint64, n) + for i := range res { + res[i] = uint64(100 + i) + } + return res +} + +func requireAllHeaders(t *testing.T, blocks []uint64, headers map[uint64]struct{}, nHeaders int, nErrors int) { + t.Helper() + require.Equal(t, len(blocks), nHeaders) + require.Zero(t, nErrors) + for _, bn := range blocks { + _, ok := headers[bn] + require.True(t, ok, "missing block %d", bn) + } +} + +func headerSet(res *BlockHeadersResult) map[uint64]struct{} { + set := make(map[uint64]struct{}, len(res.Headers)) + for bn := range res.Headers { + set[bn] = struct{}{} + } + return set +} + +func TestRetrieveBlockHeadersAdaptive(t *testing.T) { + tooManyWithNumber := rpc.HTTPError{StatusCode: http.StatusBadRequest, Status: "400 Bad Request", + Body: []byte("too many batch requests, max is 40")} + tooManyNoNumber := rpc.HTTPError{StatusCode: http.StatusBadRequest, Status: "400 Bad Request", + Body: []byte("too many batch requests")} + + tests := []struct { + name string + fake *limitedRPCClient + initial int + wantSize int + wantRejected []int // distinct oversized batch sizes the provider rejected, descending (nil: not asserted) + }{ + { + name: "parsed limit shrinks straight to 40", + fake: &limitedRPCClient{maxBatch: 40, rejectErr: tooManyWithNumber}, + initial: 1000, + wantSize: 40, + wantRejected: []int{1000}, + }, + { + name: "no number halves 1000 -> 31", + fake: &limitedRPCClient{maxBatch: 40, rejectErr: tooManyNoNumber}, + initial: 1000, + wantSize: 31, + wantRejected: []int{1000, 500, 250, 125, 62}, + }, + { + name: "geth per element shape halves", + fake: &limitedRPCClient{maxBatch: 40, elementShape: true}, + initial: 1000, + wantSize: 31, + wantRejected: []int{1000, 500, 250, 125, 62}, + }, + { + name: "limit of 1", + fake: &limitedRPCClient{maxBatch: 1, rejectErr: tooManyNoNumber}, + initial: 1000, + wantSize: 1, + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + client := NewDefaultEthClient(nil, tc.fake, ðermanconfig.RPCClientConfig{ + BatchBlockHeaderRetrieval: true, BatchRequestMaxSize: tc.initial, + }) + blocks := blockNumbersRange(1000) + + res, err := client.RetrieveBlockHeaders(context.Background(), blocks, 4) + require.NoError(t, err) + requireAllHeaders(t, blocks, headerSet(res), len(res.Headers), len(res.Errors)) + require.Equal(t, tc.wantSize, client.batchSize.Size()) + if tc.wantRejected != nil { + require.Equal(t, tc.wantRejected, distinctDescending(tc.fake.oversize)) + } + + // Second call on the same client starts at the remembered size: no oversized batch at all. + tc.fake.reset() + res, err = client.RetrieveBlockHeaders(context.Background(), blocks, 4) + require.NoError(t, err) + requireAllHeaders(t, blocks, headerSet(res), len(res.Headers), len(res.Errors)) + require.Empty(t, tc.fake.oversize) + require.LessOrEqual(t, tc.fake.maxSeenSince(), tc.wantSize) + require.Equal(t, tc.wantSize, client.batchSize.Size()) + }) + } +} + +func TestRetrieveBlockHeadersAdaptive_ConfiguredStartSize(t *testing.T) { + fake := &limitedRPCClient{maxBatch: 1000} + client := NewDefaultEthClient(nil, fake, ðermanconfig.RPCClientConfig{ + BatchBlockHeaderRetrieval: true, BatchRequestMaxSize: 25, + }) + blocks := blockNumbersRange(100) + res, err := client.RetrieveBlockHeaders(context.Background(), blocks, 2) + require.NoError(t, err) + require.Len(t, res.Headers, 100) + require.Equal(t, 25, fake.maxSeenSince()) + require.Equal(t, 25, client.batchSize.Size()) +} + +func TestRetrieveBlockHeadersAdaptive_ZeroConfigUsesDefault(t *testing.T) { + client := NewDefaultEthClient(nil, &limitedRPCClient{maxBatch: 1000}, + ðermanconfig.RPCClientConfig{BatchBlockHeaderRetrieval: true}) + require.Equal(t, ethermanconfig.DefaultBatchRequestMaxSize, client.batchSize.Size()) +} + +func TestRetrieveBlockHeadersAdaptive_GenericErrorDoesNotShrink(t *testing.T) { + fake := &limitedRPCClient{maxBatch: 0, rejectErr: errors.New("connection refused")} + client := NewDefaultEthClient(nil, fake, ðermanconfig.RPCClientConfig{BatchBlockHeaderRetrieval: true}) + res, err := client.RetrieveBlockHeaders(context.Background(), blockNumbersRange(10), 2) + require.Error(t, err) + require.Nil(t, res) + require.ErrorContains(t, err, "connection refused") + require.Equal(t, ethermanconfig.DefaultBatchRequestMaxSize, client.batchSize.Size()) +} + +func TestRetrieveBlockHeadersAdaptive_SizeOneRejectedReturnsError(t *testing.T) { + // the provider rejects even a single request as "too large": stop with the error + fake := &limitedRPCClient{maxBatch: 0, + rejectErr: errors.New("too many batch requests")} + client := NewDefaultEthClient(nil, fake, ðermanconfig.RPCClientConfig{BatchBlockHeaderRetrieval: true}) + res, err := client.RetrieveBlockHeaders(context.Background(), blockNumbersRange(10), 2) + require.Error(t, err) + require.Nil(t, res) + require.Equal(t, 1, client.batchSize.Size()) +} + +func TestRetrieveBlockHeadersAdaptive_SizeOneElementRejectionIsPerBlockError(t *testing.T) { + // a per-element limit error on a single-request batch cannot be shrunk further: it must stay a + // per-block error instead of failing the whole header retrieval + fake := &limitedRPCClient{maxBatch: 0, elementShape: true} + client := NewDefaultEthClient(nil, fake, ðermanconfig.RPCClientConfig{BatchBlockHeaderRetrieval: true}) + blocks := blockNumbersRange(3) + res, err := client.RetrieveBlockHeaders(context.Background(), blocks, 2) + require.NoError(t, err) + require.NotNil(t, res) + require.Empty(t, res.Headers) + require.Len(t, res.Errors, len(blocks)) + require.Equal(t, 1, client.batchSize.Size()) +} + +func TestRetrieveBlockHeadersAdaptive_ContextDone(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + limiter := newBatchSizeLimiter(10) + res, err := retrieveBlockHeadersBatchAdaptive(ctx, log.WithFields("test", "x"), + &limitedRPCClient{maxBatch: 10}, limiter, blockNumbersRange(5), 2) + require.ErrorIs(t, err, context.Canceled) + require.Nil(t, res) +} + +func TestRetrieveBlockHeadersAdaptive_ConcurrentRejectionsNotOverShrunk(t *testing.T) { + // 30 concurrent chunks of 100 are rejected at once with a parsed limit: the size must end at exactly 40. + fake := &limitedRPCClient{maxBatch: 40, rejectErr: rpc.HTTPError{StatusCode: http.StatusBadRequest, + Body: []byte("too many batch requests, max is 40")}} + limiter := newBatchSizeLimiter(100) + blocks := blockNumbersRange(3000) + res, err := retrieveBlockHeadersBatchAdaptive(context.Background(), log.WithFields("test", "x"), + fake, limiter, blocks, 30) + require.NoError(t, err) + requireAllHeaders(t, blocks, headerSet(res), len(res.Headers), len(res.Errors)) + require.Equal(t, 40, limiter.Size()) +} + +func TestBatchSizeLimiter_ShrinkNeverRaises(t *testing.T) { + l := newBatchSizeLimiter(100) + oldSize, newSize, changed := l.shrinkAfterRejection(100, errors.New("too many batch requests, max is 40")) + require.True(t, changed) + require.Equal(t, 100, oldSize) + require.Equal(t, 40, newSize) + + // parsed limit not below the sent size -> halve the sent size, which is already above current: no change + oldSize, newSize, changed = l.shrinkAfterRejection(100, errors.New("too many batch requests, max is 500")) + require.False(t, changed) + require.Equal(t, 40, oldSize) + require.Equal(t, 40, newSize) + require.Equal(t, 40, l.Size()) + + require.Equal(t, ethermanconfig.DefaultBatchRequestMaxSize, newBatchSizeLimiter(0).Size()) + require.Equal(t, ethermanconfig.DefaultBatchRequestMaxSize, newBatchSizeLimiter(-5).Size()) +} diff --git a/etherman/batch_size_limiter.go b/etherman/batch_size_limiter.go new file mode 100644 index 000000000..17984007c --- /dev/null +++ b/etherman/batch_size_limiter.go @@ -0,0 +1,52 @@ +package etherman + +import ( + "sync/atomic" + + aggkitcommon "github.com/agglayer/aggkit/common" + ethermanconfig "github.com/agglayer/aggkit/etherman/config" +) + +// batchSizeLimiter holds the current maximum JSON-RPC batch size. It only ever decreases. +// Invariant: current >= 1. +type batchSizeLimiter struct { + current atomic.Int64 +} + +// newBatchSizeLimiter creates a limiter starting at initial. +// initial <= 0 means ethermanconfig.DefaultBatchRequestMaxSize. +func newBatchSizeLimiter(initial int) *batchSizeLimiter { + if initial <= 0 { + initial = ethermanconfig.DefaultBatchRequestMaxSize + } + l := &batchSizeLimiter{} + l.current.Store(int64(initial)) + return l +} + +// Size returns the current maximum batch size. +func (l *batchSizeLimiter) Size() int { + return int(l.current.Load()) +} + +// shrinkAfterRejection lowers the size after a chunk of sentSize requests was rejected with err. +// target = parsed limit if it satisfies 1 <= parsed < sentSize, else max(1, sentSize/2). +// It only lowers the size, never raises it. changed is true when this caller performed the lowering. +func (l *batchSizeLimiter) shrinkAfterRejection(sentSize int, err error) (oldSize, newSize int, changed bool) { + target := int64(max(1, sentSize/2)) //nolint:mnd + if err != nil { + if parsed, ok := aggkitcommon.ParseMaxBatchSizeFromError(err.Error()); ok && + parsed >= 1 && parsed < uint64(sentSize) { + target = int64(parsed) + } + } + for { + cur := l.current.Load() + if target >= cur { + return int(cur), int(cur), false + } + if l.current.CompareAndSwap(cur, target) { + return int(cur), int(target), true + } + } +} diff --git a/etherman/config/network.go b/etherman/config/network.go index 1f83a4084..7c91c00c0 100644 --- a/etherman/config/network.go +++ b/etherman/config/network.go @@ -18,8 +18,13 @@ var ( ErrMissingGlobalExitRootManagerAddress = errors.New("missing global exit root manager address") ErrInvalidBlocksChunkSize = errors.New("blocks chunk size must be greater than 0") ErrInvalidRollupManagerCreationBlock = errors.New("rollup manager creation block must be greater than 0") + // ErrInvalidBatchRequestMaxSize is returned when BatchRequestMaxSize is negative. + ErrInvalidBatchRequestMaxSize = errors.New("BatchRequestMaxSize must be >= 0") ) +// DefaultBatchRequestMaxSize is the default initial JSON-RPC batch size for block header retrieval. +const DefaultBatchRequestMaxSize = 1000 + // Config holds the common configuration for the Aggkit services type CommonConfig struct { // L2URL is the URL of the L2 node @@ -106,6 +111,10 @@ type RPCClientConfig struct { // BatchBlockHeaderRetrieval enables using JSON-RPC batch requests when fetching block headers. // Disable this if the node does not support batch requests. Default: true. BatchBlockHeaderRetrieval bool `mapstructure:"BatchBlockHeaderRetrieval"` + // BatchRequestMaxSize is the initial maximum number of requests per JSON-RPC batch when fetching block + // headers. The client lowers it automatically when the provider rejects a batch as too large. + // 0 means the default (1000). + BatchRequestMaxSize int `mapstructure:"BatchRequestMaxSize"` // // Params specific per client // ExtraParams contains any additional parameters that may be needed for the RPC client @@ -118,6 +127,7 @@ func NewDefaultRPCClientConfig() *RPCClientConfig { Mode: RPCModeDefault, HashFromJSON: false, BatchBlockHeaderRetrieval: true, + BatchRequestMaxSize: DefaultBatchRequestMaxSize, ExtraParams: make(map[string]any), RetryPolicyGenericConfig: common.RetryPolicyGenericConfig{ Mode: common.RetryConfigModeBackoff, @@ -139,6 +149,10 @@ func (c *RPCClientConfig) Validate() error { return fmt.Errorf("invalid RPC configuration: %w", err) } + if c.BatchRequestMaxSize < 0 { + return fmt.Errorf("invalid RPC configuration: %w (got %d)", ErrInvalidBatchRequestMaxSize, c.BatchRequestMaxSize) + } + if c.Mode != RPCModeDefault && c.Mode != RPCModeBasic && c.Mode != RPCModeOp { return fmt.Errorf("invalid RPC mode: %s", c.Mode) } diff --git a/etherman/config/network_test.go b/etherman/config/network_test.go index 320bb63d2..9984f4c58 100644 --- a/etherman/config/network_test.go +++ b/etherman/config/network_test.go @@ -1,6 +1,7 @@ package config import ( + "bytes" "errors" "fmt" "math/big" @@ -12,6 +13,7 @@ import ( "github.com/agglayer/aggkit/config/types" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethclient" + "github.com/spf13/viper" "github.com/stretchr/testify/require" ) @@ -339,3 +341,61 @@ func TestNewDefaultRPCClientConfig(t *testing.T) { require.Equal(t, time.Second*60, cfg.MaxBackoff.Duration) require.Equal(t, 2.0, cfg.BackoffMultiplier) } + +func TestRPCClientConfig_BatchRequestMaxSize(t *testing.T) { + decode := func(t *testing.T, tomlData string, into *RPCClientConfig) { + t.Helper() + v := viper.New() + v.SetConfigType("toml") + require.NoError(t, v.ReadConfig(bytes.NewBufferString(tomlData))) + require.NoError(t, v.Unmarshal(into)) + } + + t.Run("default is 1000", func(t *testing.T) { + require.Equal(t, 1000, DefaultBatchRequestMaxSize) + require.Equal(t, DefaultBatchRequestMaxSize, NewDefaultRPCClientConfig().BatchRequestMaxSize) + }) + + t.Run("existing TOML without the key still loads with 1000", func(t *testing.T) { + cfg := NewDefaultRPCClientConfig() + decode(t, ` +URL = "http://localhost:8545" +Mode = "basic" +HashFromJSON = true +BatchBlockHeaderRetrieval = true +`, cfg) + require.Equal(t, "http://localhost:8545", cfg.URL) + require.Equal(t, 1000, cfg.BatchRequestMaxSize) + require.NoError(t, cfg.Validate()) + }) + + t.Run("key in TOML is honoured", func(t *testing.T) { + cfg := NewDefaultRPCClientConfig() + decode(t, ` +URL = "http://localhost:8545" +BatchRequestMaxSize = 40 +`, cfg) + require.Equal(t, 40, cfg.BatchRequestMaxSize) + require.NoError(t, cfg.Validate()) + }) + + t.Run("zero is valid and means the default", func(t *testing.T) { + cfg := NewDefaultRPCClientConfig() + decode(t, ` +URL = "http://localhost:8545" +BatchRequestMaxSize = 0 +`, cfg) + require.Zero(t, cfg.BatchRequestMaxSize) + require.NoError(t, cfg.Validate()) + }) + + t.Run("negative is rejected", func(t *testing.T) { + cfg := NewDefaultRPCClientConfig() + decode(t, ` +URL = "http://localhost:8545" +BatchRequestMaxSize = -1 +`, cfg) + err := cfg.Validate() + require.ErrorIs(t, err, ErrInvalidBatchRequestMaxSize) + }) +} diff --git a/etherman/default_eth_client.go b/etherman/default_eth_client.go index 75c206ace..709f1d76d 100644 --- a/etherman/default_eth_client.go +++ b/etherman/default_eth_client.go @@ -28,6 +28,7 @@ type DefaultEthClient struct { HashFromJSON bool batchBlockHeaders bool logger aggkitcommon.Logger + batchSize *batchSizeLimiter } // DialWithRetry attempts to connect to an Ethereum client with retries and exponential backoff. @@ -86,6 +87,7 @@ func NewDefaultEthClientWithLogger( HashFromJSON: hashFromJSON, batchBlockHeaders: batchBlockHeaders, logger: logger, + batchSize: newBatchSizeLimiter(cfg.BatchRequestMaxSize), } } @@ -175,7 +177,7 @@ func (c *DefaultEthClient) RetrieveBlockHeaders( ctx context.Context, blockNumbers []uint64, maxConcurrency int, ) (*aggkittypes.BlockHeadersResult, error) { if c.batchBlockHeaders { - return RetrieveBlockHeadersBatch(ctx, c.logger, c.RPCClienter, blockNumbers, maxConcurrency) + return retrieveBlockHeadersBatchAdaptive(ctx, c.logger, c.RPCClienter, c.batchSize, blockNumbers, maxConcurrency) } return RetrieveBlockHeadersLegacy(ctx, c.logger, c, blockNumbers, maxConcurrency) } From 4cd28b61d604d3cfe198f9e0608da1bf65b00632 Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 17:48:41 +0000 Subject: [PATCH 3/8] fix(multidownloader): back off and throttle logs on step errors (#1889) Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- multidownloader/e2e_test.go | 222 +++++++++++++++++++- multidownloader/evm_multidownloader.go | 39 +++- multidownloader/evm_multidownloader_test.go | 151 +++++++++++++ 3 files changed, 409 insertions(+), 3 deletions(-) diff --git a/multidownloader/e2e_test.go b/multidownloader/e2e_test.go index 8904cc6d3..346d3778d 100644 --- a/multidownloader/e2e_test.go +++ b/multidownloader/e2e_test.go @@ -2,20 +2,26 @@ package multidownloader import ( "context" + "encoding/json" "errors" "fmt" "math/big" "math/rand" + "strconv" + "strings" "sync" "testing" "time" + aggkitcommon "github.com/agglayer/aggkit/common" configtypes "github.com/agglayer/aggkit/config/types" "github.com/agglayer/aggkit/etherman" + ethermanconfig "github.com/agglayer/aggkit/etherman/config" "github.com/agglayer/aggkit/log" "github.com/agglayer/aggkit/multidownloader/storage" mdsync "github.com/agglayer/aggkit/multidownloader/sync" mdrsynctypes "github.com/agglayer/aggkit/multidownloader/sync/types" + mdrtypes "github.com/agglayer/aggkit/multidownloader/types" aggkitsync "github.com/agglayer/aggkit/sync" "github.com/agglayer/aggkit/test/contracts/logemitter" aggkittypes "github.com/agglayer/aggkit/types" @@ -25,6 +31,7 @@ import ( "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/ethclient/simulated" "github.com/ethereum/go-ethereum/params" + "github.com/ethereum/go-ethereum/rpc" "github.com/stretchr/testify/require" ) @@ -217,6 +224,12 @@ func buildL1Simulated(t *testing.T) *mdrE2ESimulatedEnv { } func newMultidownloader(t *testing.T, testData *mdrE2ESimulatedEnv) *EVMMultidownloader { + t.Helper() + return newMultidownloaderWithFinality(t, testData, "LatestBlock/-5") +} + +func newMultidownloaderWithFinality(t *testing.T, testData *mdrE2ESimulatedEnv, + finality string) *EVMMultidownloader { t.Helper() cfg := NewConfigDefault("e2e_test", t.TempDir()) // This log logger will only log errors to avoid cluttering the test output @@ -231,7 +244,7 @@ func newMultidownloader(t *testing.T, testData *mdrE2ESimulatedEnv) *EVMMultidow DBPath: cfg.StoragePath, }) require.NoError(t, err) - simulatedFinalized, err := aggkittypes.NewBlockNumberFinality("LatestBlock/-5") + simulatedFinalized, err := aggkittypes.NewBlockNumberFinality(finality) require.NoError(t, err) _, err = testData.ethClient.CustomHeaderByNumber(t.Context(), simulatedFinalized) require.NoError(t, err) @@ -339,3 +352,210 @@ func TestE2E_CustomSyncer(t *testing.T) { } log.Info("Finish tests") } + +// batchLimitedRPCClient is an RPCClienter on top of the simulated backend (which has no batch support) +// that rejects JSON-RPC batches larger than maxBatch like a capped provider does. +type batchLimitedRPCClient struct { + env *mdrE2ESimulatedEnv + maxBatch int + rejectFn func() error + + mu sync.Mutex + calls []batchCall +} + +type batchCall struct { + size int + rejected bool +} + +func (c *batchLimitedRPCClient) Call(_ any, method string, _ ...any) error { + return fmt.Errorf("batchLimitedRPCClient: Call %s not supported", method) +} + +func (c *batchLimitedRPCClient) CallContext(_ context.Context, _ any, method string, _ ...any) error { + return fmt.Errorf("batchLimitedRPCClient: CallContext %s not supported", method) +} + +func (c *batchLimitedRPCClient) BatchCallContext(ctx context.Context, b []rpc.BatchElem) error { + rejected := len(b) > c.maxBatch + c.mu.Lock() + c.calls = append(c.calls, batchCall{size: len(b), rejected: rejected}) + c.mu.Unlock() + if rejected { + return c.rejectFn() + } + for i := range b { + if b[i].Method != "eth_getBlockByNumber" { + b[i].Error = fmt.Errorf("method %s not supported", b[i].Method) + continue + } + hexNum, ok := b[i].Args[0].(string) + if !ok { + b[i].Error = fmt.Errorf("unexpected block argument %v", b[i].Args[0]) + continue + } + num, err := strconv.ParseUint(strings.TrimPrefix(hexNum, "0x"), 16, 64) + if err != nil { + b[i].Error = err + continue + } + hdr, err := c.env.SimulatedL1.Client().HeaderByNumber(ctx, new(big.Int).SetUint64(num)) + if err != nil { + b[i].Error = err + continue + } + raw, err := json.Marshal(hdr) + if err != nil { + b[i].Error = err + continue + } + b[i].Error = json.Unmarshal(raw, b[i].Result) + } + return nil +} + +func (c *batchLimitedRPCClient) snapshot() []batchCall { + c.mu.Lock() + defer c.mu.Unlock() + return append([]batchCall(nil), c.calls...) +} + +func TestE2E_BatchLimitedProvider(t *testing.T) { + if testing.Short() { + t.Skip("skipping E2E test in short mode") + } + const ( + providerMaxBatch = 40 + numEvents = 130 + // the LogEmitter constructor emits one Ping too + totalEvents = numEvents + 1 + ) + tests := []struct { + name string + // rejectFn builds the error returned by the provider for an oversized batch + rejectFn func() error + // expectedRejectedSizes is the number of distinct rejected sizes expected (exact) + expectedRejectedSizes int + // maxSizeAfterFirstRejection is the largest batch the limiter may still send after the first rejection: + // the provider limit when it is parsed from the message, else half of the rejected size + maxSizeAfterFirstRejection int + }{ + { + name: "limit in the error message", + rejectFn: func() error { + return rpc.HTTPError{ + StatusCode: 400, + Status: "400 Bad Request", + Body: []byte("too many batch requests, max is 40"), + } + }, + expectedRejectedSizes: 1, + maxSizeAfterFirstRejection: providerMaxBatch, + }, + { + name: "limit not in the error message", + rejectFn: func() error { + return rpc.HTTPError{ + StatusCode: 400, + Status: "400 Bad Request", + Body: []byte("batch too large"), + } + }, + expectedRejectedSizes: 2, + maxSizeAfterFirstRejection: 65, // the first rejected batch has 129 headers: halved, rounded up + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + testData := buildL1Simulated(t) + limited := &batchLimitedRPCClient{env: testData, maxBatch: providerMaxBatch, rejectFn: tc.rejectFn} + rpcCfg := ethermanconfig.NewDefaultRPCClientConfig() + rpcCfg.HashFromJSON = false + rpcCfg.BatchBlockHeaderRetrieval = true + testData.ethClient = etherman.NewDefaultEthClient(testData.SimulatedL1.Client(), limited, rpcCfg) + + for i := 1; i <= numEvents; i++ { + _, err := testData.LogEmitterContract.EmitPing(testData.auth, big.NewInt(int64(i)), + fmt.Sprintf("iteration %d", i)) + require.NoError(t, err) + testData.SimulatedL1.Commit() + } + tip, err := testData.ethClient.BlockNumber(t.Context()) + require.NoError(t, err) + require.Greater(t, tip, uint64(2*providerMaxBatch)) + + mdr := newMultidownloaderWithFinality(t, testData, "LatestBlock/-3") + fastBackoff, err := aggkitcommon.NewExponentialBackoff(aggkitcommon.ExponentialBackoffConfig{ + Initial: time.Millisecond, Max: 5 * time.Millisecond, Factor: 2, Jitter: 0, + }) + require.NoError(t, err) + mdr.startStepBackoff = fastBackoff + require.NoError(t, mdr.RegisterSyncer(aggkittypes.SyncerConfig{ + SyncerID: "batch_limited_e2e", + ContractAddresses: []common.Address{testData.LogEmitterAddr}, + FromBlock: 0, + ToBlock: aggkittypes.LatestBlock, + })) + + ctx, cancel := context.WithTimeout(t.Context(), 90*time.Second) + defer cancel() + done := make(chan error, 1) + go func() { done <- mdr.Start(ctx) }() + + countLogs := func() int { + logs, err := mdr.storage.GetEthLogs(nil, mdrtypes.NewLogQuery(0, tip, + []common.Address{testData.LogEmitterAddr})) + if err != nil { + return -1 + } + return len(logs) + } + require.Eventually(t, func() bool { return countLogs() == totalEvents }, + 80*time.Second, 20*time.Millisecond, "sync did not converge to the tip") + highest, err := mdr.storage.GetHighestBlockNumber(nil) + require.NoError(t, err) + require.Equal(t, tip, highest) + + // the multidownloader keeps syncing: a new block is picked up after the limiter has shrunk + _, err = testData.LogEmitterContract.EmitPing(testData.auth, big.NewInt(numEvents+1), "extra") + require.NoError(t, err) + testData.SimulatedL1.Commit() + require.Eventually(t, func() bool { + logs, err := mdr.storage.GetEthLogs(nil, mdrtypes.NewLogQuery(0, tip+1, + []common.Address{testData.LogEmitterAddr})) + return err == nil && len(logs) == totalEvents+1 + }, 30*time.Second, 20*time.Millisecond, "sync stopped after the limit was discovered") + + cancel() + select { + case startErr := <-done: + require.True(t, startErr == nil || errors.Is(startErr, context.Canceled), "Start: %v", startErr) + case <-time.After(10 * time.Second): + require.FailNow(t, "Start did not return after cancel") + } + + calls := limited.snapshot() + rejectedSizes := map[int]struct{}{} + firstRejection := -1 + for i, call := range calls { + if call.rejected { + rejectedSizes[call.size] = struct{}{} + if firstRejection < 0 { + firstRejection = i + } + } + } + require.GreaterOrEqual(t, firstRejection, 0, "the provider limit was never hit; calls=%v", calls) + require.Len(t, rejectedSizes, tc.expectedRejectedSizes, "rejected sizes=%v calls=%v", rejectedSizes, calls) + require.LessOrEqual(t, len(rejectedSizes), 6, "too many distinct rejected sizes: %v", rejectedSizes) + for i, call := range calls[firstRejection+1:] { + require.LessOrEqual(t, call.size, tc.maxSizeAfterFirstRejection, + "batch of %d sent after the first rejection (call %d); calls=%v", call.size, i, calls) + if !call.rejected { + require.LessOrEqual(t, call.size, providerMaxBatch) + } + } + }) + } +} diff --git a/multidownloader/evm_multidownloader.go b/multidownloader/evm_multidownloader.go index ead9acc78..9d51a51c5 100644 --- a/multidownloader/evm_multidownloader.go +++ b/multidownloader/evm_multidownloader.go @@ -32,6 +32,15 @@ const ( minChunkSize = 1 ) +// Back-off and log throttling applied by Start when StartStep fails with a non-reorg error. +const ( + startStepRetryInitialBackoff = 100 * time.Millisecond + startStepRetryMaxBackoff = 10 * time.Second + startStepRetryBackoffFactor = 2.0 + startStepRetryBackoffJitter = 0.2 + startStepErrorLogWindow = time.Minute +) + type EVMMultidownloader struct { log aggkitcommon.Logger cfg Config @@ -53,6 +62,10 @@ type EVMMultidownloader struct { wg sync.WaitGroup cancel context.CancelFunc + // Retry policy of the Start loop on non-reorg errors (only used from the Start goroutine) + startStepBackoff *aggkitcommon.ExponentialBackoff + startStepErrLogger *aggkitcommon.RepeatedErrorLogger + // Debug fields debug *EVMMultidownloaderDebug } @@ -102,6 +115,19 @@ func NewEVMMultidownloader(log aggkitcommon.Logger, debug = NewEVMMultidownloaderDebug() } + startStepBackoff, err := aggkitcommon.NewExponentialBackoff(aggkitcommon.ExponentialBackoffConfig{ + Initial: startStepRetryInitialBackoff, + Max: startStepRetryMaxBackoff, + Factor: startStepRetryBackoffFactor, + Jitter: startStepRetryBackoffJitter, + }) + if err != nil { + return nil, fmt.Errorf("NewEVMMultidownloader: cannot create step retry back-off: %w", err) + } + startStepErrLogger := aggkitcommon.NewRepeatedErrorLogger(log, + fmt.Sprintf("EVMMultidownloader(%s).Start: error running multidownloader step", name), + startStepErrorLogWindow) + return &EVMMultidownloader{ log: log, ethClient: ethClient, @@ -114,6 +140,8 @@ func NewEVMMultidownloader(log aggkitcommon.Logger, name: name, reorgProcessor: reorgProcessor, debug: debug, + startStepBackoff: startStepBackoff, + startStepErrLogger: startStepErrLogger, }, nil } @@ -266,8 +294,12 @@ func (dh *EVMMultidownloader) startNumLoops(ctx context.Context, numLoopsToExecu if err != nil { reorgErr := mdrtypes.CastDetectedReorgError(err) if reorgErr == nil { - dh.log.Warnf("Error running multidownloader: %s ", err.Error()) - time.Sleep(time.Millisecond) // Brief pause before retry + if runCtx.Err() != nil { + continue // the loop top returns; no Warn on shutdown + } + dh.startStepErrLogger.Log(err) + // A sleep error means the context is done: the loop top returns. + _, _ = dh.startStepBackoff.Sleep(runCtx) continue } dh.log.Warnf("Reorg detected: %s", reorgErr.Error()) @@ -299,6 +331,9 @@ func (dh *EVMMultidownloader) startNumLoops(ctx context.Context, numLoopsToExecu dh.mutex.Unlock() break } + } else { + dh.startStepBackoff.Reset() + dh.startStepErrLogger.Reset() } } } diff --git a/multidownloader/evm_multidownloader_test.go b/multidownloader/evm_multidownloader_test.go index 1181033a5..77e200487 100644 --- a/multidownloader/evm_multidownloader_test.go +++ b/multidownloader/evm_multidownloader_test.go @@ -14,6 +14,7 @@ import ( "github.com/agglayer/aggkit/config/types" "github.com/agglayer/aggkit/db" dbmocks "github.com/agglayer/aggkit/db/mocks" + dbtypes "github.com/agglayer/aggkit/db/types" "github.com/agglayer/aggkit/etherman" mockethermantypes "github.com/agglayer/aggkit/etherman/types/mocks" "github.com/agglayer/aggkit/log" @@ -1770,3 +1771,153 @@ func TestEVMMultidownloader_waitForNewBlocks(t *testing.T) { require.Equal(t, uint64(101), blockNumber) }) } + +// stepRetryCaptureLogger records the number of Warn and Debug calls (thread-safe). +type stepRetryCaptureLogger struct { + mu sync.Mutex + warns []string + debug int +} + +func (c *stepRetryCaptureLogger) Panicf(string, ...interface{}) {} +func (c *stepRetryCaptureLogger) Fatalf(string, ...interface{}) {} +func (c *stepRetryCaptureLogger) Info(...interface{}) {} +func (c *stepRetryCaptureLogger) Infof(string, ...interface{}) {} +func (c *stepRetryCaptureLogger) Error(...interface{}) {} +func (c *stepRetryCaptureLogger) Errorf(string, ...interface{}) {} +func (c *stepRetryCaptureLogger) Warn(args ...interface{}) { + c.addWarn(fmt.Sprint(args...)) +} +func (c *stepRetryCaptureLogger) Warnf(f string, a ...interface{}) { + c.addWarn(fmt.Sprintf(f, a...)) +} +func (c *stepRetryCaptureLogger) Debug(...interface{}) { c.addDebug() } +func (c *stepRetryCaptureLogger) Debugf(string, ...interface{}) { c.addDebug() } +func (c *stepRetryCaptureLogger) addWarn(s string) { + c.mu.Lock() + defer c.mu.Unlock() + c.warns = append(c.warns, s) +} +func (c *stepRetryCaptureLogger) addDebug() { + c.mu.Lock() + defer c.mu.Unlock() + c.debug++ +} +func (c *stepRetryCaptureLogger) warnCount() int { + c.mu.Lock() + defer c.mu.Unlock() + return len(c.warns) +} + +// setupStepRetryTest makes StartStep fail (non-reorg error) or succeed following script, one entry per +// StartStep call (true = success). Backoff sleeps are recorded instead of waited and jitter is zero. +func setupStepRetryTest(t *testing.T, script []bool) (*testDataEVMMultidownloader, *stepRetryCaptureLogger, *[]time.Duration) { + t.Helper() + data := newEVMMultidownloaderTestData(t, true) + data.FakeInitialized(t) + data.mdr.cfg.PeriodToCheckReorgs = types.NewDuration(time.Millisecond) + + captured := &stepRetryCaptureLogger{} + data.mdr.log = captured + clock := time.Unix(1000, 0) + data.mdr.startStepErrLogger = aggkitcommon.NewRepeatedErrorLogger(captured, "step", startStepErrorLogWindow). + WithClock(func() time.Time { + clock = clock.Add(20 * time.Second) + return clock + }) + delays := &[]time.Duration{} + backoff, err := aggkitcommon.NewExponentialBackoff(aggkitcommon.ExponentialBackoffConfig{ + Initial: startStepRetryInitialBackoff, + Max: startStepRetryMaxBackoff, + Factor: startStepRetryBackoffFactor, + Jitter: startStepRetryBackoffJitter, + }, + aggkitcommon.WithBackoffRandFloat(func() float64 { return 0.5 }), + aggkitcommon.WithBackoffSleeper(func(_ context.Context, d time.Duration) error { + *delays = append(*delays, d) + return nil + })) + require.NoError(t, err) + data.mdr.startStepBackoff = backoff + + data.mockBlockNotifierManager.EXPECT().GetCurrentBlockNumber(mock.Anything, mock.Anything). + Return(uint64(100), nil).Maybe() + data.mockStorage.EXPECT().GetBlockHeadersNotFinalized(mock.Anything, mock.Anything). + Return(aggkittypes.ListBlockHeaders{}, nil).Maybe() + data.mockStorage.EXPECT().GetBlockHeaderByNumber(mock.Anything, mock.Anything). + Return(nil, mdrtypes.Finalized, nil).Maybe() + mockTx := dbmocks.NewTxer(t) + mockTx.EXPECT().Rollback().Return(nil).Maybe() + mockTx.EXPECT().Commit().Return(nil).Maybe() + call := 0 + data.mockStorage.EXPECT().NewTx(mock.Anything).RunAndReturn(func(context.Context) (dbtypes.Txer, error) { + ok := script[call] + call++ + if ok { + return mockTx, nil + } + return nil, fmt.Errorf("persistent step failure") + }).Maybe() + return data, captured, delays +} + +func TestEVMMultidownloader_Start_StepErrorBackoff(t *testing.T) { + t.Run("delays grow by 2 from 100ms, cap at 10s, reset after a success, warns are bounded", func(t *testing.T) { + script := []bool{false, false, false, false, false, false, false, false, false, true, false} + data, captured, delays := setupStepRetryTest(t, script) + + require.NoError(t, data.mdr.startNumLoops(context.Background(), len(script))) + + require.Equal(t, []time.Duration{ + 100 * time.Millisecond, 200 * time.Millisecond, 400 * time.Millisecond, 800 * time.Millisecond, + 1600 * time.Millisecond, 3200 * time.Millisecond, 6400 * time.Millisecond, + 10 * time.Second, 10 * time.Second, + 100 * time.Millisecond, // after the success the back-off restarts + }, *delays) + // 9 identical errors, one every 20 s of fake time, window 1 min: Warn at t=0, 60 s and 120 s + // (the success then emits one summary Warn for the suppressed repeats and resets the logger so the + // last error warns again) + require.Equal(t, 5, captured.warnCount()) + }) + + t.Run("context cancelled during the sleep returns promptly", func(t *testing.T) { + data, captured, _ := setupStepRetryTest(t, []bool{false, false, false}) + longBackoff, err := aggkitcommon.NewExponentialBackoff(aggkitcommon.ExponentialBackoffConfig{ + Initial: time.Hour, Max: time.Hour, Factor: 2, Jitter: 0, + }) + require.NoError(t, err) + data.mdr.startStepBackoff = longBackoff + + done := make(chan error, 1) + go func() { done <- data.mdr.Start(context.Background()) }() + require.Eventually(t, func() bool { return captured.warnCount() == 1 }, 5*time.Second, time.Millisecond) + + require.NoError(t, data.mdr.Stop(context.Background())) + select { + case startErr := <-done: + require.ErrorIs(t, startErr, context.Canceled) + case <-time.After(5 * time.Second): + require.FailNow(t, "Start did not return after cancellation during the back-off sleep") + } + require.Equal(t, 1, captured.warnCount(), "shutdown must not produce extra Warn") + }) + + t.Run("shutdown during a failing step produces no Warn", func(t *testing.T) { + data := newEVMMultidownloaderTestData(t, true) + data.FakeInitialized(t) + captured := &stepRetryCaptureLogger{} + data.mdr.log = captured + data.mdr.startStepErrLogger = aggkitcommon.NewRepeatedErrorLogger(captured, "step", startStepErrorLogWindow) + data.mockBlockNotifierManager.EXPECT().GetCurrentBlockNumber(mock.Anything, mock.Anything). + Return(uint64(100), nil).Maybe() + ctx, cancel := context.WithCancel(context.Background()) + data.mockStorage.EXPECT().NewTx(mock.Anything).RunAndReturn(func(context.Context) (dbtypes.Txer, error) { + cancel() + return nil, fmt.Errorf("step failure caused by shutdown") + }).Once() + + err := data.mdr.Start(ctx) + require.ErrorIs(t, err, context.Canceled) + require.Equal(t, 0, captured.warnCount()) + }) +} From c8450775d602c3e7203b9b401911907610b857c4 Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 18:01:18 +0000 Subject: [PATCH 4/8] fix(autoclaim): isolate failing destinations with per-destination back-off (#1889) Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- .github/workflows/test-go-e2e.yml | 2 +- .../bridgedetector/destination_backoff.go | 107 +++++ .../destination_backoff_test.go | 302 +++++++++++++ autoclaim/bridgedetector/l1_to_l2.go | 152 +++++-- autoclaim/bridgedetector/l1_to_l2_test.go | 172 +++++++- autoclaim/bridgedetector/l2_to_lx.go | 252 +++++++++-- autoclaim/bridgedetector/l2_to_lx_test.go | 406 ++++++++++++++++++ autoclaim/metrics/metrics.go | 82 ++++ autoclaim/metrics/metrics_test.go | 70 +++ autoclaim/runtime/runtime.go | 2 + test/e2e/autoclaim_test.go | 269 ++++++++++++ 11 files changed, 1742 insertions(+), 74 deletions(-) create mode 100644 autoclaim/bridgedetector/destination_backoff.go create mode 100644 autoclaim/bridgedetector/destination_backoff_test.go create mode 100644 autoclaim/metrics/metrics.go create mode 100644 autoclaim/metrics/metrics_test.go diff --git a/.github/workflows/test-go-e2e.yml b/.github/workflows/test-go-e2e.yml index 02e64aa8e..d72610ee9 100644 --- a/.github/workflows/test-go-e2e.yml +++ b/.github/workflows/test-go-e2e.yml @@ -75,7 +75,7 @@ jobs: # a primary failure cascade into otherwise unrelated bridge tests. - env: anvil-2chains group: autoclaim - run: "^(TestAutoClaimL1ToL2AllowAll|TestAutoClaimL1ToL2APIApprove|TestAutoClaimL1ToL2BasicFilter|TestAutoClaimL2ToL1AllowAll|TestAutoClaimL2ToL2AllowAll)$" + run: "^(TestAutoClaimL1ToL2AllowAll|TestAutoClaimL1ToL2APIApprove|TestAutoClaimL1ToL2BasicFilter|TestAutoClaimL2ToL1AllowAll|TestAutoClaimL2ToL2AllowAll|TestAutoClaimL1ToL2FailingDestinationIsolated)$" - env: anvil-2chains group: bridge run: "^(TestJustBridge|TestBridgeL2ToL2|TestBridgeTrackerL1ToL2)$" diff --git a/autoclaim/bridgedetector/destination_backoff.go b/autoclaim/bridgedetector/destination_backoff.go new file mode 100644 index 000000000..e48e7de65 --- /dev/null +++ b/autoclaim/bridgedetector/destination_backoff.go @@ -0,0 +1,107 @@ +package bridgedetector + +import ( + "time" + + aggkitcommon "github.com/agglayer/aggkit/common" +) + +const ( + destinationBackoffFactor = 2.0 + destinationBackoffMax = 2 * time.Minute + destinationBackoffJitter = 0.2 +) + +// destinationBackoff tracks, per destination network, a capped exponential back-off so that a failing +// destination is retried after a growing pause instead of on every poll. The first window equals the +// initial delay (the detector poll period) and doubles up to the max; a success resets it. +// +// The window is purely computed from the number of consecutive failures: a server-provided Retry-After +// hint is NOT honoured, because go-ethereum's rpc.HTTPError does not expose the response headers. +// +// It is not goroutine-safe: each detector owns one instance and only touches it from its poll goroutine. +// The type is shared by the L1-to-L2 and L2-to-Lx detectors; the instances are not. +type destinationBackoff struct { + initial, max time.Duration + jitter float64 + randFloat func() float64 // nil = default + entries map[uint32]*destinationBackoffEntry +} + +type destinationBackoffEntry struct { + backoff *aggkitcommon.ExponentialBackoff + until time.Time + lastErr error +} + +// newDestinationBackoff creates a tracker whose first window is initial, grows by destinationBackoffFactor +// and is capped at maxWindow, with the given symmetric relative jitter. Out-of-range arguments are sanitised +// (initial <= 0 becomes one second, maxWindow < initial becomes initial, jitter outside [0, 1) becomes 0). +func newDestinationBackoff(initial, maxWindow time.Duration, jitter float64) *destinationBackoff { + if initial <= 0 { + initial = time.Second + } + if maxWindow < initial { + maxWindow = initial + } + if jitter < 0 || jitter >= 1 { + jitter = 0 + } + return &destinationBackoff{ + initial: initial, + max: maxWindow, + jitter: jitter, + entries: make(map[uint32]*destinationBackoffEntry), + } +} + +// shouldSkip reports whether dest is inside its back-off window at now. +func (b *destinationBackoff) shouldSkip(dest uint32, now time.Time) bool { + entry, ok := b.entries[dest] + return ok && now.Before(entry.until) +} + +// skipUntil returns the end of dest's current window (zero if none), for the Debug log. +func (b *destinationBackoff) skipUntil(dest uint32) time.Time { + if entry, ok := b.entries[dest]; ok { + return entry.until + } + return time.Time{} +} + +// recordFailure opens the next window: window = entry.backoff.Next(); until = now + window. +// It returns the window and the number of consecutive failures (the attempt) recorded for dest. +func (b *destinationBackoff) recordFailure( + dest uint32, err error, now time.Time, +) (window time.Duration, attempt int) { + entry, ok := b.entries[dest] + if !ok { + var opts []aggkitcommon.ExponentialBackoffOption + if b.randFloat != nil { + opts = append(opts, aggkitcommon.WithBackoffRandFloat(b.randFloat)) + } + // The configuration is sanitised by newDestinationBackoff, so it is always valid. + backoff, _ := aggkitcommon.NewExponentialBackoff(aggkitcommon.ExponentialBackoffConfig{ + Initial: b.initial, + Max: b.max, + Factor: destinationBackoffFactor, + Jitter: b.jitter, + }, opts...) + entry = &destinationBackoffEntry{backoff: backoff} + b.entries[dest] = entry + } + window = entry.backoff.Next() + entry.until = now.Add(window) + entry.lastErr = err + return window, entry.backoff.Attempts() +} + +// recordSuccess deletes dest's entry (full reset). +func (b *destinationBackoff) recordSuccess(dest uint32) { + delete(b.entries, dest) +} + +// stalledCount returns the number of destinations with an entry (failing and not yet recovered). +func (b *destinationBackoff) stalledCount() int { + return len(b.entries) +} diff --git a/autoclaim/bridgedetector/destination_backoff_test.go b/autoclaim/bridgedetector/destination_backoff_test.go new file mode 100644 index 000000000..35f084959 --- /dev/null +++ b/autoclaim/bridgedetector/destination_backoff_test.go @@ -0,0 +1,302 @@ +package bridgedetector + +import ( + "context" + "errors" + "fmt" + "net/http" + "strings" + "testing" + "time" + + autoclaimmetrics "github.com/agglayer/aggkit/autoclaim/metrics" + autoclaimtypes "github.com/agglayer/aggkit/autoclaim/types" + "github.com/agglayer/aggkit/bridgesync" + "github.com/agglayer/aggkit/prometheus" + "github.com/ethereum/go-ethereum/rpc" + "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/stretchr/testify/require" +) + +// capturingLogger records formatted Warn and Debug lines; other levels are discarded. +type capturingLogger struct { + warns []string + debugs []string +} + +func (l *capturingLogger) Panicf(string, ...interface{}) {} +func (l *capturingLogger) Fatalf(string, ...interface{}) {} +func (l *capturingLogger) Info(...interface{}) {} +func (l *capturingLogger) Infof(string, ...interface{}) {} +func (l *capturingLogger) Error(...interface{}) {} +func (l *capturingLogger) Errorf(string, ...interface{}) {} +func (l *capturingLogger) Warn(args ...interface{}) { l.warns = append(l.warns, fmt.Sprint(args...)) } +func (l *capturingLogger) Warnf(format string, args ...interface{}) { + l.warns = append(l.warns, fmt.Sprintf(format, args...)) +} +func (l *capturingLogger) Debug(args ...interface{}) { + l.debugs = append(l.debugs, fmt.Sprint(args...)) +} +func (l *capturingLogger) Debugf(format string, args ...interface{}) { + l.debugs = append(l.debugs, fmt.Sprintf(format, args...)) +} + +func TestDestinationBackoff_Curve(t *testing.T) { + b := newDestinationBackoff(time.Second, 2*time.Minute, 0) + now := testNow + failure := errors.New("boom") + + require.False(t, b.shouldSkip(7, now)) + require.True(t, b.skipUntil(7).IsZero()) + + expected := []time.Duration{ + time.Second, 2 * time.Second, 4 * time.Second, 8 * time.Second, 16 * time.Second, + 32 * time.Second, 64 * time.Second, 2 * time.Minute, 2 * time.Minute, + } + for i, want := range expected { + window, attempt := b.recordFailure(7, failure, now) + require.Equal(t, want, window) + require.Equal(t, i+1, attempt) + require.Equal(t, now.Add(want), b.skipUntil(7)) + require.True(t, b.shouldSkip(7, now)) + require.True(t, b.shouldSkip(7, now.Add(want-time.Nanosecond))) + require.False(t, b.shouldSkip(7, now.Add(want))) + } + require.Equal(t, 1, b.stalledCount()) + + b.recordSuccess(7) + require.Equal(t, 0, b.stalledCount()) + window, attempt := b.recordFailure(7, failure, now) + require.Equal(t, time.Second, window) + require.Equal(t, 1, attempt) +} + +func TestDestinationBackoff_Sanitises(t *testing.T) { + b := newDestinationBackoff(5*time.Minute, time.Minute, 2) + window, _ := b.recordFailure(1, errors.New("x"), testNow) + require.Equal(t, 5*time.Minute, window) +} + +func TestNewL1ToL2_PollPeriodDrivesInitialBackoff(t *testing.T) { + failing := &fakeClaimer{ + target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer10ID, DestinationNetwork: 10}, + claimErr: errors.New("boom"), + } + source := &fakeBridgeSource{ + lastProcessedBlock: 10, + found: true, + bridgesByRange: map[blockRange][]bridgesync.Bridge{ + {from: 0, to: 10}: {makeSyncBridge(1, autoclaimtypes.L1OriginNetwork, 10, 1, 0)}, + }, + } + detector := newTestDetector(t, source, newMemoryCursorStore(), newFakeRegistry(failing), + WithBlockWindow(11), WithPollPeriod(5*time.Second)) + + _, err := detector.PollOnce(context.Background()) + require.Error(t, err) + // Default construction: initial = poll period, jitter +-20%. + window := detector.backoff.skipUntil(10).Sub(testNow) + require.GreaterOrEqual(t, window, 4*time.Second) + require.LessOrEqual(t, window, 6*time.Second) + require.Equal(t, 5*time.Second, detector.backoff.initial) +} + +type backoffFixture struct { + detector *L1ToL2 + failing *fakeClaimer + healthyY *fakeClaimer + healthyZ *fakeClaimer + log *capturingLogger + clock *time.Time +} + +func newBackoffFixture(t *testing.T, failure error) *backoffFixture { + t.Helper() + bridges := []bridgesync.Bridge{ + makeSyncBridge(1, autoclaimtypes.L1OriginNetwork, 10, 2, 0), + makeSyncBridge(2, autoclaimtypes.L1OriginNetwork, 11, 3, 0), + makeSyncBridge(3, autoclaimtypes.L1OriginNetwork, 12, 4, 0), + } + source := &fakeBridgeSource{ + lastProcessedBlock: 10, + found: true, + bridgesByRange: map[blockRange][]bridgesync.Bridge{{from: 1, to: 10}: bridges}, + } + f := &backoffFixture{ + failing: &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer10ID, DestinationNetwork: 10}, claimErr: failure}, + healthyY: &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer11ID, DestinationNetwork: 11}}, + healthyZ: &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: "claimer-12", DestinationNetwork: 12}}, + log: &capturingLogger{}, + } + clock := testNow + f.clock = &clock + store := newMemoryCursorStore() + f.detector = newTestDetector(t, source, store, newFakeRegistry(f.failing, f.healthyY, f.healthyZ), + WithStartBlock(0), WithBlockWindow(10), WithOverlapBlocks(0), WithLogger(f.log), + WithNow(func() time.Time { return *f.clock })) + f.detector.backoff = newDestinationBackoff(time.Second, 2*time.Minute, 0) + seeded := autoclaimtypes.BridgeCursor{FromBlock: 0, ToBlock: 0, BlockNum: 0} + for _, dest := range []uint32{10, 11, 12} { + store.cursors[f.detector.cursorNameForDestination(dest)] = seeded + } + return f +} + +func TestL1ToL2_BackoffSkipsFailingDestination(t *testing.T) { + ctx := context.Background() + f := newBackoffFixture(t, errors.New("boom")) + + result, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Equal(t, []uint32{10}, result.FailedDestinations) + require.Empty(t, result.BackedOffDestinations) + require.Len(t, f.failing.claimChecks, 1) + require.Len(t, f.log.warns, 1) + + // Same clock: destination 10 is skipped, the others are unaffected. + result, err = f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Equal(t, []uint32{10}, result.BackedOffDestinations) + require.Empty(t, result.FailedDestinations) + require.Len(t, f.failing.claimChecks, 1, "no IsClaimed call while backed off") + require.Len(t, f.healthyY.claimChecks, 1, "healthy destination is not re-evaluated once its cursor advanced") + require.Len(t, f.log.warns, 1) + require.Len(t, f.log.debugs, 1) + require.Contains(t, f.log.debugs[0], "skipping destination 10, backed off until") + + // Just before the window ends it is still skipped; at the end it is retried. + *f.clock = testNow.Add(time.Second - time.Nanosecond) + result, err = f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Equal(t, []uint32{10}, result.BackedOffDestinations) + + *f.clock = testNow.Add(time.Second) + result, err = f.detector.PollOnce(ctx) + require.Error(t, err) + require.Empty(t, result.BackedOffDestinations) + require.Equal(t, []uint32{10}, result.FailedDestinations) + require.Len(t, f.failing.claimChecks, 2) + require.Len(t, f.log.warns, 2) +} + +func TestL1ToL2_BackoffWindowsGrowAndWarnOncePerWindow(t *testing.T) { + ctx := context.Background() + f := newBackoffFixture(t, errors.New("boom")) + + windows := []time.Duration{time.Second, 2 * time.Second, 4 * time.Second, 8 * time.Second} + for i, window := range windows { + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Len(t, f.log.warns, i+1) + require.Contains(t, f.log.warns[i], "paused for "+window.String()) + require.Contains(t, f.log.warns[i], fmt.Sprintf("after error (attempt %d)", i+1)) + require.Equal(t, f.clock.Add(window), f.detector.backoff.skipUntil(10)) + + // Several polls inside the window add no Warn. + for range 3 { + result, err := f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Equal(t, []uint32{10}, result.BackedOffDestinations) + } + require.Len(t, f.log.warns, i+1) + *f.clock = f.clock.Add(window) + } +} + +func TestL1ToL2_BackoffSuccessResets(t *testing.T) { + ctx := context.Background() + f := newBackoffFixture(t, errors.New("boom")) + + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + *f.clock = f.clock.Add(time.Second) + _, err = f.detector.PollOnce(ctx) + require.Error(t, err) + require.Equal(t, 1, f.detector.backoff.stalledCount()) + + f.failing.claimErr = nil + *f.clock = f.clock.Add(2 * time.Second) + result, err := f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Empty(t, result.FailedDestinations) + require.Equal(t, 0, f.detector.backoff.stalledCount()) + require.Len(t, f.log.warns, 2) + + // A new failure starts again from the initial window. + f.failing.claimErr = errors.New("boom again") + f.detector.backoff.recordFailure(11, nil, *f.clock) // unrelated entry must not matter + f.detector.backoff.recordSuccess(11) + window, attempt := f.detector.backoff.recordFailure(10, f.failing.claimErr, *f.clock) + require.Equal(t, time.Second, window) + require.Equal(t, 1, attempt) +} + +func TestL1ToL2_BackoffRateLimitedUsesHTTP429Wording(t *testing.T) { + ctx := context.Background() + f := newBackoffFixture(t, rpc.HTTPError{StatusCode: http.StatusTooManyRequests, Status: "429 Too Many Requests"}) + + for i, window := range []time.Duration{time.Second, 2 * time.Second, 4 * time.Second} { + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Len(t, f.log.warns, i+1) + require.Contains(t, f.log.warns[i], "paused for "+window.String()) + require.Contains(t, f.log.warns[i], fmt.Sprintf("after rate limiting (HTTP 429, attempt %d)", i+1)) + *f.clock = f.clock.Add(window) + } +} + +func TestL1ToL2_BackoffOtherHTTPErrorUsesGenericWording(t *testing.T) { + ctx := context.Background() + f := newBackoffFixture(t, rpc.HTTPError{StatusCode: http.StatusInternalServerError, Status: "500"}) + + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Len(t, f.log.warns, 1) + require.True(t, strings.Contains(f.log.warns[0], "paused for 1s after error (attempt 1)")) +} + +func TestL1ToL2_BackoffNotUpdatedWhenContextCancelled(t *testing.T) { + f := newBackoffFixture(t, errors.New("boom")) + ctx, cancel := context.WithCancel(context.Background()) + f.failing.claimErr = errors.New("boom") + cancel() + + result, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Equal(t, []uint32{10}, result.FailedDestinations) + require.Equal(t, 0, f.detector.backoff.stalledCount()) + require.Empty(t, f.log.warns) +} + +func TestL1ToL2_BackoffMetrics(t *testing.T) { + prometheus.Init() + autoclaimmetrics.Register() + ctx := context.Background() + f := newBackoffFixture(t, errors.New("boom")) + + gauge, ok := prometheus.Gauge("l1_to_l2_stalled_destinations") // the wrapper keys series by bare name + require.True(t, ok) + vec, ok := prometheus.CounterVec("detector_destination_errors_total") + require.True(t, ok) + errCounter := vec.WithLabelValues(string(autoclaimmetrics.DetectorL1ToL2), "10") + before := testutil.ToFloat64(errCounter) + + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Equal(t, 1.0, testutil.ToFloat64(gauge)) + require.Equal(t, before+1, testutil.ToFloat64(errCounter)) + + // Polls inside the window neither add errors nor change the gauge. + _, err = f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Equal(t, 1.0, testutil.ToFloat64(gauge)) + require.Equal(t, before+1, testutil.ToFloat64(errCounter)) + + // Recovery brings the gauge back to 0. + f.failing.claimErr = nil + *f.clock = f.clock.Add(time.Second) + _, err = f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Equal(t, 0.0, testutil.ToFloat64(gauge)) + require.Equal(t, before+1, testutil.ToFloat64(errCounter)) +} diff --git a/autoclaim/bridgedetector/l1_to_l2.go b/autoclaim/bridgedetector/l1_to_l2.go index 9b3ebe5cb..db26424b4 100644 --- a/autoclaim/bridgedetector/l1_to_l2.go +++ b/autoclaim/bridgedetector/l1_to_l2.go @@ -2,12 +2,16 @@ package bridgedetector import ( "context" + "errors" "fmt" + "net/http" "sort" "time" + "github.com/agglayer/aggkit/autoclaim/metrics" autoclaimtypes "github.com/agglayer/aggkit/autoclaim/types" aggkitcommon "github.com/agglayer/aggkit/common" + "github.com/ethereum/go-ethereum/rpc" ) const ( @@ -110,7 +114,16 @@ type PollResult struct { EnqueuedBridgeCount int IgnoredBridgeCount int SkippedBridgeCount int - CursorAdvanced bool + // DeferredBridgeCount counts bridges of a destination that failed earlier in this poll: they were + // not evaluated and will be re-evaluated on the next poll. + DeferredBridgeCount int + // FailedDestinations lists, in ascending order, the destinations whose IsClaimed or Enqueue failed + // this poll. + FailedDestinations []uint32 + // BackedOffDestinations lists, in ascending order, the destinations excluded from this poll because + // they are inside a back-off window after earlier failures. + BackedOffDestinations []uint32 + CursorAdvanced bool } // L1ToL2 is the bridge detector that discovers L1-initiated bridge exits and routes them to destination claimers. @@ -127,6 +140,7 @@ type L1ToL2 struct { etrogL1UpgradeBlock uint64 now func() time.Time log aggkitcommon.Logger + backoff *destinationBackoff } type destinationCursorState struct { @@ -136,6 +150,8 @@ type destinationCursorState struct { cursorFound bool fromBlock uint64 nextCursor autoclaimtypes.BridgeCursor + // err is the first IsClaimed/Enqueue failure for this destination in the current poll (nil = healthy). + err error } // NewL1ToL2 creates an L1-to-L2 Auto Claim bridge detector. @@ -172,6 +188,7 @@ func NewL1ToL2( for _, option := range options { option(detector) } + detector.backoff = newDestinationBackoff(detector.pollPeriod, destinationBackoffMax, destinationBackoffJitter) return detector, nil } @@ -208,6 +225,12 @@ func (w *L1ToL2) Start(ctx context.Context) { // cursor does not roll back or gate a different group's already-persisted cursor. A single map[RequestKey] // deduplication set spans the whole poll (not per group), which stays correct because every RequestKey // embeds its destination and each destination belongs to exactly one group. +// +// Failures are isolated per destination: when IsClaimed or Enqueue fails for a destination, that +// destination's remaining bridges in the window are deferred (not evaluated, not marked seen) and its +// cursor is not saved, so the next poll re-evaluates them from the persisted cursor. The other +// destinations of the same group keep processing and persist their cursors. All errors are returned +// joined, and PollResult.FailedDestinations lists the failed destinations. func (w *L1ToL2) PollOnce(ctx context.Context) (*PollResult, error) { if !w.enabled { return &PollResult{}, nil @@ -221,11 +244,14 @@ func (w *L1ToL2) PollOnce(ctx context.Context) (*PollResult, error) { return &PollResult{}, nil } - states, err := w.destinationCursorStates(ctx, lastProcessedBlock) + states, backedOff, err := w.destinationCursorStates(ctx, lastProcessedBlock) if err != nil { return nil, err } - result := &PollResult{LastProcessedBlock: lastProcessedBlock} + result := &PollResult{LastProcessedBlock: lastProcessedBlock, BackedOffDestinations: backedOff} + // queried holds the destinations of the groups whose GetBridges succeeded. + queried := make(map[uint32]*destinationCursorState) + defer func() { w.updateBackoff(ctx, states, queried) }() if len(states) == 0 { return result, nil } @@ -233,7 +259,7 @@ func (w *L1ToL2) PollOnce(ctx context.Context) (*PollResult, error) { groups := groupStatesByFromBlock(states) seen := make(map[autoclaimtypes.RequestKey]struct{}) - var firstErr error + var errs []error firstWindow := true for _, fromBlock := range orderedFromBlocks(groups) { // A fromBlock beyond lastProcessedBlock means that group's destination(s) are already @@ -261,12 +287,13 @@ func (w *L1ToL2) PollOnce(ctx context.Context) (*PollResult, error) { bridges, err := w.bridgeSource.GetBridges(ctx, fromBlock, toBlock) if err != nil { - if firstErr == nil { - firstErr = fmt.Errorf("get l1 bridges from %d to %d: %w", fromBlock, toBlock, err) - } + errs = append(errs, fmt.Errorf("get l1 bridges from %d to %d: %w", fromBlock, toBlock, err)) continue } result.BridgeCount += len(bridges) + for destination, state := range groupStates { + queried[destination] = state + } // Every bridge exit returned by l1bridgesync was initiated on L1, so there is no // bridge-origin filter to apply here. The claim identity (and the request key) is keyed on @@ -274,30 +301,25 @@ func (w *L1ToL2) PollOnce(ctx context.Context) (*PollResult, error) { // exit.OriginNetwork (the bridged token's origin network, which can be any network for a // wrapped token). A bridge whose destination is not part of this group (e.g. its window // overlaps another group's) is ignored here and left for the group that owns it. - groupFailed := false for _, bridge := range bridges { exit := autoclaimtypes.NewBridgeExitFromSyncWithEtrog(bridge, w.etrogL1UpgradeBlock) if err := w.processBridge(ctx, exit, groupStates, seen, result); err != nil { - if firstErr == nil { - firstErr = err - } - groupFailed = true - break + errs = append(errs, fmt.Errorf("destination %d: %w", exit.DestinationNetwork, err)) } } - if groupFailed { - continue - } if err := w.saveCursors(ctx, groupStates, result); err != nil { - if firstErr == nil { - firstErr = err - } - continue + errs = append(errs, err) + } + } + + for _, state := range orderedStates(states) { + if state.err != nil { + result.FailedDestinations = append(result.FailedDestinations, state.claimer.Target().DestinationNetwork) } } - return result, firstErr + return result, errors.Join(errs...) } // processBridge evaluates a single bridge exit and enqueues it for claiming when appropriate. @@ -305,6 +327,10 @@ func (w *L1ToL2) PollOnce(ctx context.Context) (*PollResult, error) { // bridge whose destination is owned by a different group's window (e.g. two windows overlap) is // tallied via the same unknown-destination path as a truly unknown destination: it is ignored here // and left for the group that owns it to enqueue exactly once. +// A destination that already failed in this poll (state.err != nil) defers its later bridges: they are +// counted in result.DeferredBridgeCount, neither marked seen nor used to advance the cursor, and +// nil is returned. The first IsClaimed/Enqueue failure of a destination is recorded in state.err and +// returned; it never affects other destinations. // It updates result counters and the seen deduplication map in place. func (w *L1ToL2) processBridge( ctx context.Context, @@ -323,6 +349,11 @@ func (w *L1ToL2) processBridge( return nil } + if state.err != nil { + result.DeferredBridgeCount++ + return nil + } + state.nextCursor = maxCursorPosition(state.nextCursor, exit.BlockNum, exit.BlockPos) // The source network is always L1 (network 0) for L1-initiated exits, independent of the @@ -337,7 +368,8 @@ func (w *L1ToL2) processBridge( claimed, err := state.claimer.IsClaimed(ctx, exit) if err != nil { - return fmt.Errorf("check l1 bridge %s target claim state: %w", key, err) + state.err = fmt.Errorf("check l1 bridge %s target claim state: %w", key, err) + return state.err } if claimed { result.IgnoredBridgeCount++ @@ -346,7 +378,8 @@ func (w *L1ToL2) processBridge( result.MatchedBridgeCount++ if err := state.claimer.Enqueue(ctx, exit); err != nil { - return fmt.Errorf("enqueue l1 bridge %s to claimer %s: %w", key, state.claimer.Target().ID, err) + state.err = fmt.Errorf("enqueue l1 bridge %s to claimer %s: %w", key, state.claimer.Target().ID, err) + return state.err } result.EnqueuedBridgeCount++ return nil @@ -370,13 +403,18 @@ func bridgeFilteredByPosition(exit autoclaimtypes.BridgeExit, state *destination // saveCursors persists the advanced cursor for every destination state in states, which is scoped to // a single window group by the caller. A destination whose cursor is saved here keeps that write even // if a save for a different group fails later in the same poll: persistence is per-group, never rolled -// back or gated by another group's outcome. +// back or gated by another group's outcome. Destinations that failed during this poll (state.err != nil) +// are skipped, so their persisted cursor stays unchanged and their bridges are re-evaluated next poll. +// A SaveBridgeCursor error stops the loop and is returned. func (w *L1ToL2) saveCursors( ctx context.Context, states map[uint32]*destinationCursorState, result *PollResult, ) error { for _, state := range orderedStates(states) { + if state.err != nil { + continue + } if err := w.cursorStore.SaveBridgeCursor(ctx, state.cursorName, state.nextCursor, w.now()); err != nil { return fmt.Errorf("save autoclaim l1-to-l2 bridge detector cursor %s: %w", state.cursorName, err) } @@ -385,24 +423,67 @@ func (w *L1ToL2) saveCursors( return nil } +// updateBackoff feeds the outcome of a poll into the per-destination back-off tracker: a destination of a +// group whose GetBridges succeeded and that did not fail is reset, and a destination that failed opens its +// next back-off window (one Warn per window). When ctx is done the failure may be a cancellation artefact, +// so the tracker is left untouched. +func (w *L1ToL2) updateBackoff( + ctx context.Context, + states map[uint32]*destinationCursorState, + queried map[uint32]*destinationCursorState, +) { + defer func() { metrics.SetStalledDestinations(metrics.DetectorL1ToL2, w.backoff.stalledCount()) }() + for _, state := range orderedStates(states) { + dest := state.claimer.Target().DestinationNetwork + if state.err == nil { + if _, ok := queried[dest]; ok { + w.backoff.recordSuccess(dest) + } + continue + } + if ctx.Err() != nil { + continue + } + window, attempt := w.backoff.recordFailure(dest, state.err, w.now()) + metrics.IncDestinationError(metrics.DetectorL1ToL2, dest) + var httpErr rpc.HTTPError + if errors.As(state.err, &httpErr) && httpErr.StatusCode == http.StatusTooManyRequests { + w.logWarnf("autoclaim l1-to-l2 bridge detector: detection for destination %d paused for %s "+ + "after rate limiting (HTTP 429, attempt %d): %v", dest, window, attempt, state.err) + } else { + w.logWarnf("autoclaim l1-to-l2 bridge detector: detection for destination %d paused for %s "+ + "after error (attempt %d): %v", dest, window, attempt, state.err) + } + } +} + +// destinationCursorStates builds the cursor state of every registered destination that is not inside a +// back-off window. The skipped destinations are returned, in ascending order, as the second value. func (w *L1ToL2) destinationCursorStates( ctx context.Context, lastProcessedBlock uint64, -) (map[uint32]*destinationCursorState, error) { +) (map[uint32]*destinationCursorState, []uint32, error) { claimers, err := w.registry.Claimers(ctx) if err != nil { - return nil, fmt.Errorf("list autoclaim l1-to-l2 bridge detector claimers: %w", err) + return nil, nil, fmt.Errorf("list autoclaim l1-to-l2 bridge detector claimers: %w", err) } states := make(map[uint32]*destinationCursorState, len(claimers)) + var backedOff []uint32 for _, runtimeClaimer := range claimers { if runtimeClaimer == nil { - return nil, fmt.Errorf("autoclaim l1-to-l2 bridge detector registry returned nil claimer") + return nil, nil, fmt.Errorf("autoclaim l1-to-l2 bridge detector registry returned nil claimer") } target := runtimeClaimer.Target() + if w.backoff.shouldSkip(target.DestinationNetwork, w.now()) { + w.logDebugf("autoclaim l1-to-l2 bridge detector: skipping destination %d, backed off until %s", + target.DestinationNetwork, w.backoff.skipUntil(target.DestinationNetwork)) + backedOff = append(backedOff, target.DestinationNetwork) + continue + } cursorName := w.cursorNameForDestination(target.DestinationNetwork) cursor, cursorFound, err := w.cursorStore.GetBridgeCursor(ctx, cursorName) if err != nil { - return nil, fmt.Errorf("get autoclaim l1-to-l2 bridge detector cursor %s: %w", cursorName, err) + return nil, nil, fmt.Errorf("get autoclaim l1-to-l2 bridge detector cursor %s: %w", cursorName, err) } states[target.DestinationNetwork] = &destinationCursorState{ claimer: runtimeClaimer, @@ -412,7 +493,8 @@ func (w *L1ToL2) destinationCursorStates( fromBlock: w.nextFromBlock(cursor, cursorFound, lastProcessedBlock), } } - return states, nil + sort.Slice(backedOff, func(i, j int) bool { return backedOff[i] < backedOff[j] }) + return states, backedOff, nil } func (w *L1ToL2) cursorNameForDestination(destinationNetwork uint32) string { @@ -497,6 +579,18 @@ func (w *L1ToL2) logErrorf(format string, args ...interface{}) { } } +func (w *L1ToL2) logWarnf(format string, args ...interface{}) { + if w.log != nil { + w.log.Warnf(format, args...) + } +} + +func (w *L1ToL2) logDebugf(format string, args ...interface{}) { + if w.log != nil { + w.log.Debugf(format, args...) + } +} + func minUint64(a, b uint64) uint64 { if a < b { return a diff --git a/autoclaim/bridgedetector/l1_to_l2_test.go b/autoclaim/bridgedetector/l1_to_l2_test.go index 65d24d16e..c2cb2d836 100644 --- a/autoclaim/bridgedetector/l1_to_l2_test.go +++ b/autoclaim/bridgedetector/l1_to_l2_test.go @@ -656,6 +656,154 @@ func TestL1ToL2_IgnoresBridgeOutsideOwnWindowWithoutDoubleEnqueue(t *testing.T) require.Len(t, claimerB.enqueued, 1, "destination B must receive exactly one enqueue, not one per overlapping window") } +// TestL1ToL2_FailingDestinationDoesNotBlockOthersInGroup proves that an IsClaimed or Enqueue failure +// for one destination of a window group neither blocks the other destinations of that group nor lets +// the failed destination's cursor advance past a bridge that was not enqueued. +func TestL1ToL2_FailingDestinationDoesNotBlockOthersInGroup(t *testing.T) { + failure := errors.New("claimer failure") + tests := []struct { + name string + setup func(c *fakeClaimer) + }{ + {name: "IsClaimed error", setup: func(c *fakeClaimer) { c.claimErr = failure }}, + {name: "Enqueue error", setup: func(c *fakeClaimer) { c.err = failure }}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + ctx := context.Background() + bridges := []bridgesync.Bridge{ + makeSyncBridge(1, autoclaimtypes.L1OriginNetwork, 10, 2, 0), + makeSyncBridge(2, autoclaimtypes.L1OriginNetwork, 11, 3, 0), + makeSyncBridge(3, autoclaimtypes.L1OriginNetwork, 12, 4, 0), + makeSyncBridge(4, autoclaimtypes.L1OriginNetwork, 10, 5, 0), + makeSyncBridge(5, autoclaimtypes.L1OriginNetwork, 11, 6, 0), + makeSyncBridge(6, autoclaimtypes.L1OriginNetwork, 10, 7, 0), + makeSyncBridge(7, autoclaimtypes.L1OriginNetwork, 12, 8, 0), + } + source := &fakeBridgeSource{ + lastProcessedBlock: 10, + found: true, + bridgesByRange: map[blockRange][]bridgesync.Bridge{{from: 1, to: 10}: bridges}, + } + store := newMemoryCursorStore() + failing := &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer10ID, DestinationNetwork: 10}} + tt.setup(failing) + healthyY := &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer11ID, DestinationNetwork: 11}} + healthyZ := &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: "claimer-12", DestinationNetwork: 12}} + detector := newTestDetector( + t, source, store, newFakeRegistry(failing, healthyY, healthyZ), + WithStartBlock(0), WithBlockWindow(10), WithOverlapBlocks(0), + ) + seeded := autoclaimtypes.BridgeCursor{FromBlock: 0, ToBlock: 0, BlockNum: 0} + for _, dest := range []uint32{10, 11, 12} { + store.cursors[detector.cursorNameForDestination(dest)] = seeded + } + + result, err := detector.PollOnce(ctx) + require.ErrorIs(t, err, failure) + require.ErrorContains(t, err, "destination 10") + require.Equal(t, []uint32{10}, result.FailedDestinations) + require.Equal(t, 2, result.DeferredBridgeCount, "bridges 4 and 6 of the failed destination are deferred") + require.True(t, result.CursorAdvanced) + + require.Len(t, healthyY.enqueued, 2) + require.Len(t, healthyZ.enqueued, 2) + require.Equal(t, uint64(10), store.cursors[detector.cursorNameForDestination(11)].ToBlock) + require.Equal(t, uint64(10), store.cursors[detector.cursorNameForDestination(12)].ToBlock) + + require.Empty(t, failing.enqueued) + require.Len(t, failing.claimChecks, 1, "later bridges of the failed destination must not be evaluated") + require.Equal(t, seeded, store.cursors[detector.cursorNameForDestination(10)]) + + claimers := map[uint32]*fakeClaimer{10: failing, 11: healthyY, 12: healthyZ} + for dest, claimer := range claimers { + cursor := store.cursors[detector.cursorNameForDestination(dest)] + for _, bridge := range bridges { + if bridge.DestinationNetwork != dest || bridge.BlockNum > cursor.BlockNum { + continue + } + enqueued := false + for _, exit := range claimer.enqueued { + enqueued = enqueued || exit.DepositCount == bridge.DepositCount + } + require.True(t, enqueued, + "cursor of destination %d advanced past non-enqueued bridge %d", dest, bridge.DepositCount) + } + } + }) + } +} + +// TestL1ToL2_DestinationFailingAfterSomeBridgesEnqueued covers a destination that fails after part of its +// bridges were enqueued: its cursor must not move, and once it recovers the earlier bridges are +// re-enqueued idempotently before the cursor advances. +func TestL1ToL2_DestinationFailingAfterSomeBridgesEnqueued(t *testing.T) { + failure := errors.New("claimer failure") + tests := []struct { + name string + setup func(c *fakeClaimer) + clear func(c *fakeClaimer) + }{ + { + name: "IsClaimed error on the second bridge", + setup: func(c *fakeClaimer) { c.claimErr, c.claimErrFrom = failure, 2 }, + clear: func(c *fakeClaimer) { c.claimErr = nil }, + }, + { + name: "Enqueue error on the second bridge", + setup: func(c *fakeClaimer) { c.err, c.enqueueErrFrom = failure, 2 }, + clear: func(c *fakeClaimer) { c.err = nil }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + ctx := context.Background() + bridges := []bridgesync.Bridge{ + makeSyncBridge(1, autoclaimtypes.L1OriginNetwork, 10, 2, 0), + makeSyncBridge(2, autoclaimtypes.L1OriginNetwork, 11, 3, 0), + makeSyncBridge(4, autoclaimtypes.L1OriginNetwork, 10, 5, 0), + makeSyncBridge(6, autoclaimtypes.L1OriginNetwork, 10, 7, 0), + } + source := &fakeBridgeSource{ + lastProcessedBlock: 10, + found: true, + bridgesByRange: map[blockRange][]bridgesync.Bridge{{from: 1, to: 10}: bridges}, + } + store := newMemoryCursorStore() + failing := &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer10ID, DestinationNetwork: 10}} + tt.setup(failing) + healthy := &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer11ID, DestinationNetwork: 11}} + clock := testNow + detector := newTestDetector(t, source, store, newFakeRegistry(failing, healthy), + WithStartBlock(0), WithBlockWindow(10), WithOverlapBlocks(0), + WithNow(func() time.Time { return clock })) + detector.backoff = newDestinationBackoff(time.Second, 2*time.Minute, 0) + seeded := autoclaimtypes.BridgeCursor{FromBlock: 0, ToBlock: 0, BlockNum: 0} + for _, dest := range []uint32{10, 11} { + store.cursors[detector.cursorNameForDestination(dest)] = seeded + } + + result, err := detector.PollOnce(ctx) + require.ErrorIs(t, err, failure) + require.Equal(t, []uint32{10}, result.FailedDestinations) + require.Len(t, failing.enqueued, 1, "the first bridge was enqueued before the failure") + require.Equal(t, uint32(1), failing.enqueued[0].DepositCount) + require.Equal(t, seeded, store.cursors[detector.cursorNameForDestination(10)], + "the cursor of the failed destination does not move") + require.Equal(t, uint64(10), store.cursors[detector.cursorNameForDestination(11)].ToBlock) + + // Recovered and past the back-off window: earlier bridges are re-enqueued idempotently. + tt.clear(failing) + clock = clock.Add(time.Second) + result, err = detector.PollOnce(ctx) + require.NoError(t, err) + require.Empty(t, result.FailedDestinations) + require.Len(t, failing.enqueued, 3, "bridges 1, 4 and 6 are enqueued exactly once each") + require.Equal(t, uint64(10), store.cursors[detector.cursorNameForDestination(10)].ToBlock) + }) + } +} + func newTestDetector( t *testing.T, source autoclaimtypes.BridgeSource, @@ -824,13 +972,18 @@ func (r *fakeRegistry) Claimers(_ context.Context) ([]autoclaimtypes.Claimer, er } type fakeClaimer struct { - target autoclaimtypes.ClaimerTarget - err error - claimErr error - claimed bool - claimChecks []autoclaimtypes.BridgeExit - enqueued []autoclaimtypes.BridgeExit - seen map[autoclaimtypes.RequestKey]struct{} + target autoclaimtypes.ClaimerTarget + err error + claimErr error + // claimErrFrom, when > 0, makes claimErr apply only from the N-th IsClaimed call (1-based); + // enqueueErrFrom does the same for err and Enqueue. Zero means every call fails. + claimErrFrom int + enqueueErrFrom int + enqueueCalls int + claimed bool + claimChecks []autoclaimtypes.BridgeExit + enqueued []autoclaimtypes.BridgeExit + seen map[autoclaimtypes.RequestKey]struct{} } func (c *fakeClaimer) Target() autoclaimtypes.ClaimerTarget { @@ -839,14 +992,15 @@ func (c *fakeClaimer) Target() autoclaimtypes.ClaimerTarget { func (c *fakeClaimer) IsClaimed(_ context.Context, bridge autoclaimtypes.BridgeExit) (bool, error) { c.claimChecks = append(c.claimChecks, bridge) - if c.claimErr != nil { + if c.claimErr != nil && len(c.claimChecks) >= c.claimErrFrom { return false, c.claimErr } return c.claimed, nil } func (c *fakeClaimer) Enqueue(_ context.Context, bridge autoclaimtypes.BridgeExit) error { - if c.err != nil { + c.enqueueCalls++ + if c.err != nil && c.enqueueCalls >= c.enqueueErrFrom { return c.err } if c.seen == nil { diff --git a/autoclaim/bridgedetector/l2_to_lx.go b/autoclaim/bridgedetector/l2_to_lx.go index 5d414f36f..1505c8051 100644 --- a/autoclaim/bridgedetector/l2_to_lx.go +++ b/autoclaim/bridgedetector/l2_to_lx.go @@ -4,14 +4,19 @@ import ( "context" "errors" "fmt" + "maps" + "net/http" + "slices" "sort" "time" + "github.com/agglayer/aggkit/autoclaim/metrics" autoclaimtypes "github.com/agglayer/aggkit/autoclaim/types" "github.com/agglayer/aggkit/bridgeservice" aggkitcommon "github.com/agglayer/aggkit/common" "github.com/agglayer/aggkit/l1infotreesync" "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/rpc" ) const ( @@ -220,10 +225,11 @@ type L2ToLxPollResult struct { ProcessedSourceCount int // SkippedSourceCount is the number of sources skipped this poll, for any of three reasons: // nothing new for any pair; the source is permanently excluded from bridge service resolution - // (ErrSourceDisabled); or at least one pair's fetch group must be retried (url miss or not synced - // yet). Only the last one holds the source's block-window position back -- a source whose groups - // partially succeeded is that case, while a permanently excluded source is counted here yet lets - // the window advance past its verify row. + // (ErrSourceDisabled); or at least one pair must be retried (url miss, not synced yet, or a + // destination whose claim-state check failed this poll or is backed off). Only the last one holds + // the source's block-window position back -- a source whose groups partially succeeded is that + // case, while a permanently excluded source is counted here yet lets the window advance past its + // verify row. SkippedSourceCount int // CandidateCount is the total number of claim candidates fetched across every fetch group of // every processed source. @@ -232,8 +238,19 @@ type L2ToLxPollResult struct { EnqueuedCount int // AlreadyClaimedCount is the number of candidates skipped because the target already claimed them. AlreadyClaimedCount int - // CursorAdvanced reports whether the block-window cursor was advanced. + // CursorAdvanced reports whether the block-window cursor was advanced. It can be true together with + // a non-nil PollOnce error when only per-destination failures occurred (see FailedDestinations). CursorAdvanced bool + // DeferredCandidateCount is the number of candidates of a destination whose claim-state check had + // already failed earlier in the same fetch group: they are neither checked nor enqueued this poll and + // are re-fetched on a later poll from the destination's unchanged pair cursor. + DeferredCandidateCount int + // FailedDestinations lists, in ascending order, the destinations whose claim-state check (IsClaimed) + // failed this poll. Their pair cursors were not advanced past the failing group. + FailedDestinations []uint32 + // BackedOffDestinations lists, in ascending order, the destinations excluded from this poll because + // they are inside a back-off window after an earlier failure. + BackedOffDestinations []uint32 } // L2ToLx is the bridge detector that discovers L2-initiated (rollup-origin) bridge exits by watching @@ -263,6 +280,9 @@ type L2ToLx struct { // "/", so a persistent condition logs at most once per retryLogInterval // rather than on every poll. Only ever touched from the single poll goroutine. retryLogged map[string]time.Time + // backoff pauses detection for a destination whose claim-state check keeps failing. Only ever + // touched from the single poll goroutine. + backoff *destinationBackoff } // retryLogInterval bounds how often a persistent retry-later condition is logged per source. @@ -320,6 +340,7 @@ func NewL2ToLx( for _, option := range options { option(detector) } + detector.backoff = newDestinationBackoff(detector.pollPeriod, destinationBackoffMax, destinationBackoffJitter) return detector, nil } @@ -383,19 +404,47 @@ const ( // sourceProcessed means every fetch group's candidates were enqueued and every pair's LER cursor // advanced. sourceProcessed - // sourceRetryLater means at least one of the source's fetch groups was skipped for a reason that - // can still clear on its own (a finder miss for a service not yet announced or unhealthy, or a - // source bridge service not synced yet) and must be retried on a later poll. Groups that did - // succeed keep their persisted pair cursors. A permanently excluded source is NOT this outcome: - // it can never clear, so holding the shared cursor for it would deadlock every other source. + // sourceRetryLater means at least one of the source's pending pairs was not advanced for a reason + // that can still clear on its own (a finder miss for a service not yet announced or unhealthy, a + // source bridge service not synced yet, a destination whose claim-state check failed, or a + // destination inside its back-off window) and must be retried on a later poll. Pairs that did + // succeed keep their persisted cursors. A permanently excluded source is NOT this outcome: it can + // never clear, so holding the shared cursor for it would deadlock every other source. sourceRetryLater ) +// pollDestinationOutcomes accumulates per-destination results across all sources of one poll. +type pollDestinationOutcomes struct { + // failed holds the first IsClaimed error per destination this poll. + failed map[uint32]error + // succeeded holds the destinations with at least one LER pair cursor advanced this poll. + succeeded map[uint32]struct{} + // backedOff holds the destinations skipped by back-off this poll (computed once at poll start). + backedOff map[uint32]struct{} +} + +func newPollDestinationOutcomes() *pollDestinationOutcomes { + return &pollDestinationOutcomes{ + failed: make(map[uint32]error), + succeeded: make(map[uint32]struct{}), + backedOff: make(map[uint32]struct{}), + } +} + // PollOnce processes at most one L1 block window of verified-batch rows. Each source found in the // window resolves an independent from_ler per destination claimer and issues one claim-candidates // query per distinct from_ler (issue #1651), so the number of fetcher calls per poll stays bounded by // the number of enabled claimers times the pages each of their queries needs, and collapses back to // today's single batched query set as soon as every destination of a source shares one cursor. +// +// Failures of a destination's claim-state check (IsClaimed) are isolated per destination: the other +// destinations keep processing and advance their pair cursors, the failed destination's pair cursor is +// held, its source holds the block-window cursor just before its verify row, and the destination is +// then paused by a per-destination back-off (it is excluded from fetches until its window ends). Those +// per-destination errors are returned joined, after the block-window cursor has been handled, so a +// non-nil error together with L2ToLxPollResult.CursorAdvanced == true is possible; FailedDestinations +// lists the destinations concerned. Any other failure (registry, enqueue, fetch, cursor storage) is a +// hard error that leaves the block-window cursor untouched, as before. func (w *L2ToLx) PollOnce(ctx context.Context) (*L2ToLxPollResult, error) { if !w.enabled { return &L2ToLxPollResult{}, nil @@ -433,14 +482,26 @@ func (w *L2ToLx) PollOnce(ctx context.Context) (*L2ToLxPollResult, error) { return result, err } + outcomes := newPollDestinationOutcomes() + defer w.updateBackoff(ctx, outcomes) + for _, destination := range sortedNetworks(destinationNetworks) { + if _, dup := outcomes.backedOff[destination]; dup || !w.backoff.shouldSkip(destination, w.now()) { + continue + } + w.logDebugf("autoclaim l2-to-lx bridge detector: skipping destination %d, backed off until %s", + destination, w.backoff.skipUntil(destination)) + outcomes.backedOff[destination] = struct{}{} + result.BackedOffDestinations = append(result.BackedOffDestinations, destination) + } + // retryBlock is the block of the earliest verify row whose source was skipped for a reason that // can still clear on its own (finder miss or source not synced yet); 0 = none. A source that can // never resolve (permanently excluded) deliberately does not contribute here. var retryBlock uint64 for _, source := range orderedSourceLERs(latestBySource) { - outcome, err := w.processSource(ctx, source, destinationNetworks, result) + outcome, err := w.processSource(ctx, source, destinationNetworks, outcomes, result) if err != nil { - return result, err + return result, w.pollError(err, outcomes, result) } switch outcome { case sourceProcessed: @@ -464,13 +525,14 @@ func (w *L2ToLx) PollOnce(ctx context.Context) (*L2ToLxPollResult, error) { // the retry fetch still uses from_ler = , which covers every candidate missed in // between; a pair whose group did succeed keeps its advanced cursor and is simply not re-fetched. // A hard error above returns before this point, leaving the cursor unchanged so the whole window - // is retried. + // is retried. A destination whose claim-state check failed (or that is backed off) is a retryable + // skip of its source, so it holds the cursor like any other; its error is returned after this point. cursorToBlock := toBlock if retryBlock > 0 { if retryBlock <= fromBlock { // The retried row sits at the very start of the window: there is no forward progress to // record, keep the stored cursor untouched and retry the same window next poll. - return result, nil + return result, w.pollError(nil, outcomes, result) } cursorToBlock = retryBlock - 1 } @@ -481,11 +543,60 @@ func (w *L2ToLx) PollOnce(ctx context.Context) (*L2ToLxPollResult, error) { BlockPos: 0, } if err := w.cursorStore.SaveBridgeCursor(ctx, w.cursorName, nextCursor, w.now()); err != nil { - return result, fmt.Errorf("save autoclaim l2-to-lx bridge detector cursor %s: %w", w.cursorName, err) + return result, w.pollError( + fmt.Errorf("save autoclaim l2-to-lx bridge detector cursor %s: %w", w.cursorName, err), outcomes, result) } result.CursorAdvanced = true - return result, nil + return result, w.pollError(nil, outcomes, result) +} + +// pollError fills result.FailedDestinations (ascending) from outcomes and returns hardErr (nil when +// none) joined with one "destination %d: ..." error per failed destination, in ascending order. The +// result is nil when there is neither a hard error nor a failed destination. +func (w *L2ToLx) pollError(hardErr error, outcomes *pollDestinationOutcomes, result *L2ToLxPollResult) error { + errs := []error{hardErr} + result.FailedDestinations = nil + for _, destination := range sortedDestinationKeys(outcomes.failed) { + result.FailedDestinations = append(result.FailedDestinations, destination) + errs = append(errs, fmt.Errorf("destination %d: %w", destination, outcomes.failed[destination])) + } + return errors.Join(errs...) +} + +// updateBackoff feeds the per-destination outcome of a poll into the back-off tracker: a destination +// that advanced at least one pair cursor and did not fail is reset, and a destination whose claim-state +// check failed opens its next back-off window (one Warn per window). A destination with no activity this +// poll is left unchanged. When ctx is done the failure may be a cancellation artefact, so failures are +// not recorded. +func (w *L2ToLx) updateBackoff(ctx context.Context, outcomes *pollDestinationOutcomes) { + defer func() { metrics.SetStalledDestinations(metrics.DetectorL2ToLx, w.backoff.stalledCount()) }() + for _, destination := range sortedDestinationKeys(outcomes.succeeded) { + if _, failed := outcomes.failed[destination]; !failed { + w.backoff.recordSuccess(destination) + } + } + if ctx.Err() != nil { + return + } + for _, destination := range sortedDestinationKeys(outcomes.failed) { + failure := outcomes.failed[destination] + window, attempt := w.backoff.recordFailure(destination, failure, w.now()) + metrics.IncDestinationError(metrics.DetectorL2ToLx, destination) + var httpErr rpc.HTTPError + if errors.As(failure, &httpErr) && httpErr.StatusCode == http.StatusTooManyRequests { + w.logWarnf("autoclaim l2-to-lx bridge detector: detection for destination %d paused for %s "+ + "after rate limiting (HTTP 429, attempt %d): %v", destination, window, attempt, failure) + } else { + w.logWarnf("autoclaim l2-to-lx bridge detector: detection for destination %d paused for %s "+ + "after error (attempt %d): %v", destination, window, attempt, failure) + } + } +} + +// sortedDestinationKeys returns the keys of a destination-keyed map in ascending order. +func sortedDestinationKeys[V any](m map[uint32]V) []uint32 { + return slices.Sorted(maps.Keys(m)) } // processSource evaluates one source network's newest LER against every destination the enabled @@ -495,14 +606,20 @@ func (w *L2ToLx) PollOnce(ctx context.Context) (*L2ToLxPollResult, error) { // baseline instead of inheriting an already-advanced cursor that would skip its history, and it does // not disturb the established destinations, which keep batching exactly as before. // +// Pending pairs whose destination is backed off this poll (outcomes.backedOff) are not fetched at all: +// they are left out of every fetch group, keep their pair cursors, and make the source retry later, so +// a backed-off pair holds the block-window cursor exactly like a failed one. +// // It returns sourceUpToDate when there is nothing to do -- no pair has anything new, the source has // no destination pair at all, or the source is permanently excluded from bridge service resolution -- -// sourceRetryLater when at least one group was skipped for a reason that can still clear (finder miss -// or not synced yet), and sourceProcessed when every group advanced its pairs' LER cursors. +// sourceRetryLater when at least one pair was not advanced for a reason that can still clear (finder +// miss, not synced yet, a failed claim-state check, or a backed-off destination), and sourceProcessed +// when every pending pair advanced its LER cursor. func (w *L2ToLx) processSource( ctx context.Context, source sourceLER, destinationNetworks []uint32, + outcomes *pollDestinationOutcomes, result *L2ToLxPollResult, ) (sourceOutcome, error) { destinationIDs := excludeNetwork(destinationNetworks, source.sourceID) @@ -556,6 +673,21 @@ func (w *L2ToLx) processSource( } result.NewLERSourceCount++ + active := make([]pendingDestination, 0, len(pending)) + deferred := 0 + for _, pair := range pending { + if _, backedOff := outcomes.backedOff[pair.destination]; backedOff { + deferred++ + continue + } + active = append(active, pair) + } + if len(active) == 0 { + // Every pending pair is backed off: nothing is fetched, and the source is retried later so its + // verify row is re-observed once the back-off window ends. + return sourceRetryLater, nil + } + url, err := w.fetcher.GetURL(source.sourceID) if err != nil { if errors.Is(err, ErrSourceDisabled) { @@ -579,7 +711,11 @@ func (w *L2ToLx) processSource( return sourceRetryLater, nil } - return w.processLERGroups(ctx, source, url, groupPendingByFromLER(pending), result) + outcome, err := w.processLERGroups(ctx, source, url, groupPendingByFromLER(active), outcomes, result) + if err == nil && outcome == sourceProcessed && deferred > 0 { + outcome = sourceRetryLater + } + return outcome, err } // processLERGroups fetches, enqueues and persists each from_ler group of one source in turn. A group @@ -588,11 +724,18 @@ func (w *L2ToLx) processSource( // gates it. A group that failed leaves its pairs' cursors untouched, so the next poll re-fetches only // that group; the source itself still reports retry-later (or the hard error), which holds the // block-window cursor just before this source's verify row so the row is re-observed. +// +// Within a group, a destination whose claim-state check failed is recorded in outcomes.failed and +// excluded from the cursor advance, while the group's other destinations still advance (and are +// recorded in outcomes.succeeded); the source then reports retry-later. On the next poll the failed +// pair's from_ler differs from its former group mates', so it forms its own group and only that group +// is re-fetched. func (w *L2ToLx) processLERGroups( ctx context.Context, source sourceLER, url string, groups []lerGroup, + outcomes *pollDestinationOutcomes, result *L2ToLxPollResult, ) (sourceOutcome, error) { var ( @@ -616,19 +759,42 @@ func (w *L2ToLx) processLERGroups( } result.CandidateCount += len(candidates) - if err := w.enqueueCandidates(ctx, source, candidates, result); err != nil { + failed, err := w.enqueueCandidates(ctx, source, candidates, result) + // Record soft destination failures even when the same group also hit a hard error, so the + // failing destination still gets its back-off window. + for destination, failure := range failed { + if _, seen := outcomes.failed[destination]; !seen { + outcomes.failed[destination] = failure + } + } + if len(failed) > 0 { + retryLater = true + } + if err != nil { if firstErr == nil { firstErr = err } continue } - if err := w.advanceLERCursors(ctx, source, group.destinations); err != nil { + advance := make([]uint32, 0, len(group.destinations)) + for _, destination := range group.destinations { + if _, isFailed := failed[destination]; !isFailed { + advance = append(advance, destination) + } + } + if len(advance) == 0 { + continue + } + if err := w.advanceLERCursors(ctx, source, advance); err != nil { if firstErr == nil { firstErr = err } continue } + for _, destination := range advance { + outcomes.succeeded[destination] = struct{}{} + } } if firstErr != nil { @@ -722,12 +888,7 @@ func lerGroupKey(fromLER *common.Hash) string { // sortedNetworks returns a copy of networks in ascending order. func sortedNetworks(networks []uint32) []uint32 { - sorted := make([]uint32, len(networks)) - copy(sorted, networks) - sort.Slice(sorted, func(i, j int) bool { - return sorted[i] < sorted[j] - }) - return sorted + return slices.Sorted(slices.Values(networks)) } // initialFromLER derives the exclusive lower-bound LER the first time a source network is seen. When @@ -827,20 +988,33 @@ func (w *L2ToLx) fetchCandidatesForDestinations( // enqueueCandidates routes every candidate to its destination claimer and enqueues the ones that are // not already claimed on the target. +// +// A failing claim-state check (IsClaimed, the only call that reaches the destination's RPC) is isolated +// per destination: it is recorded in the returned failed map (first error per destination), that +// destination's remaining candidates in this call are skipped (counted in +// result.DeferredCandidateCount, neither checked nor enqueued), and the other destinations' candidates +// continue. Every other failure (claimer registry, EnqueueRequest) is a hard error returned as err, +// which aborts the call. func (w *L2ToLx) enqueueCandidates( ctx context.Context, source sourceLER, candidates []ClaimCandidate, result *L2ToLxPollResult, -) error { +) (map[uint32]error, error) { + failed := make(map[uint32]error) for i := range candidates { candidate := candidates[i] exit := candidate.Bridge exit.SourceNetwork = source.sourceID + if _, isFailed := failed[exit.DestinationNetwork]; isFailed { + result.DeferredCandidateCount++ + continue + } + claimer, ok, err := w.registry.ClaimerForDestination(ctx, exit.DestinationNetwork) if err != nil { - return fmt.Errorf("resolve claimer for destination %d: %w", exit.DestinationNetwork, err) + return failed, fmt.Errorf("resolve claimer for destination %d: %w", exit.DestinationNetwork, err) } if !ok { // The destination was requested from the source bridge service but no claimer handles it; @@ -850,8 +1024,9 @@ func (w *L2ToLx) enqueueCandidates( claimed, err := claimer.IsClaimed(ctx, exit) if err != nil { - return fmt.Errorf("check target claim state for source %d deposit %d: %w", + failed[exit.DestinationNetwork] = fmt.Errorf("check target claim state for source %d deposit %d: %w", source.sourceID, exit.DepositCount, err) + continue } if claimed { result.AlreadyClaimedCount++ @@ -864,18 +1039,19 @@ func (w *L2ToLx) enqueueCandidates( request.VerifyBlockNum = source.verifyNum if _, inserted, err := w.enqueuer.EnqueueRequest(ctx, request); err != nil { - return fmt.Errorf("enqueue autoclaim request %s: %w", request.Key, err) + return failed, fmt.Errorf("enqueue autoclaim request %s: %w", request.Key, err) } else if inserted { result.EnqueuedCount++ } } - return nil + return failed, nil } // advanceLERCursors records the source's newest LER as processed for each of the given destinations. -// It is called once per fetch group and only after every candidate of that group has been enqueued, -// so a pair's cursor never moves past candidates that were not persisted. Destinations whose group -// did not complete are not passed in, which leaves their own cursors at their previous value. +// It is called once per fetch group and only after every candidate of that group has been enqueued or +// classified as already claimed, so a pair's cursor never moves past candidates that were not +// persisted. Destinations whose group did not complete, and destinations whose claim-state check failed +// within the group, are not passed in, which leaves their own cursors at their previous value. func (w *L2ToLx) advanceLERCursors(ctx context.Context, source sourceLER, destinations []uint32) error { for _, destination := range destinations { cursor := autoclaimtypes.LERCursor{ @@ -945,6 +1121,12 @@ func (w *L2ToLx) logWarnf(format string, args ...interface{}) { } } +func (w *L2ToLx) logDebugf(format string, args ...interface{}) { + if w.log != nil { + w.log.Debugf(format, args...) + } +} + // shouldLogRetry reports whether the given retry-later condition for sourceID is due to be logged, // and records the time if so. func (w *L2ToLx) shouldLogRetry(condition string, sourceID uint32) bool { diff --git a/autoclaim/bridgedetector/l2_to_lx_test.go b/autoclaim/bridgedetector/l2_to_lx_test.go index 6d5109fe9..9903c99f0 100644 --- a/autoclaim/bridgedetector/l2_to_lx_test.go +++ b/autoclaim/bridgedetector/l2_to_lx_test.go @@ -5,17 +5,22 @@ import ( "errors" "fmt" "math/big" + "net/http" "strings" "testing" "time" + autoclaimmetrics "github.com/agglayer/aggkit/autoclaim/metrics" autoclaimtypes "github.com/agglayer/aggkit/autoclaim/types" "github.com/agglayer/aggkit/bridgeservice" "github.com/agglayer/aggkit/bridgeservicefinder" bridgesynctypes "github.com/agglayer/aggkit/bridgesync/types" commonmocks "github.com/agglayer/aggkit/common/mocks" "github.com/agglayer/aggkit/l1infotreesync" + "github.com/agglayer/aggkit/prometheus" "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/rpc" + "github.com/prometheus/client_golang/prometheus/testutil" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" ) @@ -1583,3 +1588,404 @@ func (e *fakeEnqueuer) EnqueueRequest( e.order = append(e.order, request) return &request, true, nil } + +// --- S23: per-destination isolation and back-off --- + +const ( + isoSource uint32 = 1 + isoFailing uint32 = 10 + isoHealthy uint32 = 11 + isoClaimed uint32 = 12 + isoVerify = uint64(40) + isoFirstTo = isoVerify - 1 // block cursor held just before the source's verify row + isoLastBlck = uint64(50) +) + +// destinationFilteringFetcher wraps fakeFetcher and, like the real bridge service, only returns the +// candidates whose destination is in the query's DestinationNetworkIDs (with a matching count). +type destinationFilteringFetcher struct { + *fakeFetcher +} + +func (f *destinationFilteringFetcher) GetClaimCandidates( + ctx context.Context, query ClaimCandidatesQuery, +) ([]ClaimCandidate, int, error) { + candidates, _, err := f.fakeFetcher.GetClaimCandidates(ctx, query) + if err != nil { + return nil, 0, err + } + wanted := make(map[uint32]struct{}, len(query.DestinationNetworkIDs)) + for _, destination := range query.DestinationNetworkIDs { + wanted[destination] = struct{}{} + } + filtered := make([]ClaimCandidate, 0, len(candidates)) + for _, candidate := range candidates { + if _, ok := wanted[candidate.Bridge.DestinationNetwork]; ok { + filtered = append(filtered, candidate) + } + } + return filtered, len(filtered), nil +} + +type isolationFixture struct { + detector *L2ToLx + fetcher *destinationFilteringFetcher + registry *fakeRegistry + failing *fakeClaimer + healthy *fakeClaimer + claimed *fakeClaimer + lerStore *fakePerPairLERStore + cursorStore *memoryCursorStore + enqueuer *fakeEnqueuer + log *capturingLogger + clock *time.Time + lerX, lerY common.Hash + // published maps a source LER to every candidate the source published up to (and including) it. + published map[common.Hash][]ClaimCandidate +} + +// newIsolationFixture builds one source whose three destination pairs share from_ler = lerX and whose +// newest LER lerY (verify row at block 40) carries two candidates for the failing destination, one for +// the healthy destination and one for a destination where the bridge is already claimed. +func newIsolationFixture(t *testing.T, failure error) *isolationFixture { + t.Helper() + f := &isolationFixture{ + failing: &fakeClaimer{ + target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer10ID, DestinationNetwork: isoFailing}, + claimErr: failure, + }, + healthy: &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer11ID, DestinationNetwork: isoHealthy}}, + claimed: &fakeClaimer{target: autoclaimtypes.ClaimerTarget{ID: "claimer-12", DestinationNetwork: isoClaimed}, claimed: true}, + lerStore: newFakePerPairLERStore(), + enqueuer: newFakeEnqueuer(), + log: &capturingLogger{}, + lerX: lerHash(20), + lerY: lerHash(30), + } + clock := testNow + f.clock = &clock + f.registry = newFakeRegistry(f.failing, f.healthy, f.claimed) + f.cursorStore = newMemoryCursorStore() + + candidates := []ClaimCandidate{ + makeCandidate(5, isoFailing), makeCandidate(6, isoFailing), + makeCandidate(7, isoHealthy), makeCandidate(8, isoClaimed), + } + f.published = map[common.Hash][]ClaimCandidate{f.lerX: nil, f.lerY: candidates} + f.fetcher = &destinationFilteringFetcher{fakeFetcher: newFakeFetcher()} + f.fetcher.urls[isoSource] = fakeSrcURL1 + f.fetcher.setPageForLER(fakeSrcURL1, &f.lerX, 1, candidates, len(candidates)) + + for _, destination := range []uint32{isoFailing, isoHealthy, isoClaimed} { + f.lerStore.set(isoSource, destination, autoclaimtypes.LERCursor{ + SourceNetwork: isoSource, DestinationNetwork: destination, LastLER: f.lerX, LastVerifyBlockNum: 5, + }) + } + + row := makeVerifyRow(isoSource, f.lerY, isoVerify) + source := &fakeVerifiedBatchSource{ + lastProcessedBlock: isoLastBlck, + rowsByRange: map[blockRange][]*l1infotreesync.VerifyBatches{ + {from: 0, to: 49}: {row}, + {from: isoFirstTo, to: isoLastBlck}: {row}, // re-observed window (overlap 1) while the cursor is held + }, + } + f.detector = newTestL2ToLxDetector(t, source, f.fetcher, f.registry, f.cursorStore, f.lerStore, f.enqueuer, + WithL2ToLxBlockWindow(50), WithL2ToLxLogger(f.log), WithL2ToLxNow(func() time.Time { return *f.clock })) + f.detector.backoff = newDestinationBackoff(time.Second, 2*time.Minute, 0) + return f +} + +func (f *isolationFixture) pairLER(t *testing.T, destination uint32) common.Hash { + t.Helper() + cursor, found, err := f.lerStore.GetLERCursor(context.Background(), isoSource, destination) + require.NoError(t, err) + require.True(t, found) + return cursor.LastLER +} + +func (f *isolationFixture) blockCursorTo(t *testing.T) uint64 { + t.Helper() + cursor, ok := f.cursorStore.cursors[defaultL2ToLxCursorName] + require.True(t, ok) + return cursor.ToBlock +} + +// requireLERCursorInvariant asserts the S23 safety invariant: for every persisted LER pair cursor, every +// candidate the source published up to that cursor's LER for that destination was enqueued or is already +// claimed on the destination. A pair cursor therefore never moves past an un-enqueued candidate. +func requireLERCursorInvariant(t *testing.T, f *isolationFixture) { + t.Helper() + require.NotEmpty(t, f.lerStore.cursors) + for key, cursor := range f.lerStore.cursors { + sourceID, destination := key[0], key[1] + upTo, known := f.published[cursor.LastLER] + require.True(t, known, "pair (%d, %d) cursor points at an unknown LER %s", sourceID, destination, cursor.LastLER) + for _, candidate := range upTo { + if candidate.Bridge.DestinationNetwork != destination { + continue + } + requestKey := autoclaimtypes.DeriveRequestKey(sourceID, destination, candidate.Bridge.DepositCount) + _, enqueued := f.enqueuer.requests[requestKey] + claimer := f.registry.claimers[destination] + alreadyClaimed := claimer != nil && claimer.claimed + require.True(t, enqueued || alreadyClaimed, + "pair (%d, %d) cursor at %s is past candidate %s, which was neither enqueued nor already claimed", + sourceID, destination, cursor.LastLER, requestKey) + } + } +} + +func TestL2ToLx_FailingDestinationIsIsolated(t *testing.T) { + ctx := context.Background() + claimErr := errors.New("destination rpc down") + f := newIsolationFixture(t, claimErr) + + result, err := f.detector.PollOnce(ctx) + require.ErrorIs(t, err, claimErr) + require.ErrorContains(t, err, fmt.Sprintf("destination %d:", isoFailing)) + require.True(t, result.CursorAdvanced, "a per-destination failure still saves the (held) block cursor") + require.Equal(t, []uint32{isoFailing}, result.FailedDestinations) + require.Empty(t, result.BackedOffDestinations) + require.Equal(t, 1, result.DeferredCandidateCount, "the failing destination's second candidate is deferred") + require.Len(t, f.failing.claimChecks, 1, "no IsClaimed call after the destination failed") + require.Equal(t, 1, result.SkippedSourceCount) + require.Equal(t, 0, result.ProcessedSourceCount) + + // One query for the shared from_ler group. + require.Len(t, f.fetcher.queries, 1) + require.Equal(t, []uint32{isoFailing, isoHealthy, isoClaimed}, f.fetcher.queries[0].DestinationNetworkIDs) + + // The healthy destination's candidate is enqueued and its pair advances; the already-claimed pair + // advances too; the failing pair stays. + _, enqueued := f.enqueuer.requests[autoclaimtypes.DeriveRequestKey(isoSource, isoHealthy, 7)] + require.True(t, enqueued) + require.Len(t, f.enqueuer.order, 1) + require.Equal(t, f.lerY, f.pairLER(t, isoHealthy)) + require.Equal(t, f.lerY, f.pairLER(t, isoClaimed)) + require.Equal(t, f.lerX, f.pairLER(t, isoFailing)) + + // The block cursor is held just before the source's verify row. + require.Equal(t, isoFirstTo, f.blockCursorTo(t)) + + require.Len(t, f.log.warns, 1) + require.Contains(t, f.log.warns[0], "autoclaim l2-to-lx bridge detector: detection for destination 10 "+ + "paused for 1s after error (attempt 1)") + require.Equal(t, 1, f.detector.backoff.stalledCount()) + requireLERCursorInvariant(t, f) +} + +// TestL2ToLx_DestinationFailingAfterSomeCandidatesEnqueued covers a destination whose claim-state check fails +// on its second candidate: the first one is enqueued, the pair cursor stays, and once the destination +// recovers the first is re-enqueued idempotently before the cursor advances. +func TestL2ToLx_DestinationFailingAfterSomeCandidatesEnqueued(t *testing.T) { + ctx := context.Background() + f := newIsolationFixture(t, nil) + failure := errors.New("destination rpc down") + f.failing.claimErr, f.failing.claimErrFrom = failure, 2 + + result, err := f.detector.PollOnce(ctx) + require.ErrorIs(t, err, failure) + require.Equal(t, []uint32{isoFailing}, result.FailedDestinations) + _, enqueued := f.enqueuer.requests[autoclaimtypes.DeriveRequestKey(isoSource, isoFailing, 5)] + require.True(t, enqueued, "the first candidate was enqueued before the failure") + _, enqueued = f.enqueuer.requests[autoclaimtypes.DeriveRequestKey(isoSource, isoFailing, 6)] + require.False(t, enqueued) + require.Equal(t, f.lerX, f.pairLER(t, isoFailing), "the pair cursor does not move") + require.Equal(t, isoFirstTo, f.blockCursorTo(t)) + requireLERCursorInvariant(t, f) + + f.failing.claimErr = nil + *f.clock = testNow.Add(time.Second) + _, err = f.detector.PollOnce(ctx) + require.NoError(t, err) + for _, deposit := range []uint32{5, 6} { + _, enqueued = f.enqueuer.requests[autoclaimtypes.DeriveRequestKey(isoSource, isoFailing, deposit)] + require.True(t, enqueued) + } + require.Len(t, f.enqueuer.order, 3, "failing deposits 5 and 6 plus the healthy one, each enqueued once") + require.Equal(t, f.lerY, f.pairLER(t, isoFailing)) + requireLERCursorInvariant(t, f) +} + +// TestL2ToLx_SoftFailureRecordedWhenGroupAlsoHitsHardError covers a fetch group where one destination's +// claim-state check fails (soft) and a later enqueue fails with a hard error: the soft failure must still +// open the destination's back-off window. +func TestL2ToLx_SoftFailureRecordedWhenGroupAlsoHitsHardError(t *testing.T) { + ctx := context.Background() + soft := errors.New("destination rpc down") + hard := errors.New("local db down") + f := newIsolationFixture(t, soft) + f.enqueuer.errForDestination = map[uint32]error{isoHealthy: hard} + + result, err := f.detector.PollOnce(ctx) + require.ErrorIs(t, err, hard) + require.Equal(t, []uint32{isoFailing}, result.FailedDestinations) + require.Equal(t, 1, f.detector.backoff.stalledCount(), "the soft failure opens a back-off window") + require.Len(t, f.log.warns, 1) + require.Contains(t, f.log.warns[0], "detection for destination 10 paused for 1s") + require.Equal(t, f.lerX, f.pairLER(t, isoFailing)) + require.Equal(t, f.lerX, f.pairLER(t, isoHealthy), "nothing advances in the group that hit the hard error") + requireLERCursorInvariant(t, f) +} + +func TestL2ToLx_BackedOffDestinationHoldsBlockCursor(t *testing.T) { + ctx := context.Background() + f := newIsolationFixture(t, errors.New("boom")) + + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + queries := len(f.fetcher.queries) + + // Same clock, then just before the window ends: the destination is backed off, nothing is fetched, + // and the source still holds the block cursor at the verify row. + for _, at := range []time.Time{testNow, testNow.Add(time.Second - time.Nanosecond)} { + *f.clock = at + result, err := f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Equal(t, []uint32{isoFailing}, result.BackedOffDestinations) + require.Empty(t, result.FailedDestinations) + require.Equal(t, 1, result.NewLERSourceCount) + require.Equal(t, 1, result.SkippedSourceCount) + require.Equal(t, 0, result.ProcessedSourceCount) + require.Len(t, f.fetcher.queries, queries, "a backed-off pair is not fetched") + require.Len(t, f.failing.claimChecks, 1, "no IsClaimed call while backed off") + require.Equal(t, isoFirstTo, f.blockCursorTo(t), "the block cursor stays held at the verify row") + require.Equal(t, f.lerX, f.pairLER(t, isoFailing)) + requireLERCursorInvariant(t, f) + } + require.Len(t, f.log.warns, 1, "no Warn while backed off") + require.Len(t, f.log.debugs, 2) + require.Contains(t, f.log.debugs[0], + "autoclaim l2-to-lx bridge detector: skipping destination 10, backed off until") +} + +func TestL2ToLx_FailedDestinationRetriedAloneAfterWindow(t *testing.T) { + ctx := context.Background() + f := newIsolationFixture(t, errors.New("boom")) + + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + queries := len(f.fetcher.queries) + + f.failing.claimErr = nil + *f.clock = testNow.Add(time.Second) + result, err := f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Empty(t, result.BackedOffDestinations) + require.Empty(t, result.FailedDestinations) + require.Equal(t, 1, result.ProcessedSourceCount) + + // Only the failed destination's own group is re-fetched, from its unchanged pair cursor. + require.Len(t, f.fetcher.queries, queries+1) + retry := f.fetcher.queries[queries] + require.Equal(t, []uint32{isoFailing}, retry.DestinationNetworkIDs) + require.NotNil(t, retry.FromLER) + require.Equal(t, f.lerX, *retry.FromLER) + + for _, deposit := range []uint32{5, 6} { + _, enqueued := f.enqueuer.requests[autoclaimtypes.DeriveRequestKey(isoSource, isoFailing, deposit)] + require.True(t, enqueued) + } + require.Equal(t, f.lerY, f.pairLER(t, isoFailing)) + require.Equal(t, isoLastBlck, f.blockCursorTo(t), "the block cursor moves on once the destination recovered") + require.Equal(t, 0, f.detector.backoff.stalledCount()) + requireLERCursorInvariant(t, f) +} + +func TestL2ToLx_BackoffWindowsGrowAndSuccessResets(t *testing.T) { + ctx := context.Background() + f := newIsolationFixture(t, errors.New("boom")) + + for i, window := range []time.Duration{time.Second, 2 * time.Second, 4 * time.Second} { + result, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Equal(t, []uint32{isoFailing}, result.FailedDestinations) + require.Len(t, f.log.warns, i+1) + require.Contains(t, f.log.warns[i], "paused for "+window.String()) + require.Contains(t, f.log.warns[i], fmt.Sprintf("after error (attempt %d)", i+1)) + require.Equal(t, f.clock.Add(window), f.detector.backoff.skipUntil(isoFailing)) + require.Equal(t, isoFirstTo, f.blockCursorTo(t)) + requireLERCursorInvariant(t, f) + *f.clock = f.clock.Add(window) + } + + f.failing.claimErr = nil + result, err := f.detector.PollOnce(ctx) + require.NoError(t, err) + require.Empty(t, result.FailedDestinations) + require.Equal(t, 0, f.detector.backoff.stalledCount(), "success resets the back-off") + require.Len(t, f.log.warns, 3) + requireLERCursorInvariant(t, f) + + // A new failure starts again from the initial window. + window, attempt := f.detector.backoff.recordFailure(isoFailing, errors.New("again"), *f.clock) + require.Equal(t, time.Second, window) + require.Equal(t, 1, attempt) +} + +func TestL2ToLx_BackoffRateLimitedUsesHTTP429Wording(t *testing.T) { + ctx := context.Background() + f := newIsolationFixture(t, rpc.HTTPError{StatusCode: http.StatusTooManyRequests, Status: "429 Too Many Requests"}) + + _, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Len(t, f.log.warns, 1) + require.Contains(t, f.log.warns[0], "autoclaim l2-to-lx bridge detector: detection for destination 10 "+ + "paused for 1s after rate limiting (HTTP 429, attempt 1)") +} + +func TestL2ToLx_BackoffNotUpdatedWhenContextCancelled(t *testing.T) { + f := newIsolationFixture(t, errors.New("boom")) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + result, err := f.detector.PollOnce(ctx) + require.Error(t, err) + require.Equal(t, []uint32{isoFailing}, result.FailedDestinations) + require.Equal(t, 0, f.detector.backoff.stalledCount()) + require.Empty(t, f.log.warns) + require.Equal(t, f.lerX, f.pairLER(t, isoFailing)) + requireLERCursorInvariant(t, f) +} + +func TestL2ToLx_BackoffMetrics(t *testing.T) { + prometheus.Init() + autoclaimmetrics.Register() + ctx := context.Background() + f := newIsolationFixture(t, errors.New("boom")) + + gauge, ok := prometheus.Gauge("l2_to_lx_stalled_destinations") // the wrapper keys series by bare name + require.True(t, ok) + vec, ok := prometheus.CounterVec("detector_destination_errors_total") + require.True(t, ok) + errCounter := vec.WithLabelValues(string(autoclaimmetrics.DetectorL2ToLx), "10") + before := testutil.ToFloat64(errCounter) // counters are process-global: assert deltas + + steps := []struct { + name string + recover bool + advance time.Duration + wantErr bool + wantGauge float64 + wantErrInc float64 + }{ + {name: "failure opens a window", wantErr: true, wantGauge: 1, wantErrInc: 1}, + {name: "poll inside the window adds nothing", wantGauge: 1, wantErrInc: 1}, + {name: "recovery clears the gauge", recover: true, advance: time.Second, wantGauge: 0, wantErrInc: 1}, + } + for _, step := range steps { + if step.recover { + f.failing.claimErr = nil + } + *f.clock = f.clock.Add(step.advance) + _, err := f.detector.PollOnce(ctx) + if step.wantErr { + require.Error(t, err, step.name) + } else { + require.NoError(t, err, step.name) + } + require.Equal(t, step.wantGauge, testutil.ToFloat64(gauge), step.name) + require.Equal(t, before+step.wantErrInc, testutil.ToFloat64(errCounter), step.name) + } +} diff --git a/autoclaim/metrics/metrics.go b/autoclaim/metrics/metrics.go new file mode 100644 index 000000000..2687a786d --- /dev/null +++ b/autoclaim/metrics/metrics.go @@ -0,0 +1,82 @@ +// Package metrics exposes the Prometheus series of the autoclaim bridge detectors. +package metrics + +import ( + "strconv" + + "github.com/agglayer/aggkit/prometheus" + prometheusclient "github.com/prometheus/client_golang/prometheus" +) + +// Detector identifies the bridge detector a metric sample belongs to. +type Detector string + +const ( + // DetectorL1ToL2 is the L1-to-L2 bridge detector. + DetectorL1ToL2 Detector = "l1_to_l2" + // DetectorL2ToLx is the L2-to-Lx bridge detector. + DetectorL2ToLx Detector = "l2_to_lx" + + namespace = "autoclaim" + l1ToL2StalledDestinationsName = "l1_to_l2_stalled_destinations" + l2ToLxStalledDestinationsName = "l2_to_lx_stalled_destinations" + destinationErrorsName = "detector_destination_errors_total" + skippedAlreadyClaimedName = "detector_skipped_already_claimed_total" + detectorLabel = "detector" + destinationLabel = "destination" +) + +// Register registers the autoclaim detector metrics. It is a no-op until prometheus.Init() has run, +// and a duplicate registration only logs a warning. +func Register() { + prometheus.RegisterGauges( + prometheusclient.GaugeOpts{ + Namespace: namespace, + Name: l1ToL2StalledDestinationsName, + Help: "Number of destinations currently failing or backed off in the L1-to-L2 bridge detector", + }, + prometheusclient.GaugeOpts{ + Namespace: namespace, + Name: l2ToLxStalledDestinationsName, + Help: "Number of destinations currently failing or backed off in the L2-to-Lx bridge detector", + }, + ) + prometheus.RegisterCounterVecs( + prometheus.CounterVecOpts{ + CounterOpts: prometheusclient.CounterOpts{ + Namespace: namespace, + Name: destinationErrorsName, + Help: "Number of failing detector polls per detector and destination (one per back-off window)", + }, + Labels: []string{detectorLabel, destinationLabel}, + }, + prometheus.CounterVecOpts{ + CounterOpts: prometheusclient.CounterOpts{ + Namespace: namespace, + Name: skippedAlreadyClaimedName, + Help: "Number of bridges skipped by a detector because they were already claimed", + }, + Labels: []string{detectorLabel, destinationLabel}, + }, + ) +} + +// SetStalledDestinations sets the number of stalled destinations of the given detector. +func SetStalledDestinations(detector Detector, n int) { + switch detector { + case DetectorL1ToL2: + prometheus.GaugeSet(l1ToL2StalledDestinationsName, float64(n)) + case DetectorL2ToLx: + prometheus.GaugeSet(l2ToLxStalledDestinationsName, float64(n)) + } +} + +// IncDestinationError increments the error counter of the given detector and destination network. +func IncDestinationError(detector Detector, destination uint32) { + prometheus.CounterVecInc(destinationErrorsName, string(detector), strconv.FormatUint(uint64(destination), 10)) +} + +// IncSkippedAlreadyClaimed increments the already-claimed skip counter of the given detector and destination. +func IncSkippedAlreadyClaimed(detector Detector, destination uint32) { + prometheus.CounterVecInc(skippedAlreadyClaimedName, string(detector), strconv.FormatUint(uint64(destination), 10)) +} diff --git a/autoclaim/metrics/metrics_test.go b/autoclaim/metrics/metrics_test.go new file mode 100644 index 000000000..0ce81c56e --- /dev/null +++ b/autoclaim/metrics/metrics_test.go @@ -0,0 +1,70 @@ +package metrics + +import ( + "testing" + + "github.com/agglayer/aggkit/prometheus" + prometheusclient "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/stretchr/testify/require" +) + +func TestRegister_ExposesSeries(t *testing.T) { + prometheus.Init() + Register() + require.NotPanics(t, Register, "duplicate registration must not panic") + + for _, name := range []string{l1ToL2StalledDestinationsName, l2ToLxStalledDestinationsName} { + _, ok := prometheus.Gauge(name) + require.True(t, ok, name) + } + for _, name := range []string{destinationErrorsName, skippedAlreadyClaimedName} { + _, ok := prometheus.CounterVec(name) + require.True(t, ok, name) + } + + // Series appear in the default registry once they have a sample. + IncDestinationError(DetectorL2ToLx, 4242) + IncSkippedAlreadyClaimed(DetectorL2ToLx, 4242) + SetStalledDestinations(DetectorL2ToLx, 0) + families, err := prometheusclientGather() + require.NoError(t, err) + for _, want := range []string{ + "autoclaim_l1_to_l2_stalled_destinations", + "autoclaim_l2_to_lx_stalled_destinations", + "autoclaim_detector_destination_errors_total", + "autoclaim_detector_skipped_already_claimed_total", + } { + require.Contains(t, families, want) + } +} + +func TestHelpers_UpdateSeries(t *testing.T) { + prometheus.Init() + Register() + + SetStalledDestinations(DetectorL2ToLx, 3) + gauge, ok := prometheus.Gauge(l2ToLxStalledDestinationsName) + require.True(t, ok) + require.Equal(t, 3.0, testutil.ToFloat64(gauge)) + + vec, ok := prometheus.CounterVec(destinationErrorsName) + require.True(t, ok) + counter := vec.WithLabelValues(string(DetectorL2ToLx), "7777") + before := testutil.ToFloat64(counter) + IncDestinationError(DetectorL2ToLx, 7777) + require.Equal(t, before+1, testutil.ToFloat64(counter)) +} + +// prometheusclientGather returns the names of the metric families in the default registry. +func prometheusclientGather() ([]string, error) { + mfs, err := prometheusclient.DefaultGatherer.Gather() + if err != nil { + return nil, err + } + names := make([]string, 0, len(mfs)) + for _, mf := range mfs { + names = append(names, mf.GetName()) + } + return names, nil +} diff --git a/autoclaim/runtime/runtime.go b/autoclaim/runtime/runtime.go index 035eb4b18..6eba58198 100644 --- a/autoclaim/runtime/runtime.go +++ b/autoclaim/runtime/runtime.go @@ -15,6 +15,7 @@ import ( "github.com/agglayer/aggkit/autoclaim/bridgedetector" "github.com/agglayer/aggkit/autoclaim/claimer" autoclaimcfg "github.com/agglayer/aggkit/autoclaim/config" + autoclaimmetrics "github.com/agglayer/aggkit/autoclaim/metrics" "github.com/agglayer/aggkit/autoclaim/policy" "github.com/agglayer/aggkit/autoclaim/proof" "github.com/agglayer/aggkit/autoclaim/sender" @@ -344,6 +345,7 @@ func Start(ctx context.Context, deps Dependencies, factories Factories) (*Runtim } factories = withDefaultFactories(factories, deps.LogConfig) + autoclaimmetrics.Register() logger := deps.Logger if logger == nil { logger = log.WithFields("module", aggkitcommon.AUTOCLAIM) diff --git a/test/e2e/autoclaim_test.go b/test/e2e/autoclaim_test.go index d429412aa..bbc2d3784 100644 --- a/test/e2e/autoclaim_test.go +++ b/test/e2e/autoclaim_test.go @@ -24,6 +24,7 @@ import ( "github.com/ethereum/go-ethereum/accounts/abi/bind" "github.com/ethereum/go-ethereum/accounts/keystore" "github.com/ethereum/go-ethereum/common" + ethtypes "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/crypto" "github.com/google/uuid" "github.com/stretchr/testify/require" @@ -1449,3 +1450,271 @@ HTTPHeaders = {} networkBClaimerSection, ) } + +const ( + // autoClaimFailingDestinationURL is a refused-connection endpoint inside the aggkit-001 container + // (nothing listens on port 1), used as the failing destination's detection RPC. + autoClaimFailingDestinationURL = "http://127.0.0.1:1" + // autoClaimFailingDestinationService is the compose service whose logs are inspected. + autoClaimFailingDestinationService = "aggkit-001" + // autoClaimBackoffLogWindow is the window after the first back-off line in which the number of + // repeated back-off lines is bounded. + autoClaimBackoffLogWindow = 60 * time.Second + // autoClaimBackoffMaxLogLines bounds the back-off lines in autoClaimBackoffLogWindow; without + // back-off a 2s poll would produce about 30. + autoClaimBackoffMaxLogLines = 8 +) + +// TestAutoClaimL1ToL2FailingDestinationIsolated proves (issue #1889) that one L1->L2 destination whose +// detection RPC is failing neither stalls the healthy destination nor gets hammered: an L1->L2A bridge is +// auto-claimed while L2B's claimer URLRPC refuses connections, and L2B's detection is backed off. +func TestAutoClaimL1ToL2FailingDestinationIsolated(t *testing.T) { + if testing.Short() { + t.Skip("Skipping E2E test in short mode") + } + env := loadAutoClaimL2ToL2TestEnv(t) + + ctx, cancel := context.WithTimeout(context.Background(), 15*time.Minute) + defer cancel() + + l2aNetworkID := env.L2.NetworkID + l2bNetworkID := env.L2B.NetworkID + + // The failing claimer never sends a tx, so its signer is a fresh, unfunded key outside the key pool. + failingKey, err := crypto.GenerateKey() + require.NoError(t, err) + l2bKeystorePath, err := writeAutoClaimL2NetworkBKeystore(env, failingKey) + require.NoError(t, err, "provision failing-destination claimer keystore") + requireHostKeystoreVisible(t, env, "autoclaim-l2b-keystore", "l2b-autoclaim.keystore") + + originalConfig, err := os.ReadFile(env.GetAggkitConfigPath()) + require.NoError(t, err) + t.Cleanup(func() { + restoreCtx, restoreCancel := context.WithTimeout(context.Background(), autoClaimRestoreWait) + defer restoreCancel() + if err := env.RestartAggkitWithConfig(restoreCtx, func(configPath string) error { + return os.WriteFile(configPath, originalConfig, 0o600) + }); err != nil { + t.Logf("failed to restore aggkit-001 config after %s: %v", t.Name(), err) + } + }) + + t0 := time.Now() + restartCtx, restartCancel := context.WithTimeout(ctx, autoClaimRestartWait) + err = env.RestartAggkitWithConfig(restartCtx, func(configPath string) error { + patched := patchAutoClaimConfig( + string(originalConfig), + autoClaimFailingDestinationConfig(l2aNetworkID, l2bNetworkID, l2bKeystorePath), + ) + return os.WriteFile(configPath, []byte(patched), 0o600) + }) + restartCancel() + require.NoError(t, err, "restart aggkit-001 with failing-destination Auto Claim config") + waitForBridgeServiceSynced(ctx, t) + + l1Opts, l1Key, err := env.Keys.L1Keys.Checkout() + require.NoError(t, err) + defer env.Keys.L1Keys.Return(l1Key) + l2Opts, l2Key, err := env.Keys.L2Keys.Checkout() + require.NoError(t, err) + defer env.Keys.L2Keys.Return(l2Key) + + bridgeAmount := big.NewInt(autoClaimBridgeAmountWei) + initialBalance, err := env.Clients.L2.BalanceAt(ctx, l2Opts.From, nil) + require.NoError(t, err) + + // Bridge L1->L2B first, then L1->L2A: both land in the same L1 window, with the failing + // destination's bridge first. + l2bDepositCount, err := bridgeL1ToNetworkNoClaim(ctx, env, l1Opts, l2bNetworkID, bridgeAmount) + require.NoError(t, err, "bridge L1->L2B") + result, err := BridgeL1NoClaim(ctx, env, l1Opts, l2Opts, bridgeAmount, "autoclaim-failing-destination-L2A") + require.NoError(t, err) + require.Empty(t, result.ClaimTxHash, "test helper must not manually claim on L2") + + requestKey := autoclaimtypes.DeriveRequestKey( + result.Bridge.OriginNetwork, result.Bridge.DestinationNetwork, result.DepositCount, + ) + confirmed := waitForAutoClaimStatus(ctx, t, requestKey, autoclaimtypes.RequestStatusConfirmed) + require.NotNil(t, confirmed.ClaimTxHash, "confirmed Auto Claim request should expose claim tx hash") + require.Equal(t, string(result.Bridge.TxHash), confirmed.BridgeTxHash) + assertClaimedOnL2(ctx, t, env, result.GlobalIndex) + finalBalance, err := env.Clients.L2.BalanceAt(ctx, result.DestinationAddr, nil) + require.NoError(t, err) + require.GreaterOrEqual(t, new(big.Int).Sub(finalBalance, initialBalance).Cmp(bridgeAmount), 0) + + // The failing destination's request must never be created. + l2bKey := autoclaimtypes.DeriveRequestKey(0, l2bNetworkID, l2bDepositCount) + _, found, err := getAutoClaimRequestAt(ctx, bridgeServiceBaseURL, l2bKey) + require.NoError(t, err) + require.False(t, found, "no Auto Claim request must exist for the failing destination (%s)", l2bKey) + + // Back-off assertions on the container logs. + pausedFailing := fmt.Sprintf("detection for destination %d paused for", l2bNetworkID) + pausedHealthy := fmt.Sprintf("detection for destination %d paused for", l2aNetworkID) + var logs string + var first time.Time + require.Eventually(t, func() bool { + out, logErr := env.DockerComposeLogs( + ctx, "--no-log-prefix", "--timestamps", "--since", t0.Format(time.RFC3339), + autoClaimFailingDestinationService, + ) + if logErr != nil { + return false + } + logs = string(out) + for _, ts := range logLineTimes(logs, pausedFailing) { + if first.IsZero() || ts.Before(first) { + first = ts + } + } + // Only judge the window once it has fully elapsed in the container's clock. + return !first.IsZero() && time.Now().After(first.Add(autoClaimBackoffLogWindow+5*time.Second)) + }, 3*time.Minute, 5*time.Second, "failing destination back-off log line never appeared") + + require.NotEmpty(t, logLineTimes(logs, pausedFailing), "expected %q in aggkit-001 logs", pausedFailing) + inWindow := 0 + for _, ts := range logLineTimes(logs, pausedFailing) { + if !ts.After(first.Add(autoClaimBackoffLogWindow)) { + inWindow++ + } + } + require.LessOrEqual(t, inWindow, autoClaimBackoffMaxLogLines, + "failing destination must be backed off, not hammered (%d %q lines in the first %s)", + inWindow, pausedFailing, autoClaimBackoffLogWindow) + require.Empty(t, logLineTimes(logs, pausedHealthy), "healthy destination must never be paused") +} + +// logLineTimes returns the leading RFC3339Nano timestamps of the log lines containing substr. Lines +// whose timestamp cannot be parsed are ignored. +func logLineTimes(logs, substr string) []time.Time { + times := make([]time.Time, 0) + for _, line := range strings.Split(logs, "\n") { + if !strings.Contains(line, substr) { + continue + } + fields := strings.Fields(line) + if len(fields) == 0 { + continue + } + ts, err := time.Parse(time.RFC3339Nano, fields[0]) + if err != nil { + continue + } + times = append(times, ts) + } + return times +} + +// bridgeL1ToNetworkNoClaim bridges native ETH from L1 to destNetworkID (to the sender's own address), +// waits until the tx is mined and returns the bridge's deposit count. It never claims. +func bridgeL1ToNetworkNoClaim( + ctx context.Context, env *envs.Env, l1Opts *bind.TransactOpts, destNetworkID uint32, amount *big.Int, +) (uint32, error) { + l1Opts.Value = amount + defer func() { l1Opts.Value = nil }() + tx, err := env.L1.Contracts.Bridge.BridgeAsset( + l1Opts, destNetworkID, l1Opts.From, amount, common.Address{}, true, nil, + ) + if err != nil { + return 0, fmt.Errorf("send bridge tx: %w", err) + } + mineCtx, mineCancel := context.WithTimeout(ctx, 30*time.Second) + defer mineCancel() + receipt, err := bind.WaitMined(mineCtx, env.Clients.L1, tx) + if err != nil { + return 0, fmt.Errorf("wait for bridge tx: %w", err) + } + if receipt.Status != ethtypes.ReceiptStatusSuccessful { + return 0, fmt.Errorf("bridge tx %s failed", tx.Hash().Hex()) + } + bridgeEvent, err := env.L1.Contracts.Bridge.ParseBridgeEvent(*receipt.Logs[0]) + if err != nil { + return 0, fmt.Errorf("parse bridge event: %w", err) + } + return bridgeEvent.DepositCount, nil +} + +// autoClaimFailingDestinationConfig renders the [AutoClaim] section for +// TestAutoClaimL1ToL2FailingDestinationIsolated: the L1ToL2 detector enabled (L2ToLx disabled), a +// healthy allow-all claimer for L2A, and an allow-all claimer for L2B whose detection URLRPC refuses +// connections while its tx sender (EthTxManager.Etherman.URL) points at the real L2B RPC. The +// StoragePath is fresh, so both destinations start with no cursor and share one window group. +func autoClaimFailingDestinationConfig(l2aNetworkID, l2bNetworkID uint32, l2bKeystorePath string) string { + const policyName = "allow-all" + claimer := func(id string, networkID uint32, urlRPC, keystorePath, ethtxStorage, txRPC string, chainID int) string { + return fmt.Sprintf(` +[[AutoClaim.Claimers]] +Enabled = true +ID = %q +NetworkType = "EVM" +NetworkID = %d +URLRPC = %q +BridgeAddr = %q +PolicyName = %q +GasOffset = 100000 +WaitPeriod = "1s" +RetryAfter = "1s" +MaxRetries = 180 + +[AutoClaim.Claimers.Policy] +AllowMessageClaims = false +AllowedOrigins = [0] +AllowedTokens = [] +ManualFallback = false +MaxGas = 500000 + +[AutoClaim.Claimers.EthTxManager] +FrequencyToMonitorTxs = "1s" +WaitTxToBeMined = "2s" +WaitReceiptMaxTime = "250ms" +WaitReceiptCheckInterval = "1s" +PrivateKeys = [ + {Method = "local", Path = %q, Password = %q}, +] +ForcedGas = 0 +GasPriceMarginFactor = 1 +MaxGasPriceLimit = 0 +StoragePath = %q +ReadPendingL1Txs = false +SafeStatusL1NumberOfBlocks = 0 +FinalizedStatusL1NumberOfBlocks = 0 +EstimateGasMaxRetries = 1 + +[AutoClaim.Claimers.EthTxManager.Etherman] +URL = %q +MultiGasProvider = false +L1ChainID = %d +HTTPHeaders = {} +`, id, networkID, urlRPC, autoClaimBridgeAddr, policyName, keystorePath, autoClaimKeystorePass, + ethtxStorage, txRPC, chainID) + } + + return fmt.Sprintf(` +[AutoClaim] +StoragePath = "/tmp/autoclaim-e2e-failing-destination.sqlite" + +[AutoClaim.API] +Enabled = true + +[AutoClaim.L1ToL2BridgeDetector] +Enabled = true +PollInterval = "2s" +EtrogL1UpgradeBlock = 0 + +[AutoClaim.L2ToLxBridgeDetector] +Enabled = false + +[AutoClaim.BridgeServiceFinder] +PollInterval = "3s" + +[AutoClaim.BridgeServiceFinder.BridgeURLs] +%d = %q +%d = %q +%s%s`, + l2aNetworkID, autoClaimSourceBridgeServiceURL, l2bNetworkID, autoClaimNet2BridgeServiceURL, + claimer("l2-autoclaim-e2e", l2aNetworkID, autoClaimL2RPC, "/etc/aggkit/aggoracle.keystore", + "/tmp/ethtxmanager-autoclaim-failing-destination-l2a.sqlite", autoClaimL2RPC, autoClaimL2ChainID), + claimer("failing-destination-e2e", l2bNetworkID, autoClaimFailingDestinationURL, l2bKeystorePath, + "/tmp/ethtxmanager-autoclaim-failing-destination-l2b.sqlite", autoClaimL2BRPC, autoClaimL2BChainID), + ) +} From 3e1deea8f4db8345f3b380ebf341f0345a210b86 Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 18:23:23 +0000 Subject: [PATCH 5/8] fix(sync): recover omitted eth_getLogs results without whole-range retries (#1889) Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- sync/evmdownloader.go | 81 +++--- sync/logs_completeness.go | 141 ++++++++-- sync/logs_completeness_test.go | 460 +++++++++++++++++++++++++++++---- sync/metrics/metrics.go | 58 +++++ sync/metrics/metrics_test.go | 55 ++++ 5 files changed, 694 insertions(+), 101 deletions(-) create mode 100644 sync/metrics/metrics.go create mode 100644 sync/metrics/metrics_test.go diff --git a/sync/evmdownloader.go b/sync/evmdownloader.go index cdee00baf..904e10716 100644 --- a/sync/evmdownloader.go +++ b/sync/evmdownloader.go @@ -12,6 +12,7 @@ import ( aggkitcommon "github.com/agglayer/aggkit/common" "github.com/agglayer/aggkit/log" + syncmetrics "github.com/agglayer/aggkit/sync/metrics" aggkittypes "github.com/agglayer/aggkit/types" "github.com/ethereum/go-ethereum" "github.com/ethereum/go-ethereum/common" @@ -351,7 +352,8 @@ type EVMDownloaderImplementation struct { topicsToQuery []common.Hash addressesToQuery []common.Address rh *RetryHandler - log *log.Logger + log aggkitcommon.Logger + syncerID string finalizedBlockType *aggkittypes.BlockNumberFinality reorgDetector ReorgDetector reorgDetectorID string @@ -381,6 +383,7 @@ func NewEVMDownloaderImplementation( reorgDetectorID string, ) *EVMDownloaderImplementation { logger := log.WithFields("syncer", syncerID) + syncmetrics.Register() var topics []common.Hash if appender != nil { topics = appender.GetTopics() @@ -395,6 +398,7 @@ func NewEVMDownloaderImplementation( addressesToQuery: addressesToQuery, rh: rh, log: logger, + syncerID: syncerID, finalizedBlockType: finalizedBlockType, reorgDetector: reorgDetector, reorgDetectorID: reorgDetectorID, @@ -521,6 +525,53 @@ retry: // block, not that a log matching the queried topics exists (a contract emitting only a // non-queried event would otherwise be flagged as a false omission). unfilteredLogs := d.getUnfilteredLogs(ctx, fromBlock, toBlock) + + // The completeness check runs before block assembly because it can splice: for every + // confirmed omission it returns the logs recovered by the by-hash query, which are merged + // into unfilteredLogs so they go through the same filter, hook and assembly path as range + // logs. Block header logs blooms have no false negatives, so a bloom-positive, zero-log + // block is only ever *suspicious* -- never a direct failure -- because a bloom false + // positive is deterministic per (block, address) and would otherwise wedge the syncer + // forever; checkLogsCompleteness arbitrates every suspicion with a single-block re-query. + res := d.checkLogsCompleteness(ctx, fromBlock, toBlock, lastFinalizedBlock, unfilteredLogs) + if res.canceled { + return nil + } + syncmetrics.AddLogsOmissionConfirmed(d.syncerID, res.omittedBlocks) + if res.needsRangeRetry { + omissionAttempts++ + syncmetrics.IncLogsOmissionRangeRetry(d.syncerID) + // An omission that cannot be spliced must NOT be treated like an exhausted hash-mismatch + // retry (which returns nil below): returning nil here would make the Download loop treat + // the range as legitimately empty and advance past it, permanently losing the omitted log + // (a missing deposit / wrong exit tree, with no error surfaced anywhere). Retry + // indefinitely instead, with bounded/throttled logging, so a persistently-omitting RPC + // produces a loud but bounded log stream rather than silent data loss. + if aggkitcommon.ShouldLogRetryAtError(omissionAttempts) { + d.log.Errorf( + "eth_getLogs completeness check failed for range [%d,%d] (attempt %d, %d block(s) confirmed "+ + "omitted, splice cap %d), retrying range download", + fromBlock, toBlock, omissionAttempts, res.omittedBlocks, maxSplicedOmittedBlocks, + ) + } else { + d.log.Debugf( + "eth_getLogs completeness check failed for range [%d,%d] (attempt %d, %d block(s) confirmed "+ + "omitted, splice cap %d), retrying range download", + fromBlock, toBlock, omissionAttempts, res.omittedBlocks, maxSplicedOmittedBlocks, + ) + } + d.rh.Handle(ctx, "logsCompletenessOmission", omissionAttempts) + continue retry + } + if len(res.splicedLogs) > 0 { + unfilteredLogs = mergeSplicedLogs(unfilteredLogs, res.splicedLogs) + d.log.Warnf( + "logs completeness check: eth_getLogs omitted logs for %d block(s) in range [%d,%d]; "+ + "spliced %d log(s) recovered by block-hash query", + res.omittedBlocks, fromBlock, toBlock, len(res.splicedLogs), + ) + } + logs := d.filterLogs(unfilteredLogs) if d.logsHook != nil { originalCount := len(logs) @@ -588,34 +639,6 @@ retry: } } - // Block header logs blooms have no false negatives, so a bloom-positive, zero-log block is - // only ever *suspicious* -- never a direct failure -- because a bloom false positive is - // deterministic per (block, address) and would otherwise wedge the syncer forever. - // checkLogsCompleteness arbitrates every suspicion with a single-block re-query before - // reporting a confirmed omission. - if d.checkLogsCompleteness(ctx, fromBlock, toBlock, lastFinalizedBlock, unfilteredLogs) { - omissionAttempts++ - // A confirmed omission must NOT be treated like an exhausted hash-mismatch retry - // (which returns nil above): returning nil here would make the Download loop treat the - // range as legitimately empty and advance past it, permanently losing the omitted log - // (a missing deposit / wrong exit tree, with no error surfaced anywhere). Retry - // indefinitely instead, with bounded/throttled logging, so a persistently-omitting RPC - // produces a loud but bounded log stream rather than silent data loss. - if aggkitcommon.ShouldLogRetryAtError(omissionAttempts) { - d.log.Errorf( - "confirmed eth_getLogs omission for range [%d,%d] (attempt %d), retrying range download", - fromBlock, toBlock, omissionAttempts, - ) - } else { - d.log.Debugf( - "confirmed eth_getLogs omission for range [%d,%d] (attempt %d), retrying range download", - fromBlock, toBlock, omissionAttempts, - ) - } - d.rh.Handle(ctx, "logsCompletenessOmission", omissionAttempts) - continue retry - } - return blocks } } diff --git a/sync/logs_completeness.go b/sync/logs_completeness.go index 9216e3248..a0c42b65c 100644 --- a/sync/logs_completeness.go +++ b/sync/logs_completeness.go @@ -3,6 +3,7 @@ package sync import ( "context" "errors" + "sort" "time" aggkittypes "github.com/agglayer/aggkit/types" @@ -17,6 +18,41 @@ import ( // generally unhealthy RPC. const maxArbitrationAttempts = 2 +// maxSplicedOmittedBlocks caps how many confirmed-omitted blocks one completeness check recovers by +// splicing their by-hash logs into the range result. The observed pattern is a single omitted block +// per range; more than a handful of omitted blocks means the whole response is untrustworthy (for +// example a truncated or broken backend), and at that point one range retry costs less than many +// single-block queries and keeps the previous semantics. Exceeding the cap bounds the extra +// arbitration cost at (maxSplicedOmittedBlocks+1) * maxArbitrationAttempts by-hash queries per check. +const maxSplicedOmittedBlocks = 8 + +// arbitrationVerdict is the outcome of arbitrating one suspicious block. +type arbitrationVerdict int + +const ( + // arbitrationFalsePositive means the by-hash query ran and found no log: a bloom false positive. + arbitrationFalsePositive arbitrationVerdict = iota + // arbitrationConfirmed means the by-hash query found logs for the block: a genuine omission. + arbitrationConfirmed + // arbitrationUnverifiable means every arbitration attempt failed, so no verdict could be reached. + arbitrationUnverifiable + // arbitrationCanceled means the context was canceled during arbitration. + arbitrationCanceled +) + +// completenessResult is the outcome of checkLogsCompleteness. +type completenessResult struct { + // splicedLogs holds the logs recovered by block-hash arbitration for every confirmed omission. + splicedLogs []types.Log + // omittedBlocks is the number of blocks confirmed omitted by the range query. + omittedBlocks int + // needsRangeRetry is true when the omission cannot be spliced (unverifiable block or more than + // maxSplicedOmittedBlocks confirmed omissions) and the whole range must be downloaded again. + needsRangeRetry bool + // canceled is true when the context was canceled during the check. + canceled bool +} + // checkLogsCompleteness defends against a silent eth_getLogs omission: during an L1 reorg a // flaky/mixed RPC view can make eth_getLogs skip a log for a block while that block's header hash // stays canonical, which is invisible to header-hash-based reorg detection by construction (this @@ -35,20 +71,23 @@ const maxArbitrationAttempts = 2 // zone for legacy syncers (bridgesync, claimsync, l2gersync) is therefore a known gap -- their // long-term fix is migrating to the multidownloader, which verifies both zones. // -// It returns true when at least one suspected omission was arbitrated and confirmed genuine, in -// which case the caller must retry the whole range rather than accept it (see the comment at the -// call site in getEventsByBlockRangeWithRetry for why treating it like an ordinary empty range +// For every confirmed omission the logs recovered by the by-hash query are collected in +// completenessResult.splicedLogs, so the caller can merge them into the range result instead of +// downloading the range again. needsRangeRetry is set (and the collected logs discarded) when a +// suspicious block is unverifiable or when more than maxSplicedOmittedBlocks blocks are confirmed +// omitted; the caller must then retry the whole range rather than accept it (see the comment at +// the call site in getEventsByBlockRangeWithRetry for why treating it like an ordinary empty range // would be unsafe). func (d *EVMDownloaderImplementation) checkLogsCompleteness( ctx context.Context, fromBlock, toBlock, lastFinalizedBlock uint64, unfilteredLogs []types.Log, -) bool { +) completenessResult { verifyFrom := fromBlock if lastFinalizedBlock >= verifyFrom { verifyFrom = lastFinalizedBlock + 1 } if verifyFrom > toBlock { // Whole range is at or below the last finalized block: outside the verified window. - return false + return completenessResult{} } blocksWithLogs := make(map[uint64]struct{}, len(unfilteredLogs)) @@ -56,6 +95,7 @@ func (d *EVMDownloaderImplementation) checkLogsCompleteness( blocksWithLogs[l.BlockNumber] = struct{}{} } + var res completenessResult for blockNum := verifyFrom; blockNum <= toBlock; blockNum++ { if _, ok := blocksWithLogs[blockNum]; ok { // At least one unfiltered log already accounts for this block; nothing to check. @@ -64,13 +104,13 @@ func (d *EVMDownloaderImplementation) checkLogsCompleteness( select { case <-ctx.Done(): - return false + return completenessResult{canceled: true} default: } header, canceled := d.getHeaderForCompletenessCheck(ctx, blockNum) if canceled { - return false + return completenessResult{canceled: true} } // Nil bloom (retrieval path didn't provide it) or bloom negative: no assertion can be @@ -80,12 +120,37 @@ func (d *EVMDownloaderImplementation) checkLogsCompleteness( continue } - if d.arbitrateSuspectedOmission(ctx, blockNum, header.Hash) { - return true + verdict, logs := d.arbitrateSuspectedOmission(ctx, blockNum, header.Hash) + switch verdict { + case arbitrationCanceled: + return completenessResult{canceled: true} + case arbitrationUnverifiable: + return completenessResult{omittedBlocks: res.omittedBlocks, needsRangeRetry: true} + case arbitrationConfirmed: + res.omittedBlocks++ + if res.omittedBlocks > maxSplicedOmittedBlocks { + return completenessResult{omittedBlocks: res.omittedBlocks, needsRangeRetry: true} + } + res.splicedLogs = append(res.splicedLogs, logs...) + case arbitrationFalsePositive: } } - return false + return res +} + +// mergeSplicedLogs returns a new slice with the unfiltered range logs and the spliced logs, ordered by +// block number. The sort is stable and keyed on BlockNumber only: spliced blocks have no entry in +// unfilteredLogs, so range-sourced logs are never reordered (the change is strictly additive), and +// each spliced block lands as one contiguous run in the Index order the caller already gave it. +func mergeSplicedLogs(unfilteredLogs, splicedLogs []types.Log) []types.Log { + merged := make([]types.Log, 0, len(unfilteredLogs)+len(splicedLogs)) + merged = append(merged, unfilteredLogs...) + merged = append(merged, splicedLogs...) + sort.SliceStable(merged, func(i, j int) bool { + return merged[i].BlockNumber < merged[j].BlockNumber + }) + return merged } // getHeaderForCompletenessCheck fetches the header for blockNum, retrying on the same transient @@ -124,15 +189,18 @@ func (d *EVMDownloaderImplementation) getHeaderForCompletenessCheck( } // arbitrateSuspectedOmission re-queries logs for a single block by hash to distinguish a genuine -// eth_getLogs omission from a deterministic bloom false positive. It returns true when a log -// matching blockHash is found (omission confirmed genuine) and also, conservatively, when every -// arbitration attempt fails to execute: an unverifiable suspicious block must trigger a range -// retry rather than be silently accepted, since silent acceptance is exactly the failure mode this -// check exists to prevent (same semantics as the multidownloader's arbitrateSuspiciousBlock). A -// successfully executed query with no matching logs is a bloom-false-positive verdict. +// eth_getLogs omission from a deterministic bloom false positive. Only logs matching both blockHash +// and blockNum are kept; a log with the right hash but another number counts as a failed attempt. +// It returns arbitrationConfirmed with the kept logs (sorted by Index) when such logs are found, +// arbitrationUnverifiable when every arbitration attempt fails to execute (an unverifiable +// suspicious block must trigger a range retry rather than be silently accepted, since silent +// acceptance is exactly the failure mode this check exists to prevent; same semantics as the +// multidownloader's arbitrateSuspiciousBlock), arbitrationCanceled when the context is done, and +// otherwise arbitrationFalsePositive: a successfully executed query with no matching logs is a +// bloom-false-positive verdict. func (d *EVMDownloaderImplementation) arbitrateSuspectedOmission( ctx context.Context, blockNum uint64, blockHash common.Hash, -) bool { +) (arbitrationVerdict, []types.Log) { query := ethereum.FilterQuery{ BlockHash: &blockHash, Addresses: d.addressesToQuery, @@ -142,29 +210,46 @@ func (d *EVMDownloaderImplementation) arbitrateSuspectedOmission( for attempt := 1; attempt <= maxArbitrationAttempts; attempt++ { select { case <-ctx.Done(): - return false + return arbitrationCanceled, nil default: } logs, err := d.ethClient.FilterLogs(ctx, query) if err != nil { if errors.Is(err, context.Canceled) { - return false + return arbitrationCanceled, nil } d.log.Warnf("logs completeness check: arbitration query failed for block %d (attempt %d/%d): %v", blockNum, attempt, maxArbitrationAttempts, err) continue } + kept := make([]types.Log, 0, len(logs)) + malformed := false for _, l := range logs { - if l.BlockHash == blockHash { - d.log.Warnf( - "logs completeness check: confirmed eth_getLogs omission for block %d (hash %s): "+ - "bloom-positive block had 0 logs in the range query but arbitration found %d log(s)", - blockNum, blockHash.Hex(), len(logs), - ) - return true + if l.BlockHash != blockHash { + continue + } + if l.BlockNumber != blockNum { + malformed = true + continue } + kept = append(kept, l) + } + if malformed { + d.log.Warnf("logs completeness check: arbitration query for block %d (hash %s) returned a log with a "+ + "matching hash but a different block number (attempt %d/%d)", + blockNum, blockHash.Hex(), attempt, maxArbitrationAttempts) + continue + } + if len(kept) > 0 { + d.log.Debugf( + "logs completeness check: confirmed eth_getLogs omission for block %d (hash %s): "+ + "bloom-positive block had 0 logs in the range query but arbitration found %d log(s)", + blockNum, blockHash.Hex(), len(kept), + ) + sort.SliceStable(kept, func(i, j int) bool { return kept[i].Index < kept[j].Index }) + return arbitrationConfirmed, kept } reachedVerdict = true } @@ -175,7 +260,7 @@ func (d *EVMDownloaderImplementation) arbitrateSuspectedOmission( "attempts failed; conservatively retrying the range", blockNum, blockHash.Hex(), maxArbitrationAttempts, ) - return true + return arbitrationUnverifiable, nil } d.log.Debugf( @@ -183,5 +268,5 @@ func (d *EVMDownloaderImplementation) arbitrateSuspectedOmission( "after %d attempt(s); treating as a deterministic bloom false positive", blockNum, blockHash.Hex(), maxArbitrationAttempts, ) - return false + return arbitrationFalsePositive, nil } diff --git a/sync/logs_completeness_test.go b/sync/logs_completeness_test.go index 84cf26520..56d44eac6 100644 --- a/sync/logs_completeness_test.go +++ b/sync/logs_completeness_test.go @@ -3,16 +3,21 @@ package sync import ( "context" "errors" + "fmt" "math/big" + "strings" "testing" "time" + aggkitcommon "github.com/agglayer/aggkit/common" "github.com/agglayer/aggkit/log" + "github.com/agglayer/aggkit/prometheus" aggkittypes "github.com/agglayer/aggkit/types" aggkittypesmocks "github.com/agglayer/aggkit/types/mocks" "github.com/ethereum/go-ethereum" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" + "github.com/prometheus/client_golang/prometheus/testutil" "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" ) @@ -32,63 +37,320 @@ func newLogsCompletenessSUT(t *testing.T, mockEthClient *aggkittypesmocks.MultiD } } -// TestGetEventsByBlockRange_LogsOmissionHealedOnRetry covers the end-to-end healing path: the -// first eth_getLogs range query silently omits a log for a bloom-positive block, arbitration -// confirms the omission (finds the log by BlockHash), the range is retried, and the second -// attempt returns the log. -func TestGetEventsByBlockRange_LogsOmissionHealedOnRetry(t *testing.T) { +// positiveBloom returns a bloom that is positive for contractAddr. +func positiveBloom() *types.Bloom { + var bloom types.Bloom + bloom.Add(contractAddr.Bytes()) + return &bloom +} + +// omissionHeader returns the bloom-positive header of blockNum, with the same hash generateEvent uses. +func omissionHeader(blockNum uint64, hash common.Hash) *aggkittypes.BlockHeader { + parentHash := common.HexToHash("foo") + return &aggkittypes.BlockHeader{ + Number: blockNum, + Hash: hash, + ParentHash: &parentHash, + LogsBloom: positiveBloom(), + } +} + +// blockHashOf returns the block hash generateEvent assigns to blockNum. +func blockHashOf(blockNum uint64) common.Hash { + header := types.Header{Number: new(big.Int).SetUint64(blockNum), ParentHash: common.HexToHash("foo")} + return header.Hash() +} + +func rangeQuery(from, to uint64) ethereum.FilterQuery { + return ethereum.FilterQuery{ + Addresses: []common.Address{contractAddr}, + FromBlock: new(big.Int).SetUint64(from), + ToBlock: new(big.Int).SetUint64(to), + } +} + +func arbitrationQueryFor(hash common.Hash) ethereum.FilterQuery { + return ethereum.FilterQuery{BlockHash: &hash, Addresses: []common.Address{contractAddr}} +} + +// newSpliceSUT builds a downloader through the constructor (so the metrics are registered) with a +// syncer ID unique to the test, because the metric counters are process-global. +func newSpliceSUT( + t *testing.T, syncerID string, +) (*EVMDownloaderImplementation, *aggkittypesmocks.MultiDownloader) { + t.Helper() + prometheus.Init() + clientMock := aggkittypesmocks.NewMultiDownloader(t) + finalized := aggkittypes.FinalizedBlock + sut := NewEVMDownloaderImplementation( + syncerID, clientMock, aggkittypes.LatestBlock, time.Millisecond, + buildAppender(), []common.Address{contractAddr}, + &RetryHandler{RetryAfterErrorPeriod: time.Millisecond, MaxRetryAttemptsAfterError: 5}, + &finalized, nil, "test-reorg-detector-id", + ) + return sut, clientMock +} + +// omissionCounter reads the process-global omission counters for syncerID. +func omissionCounter(t *testing.T, name, syncerID string) float64 { + t.Helper() + cv, ok := prometheus.CounterVec(name) + require.True(t, ok, name) + return testutil.ToFloat64(cv.WithLabelValues(syncerID)) +} + +const ( + confirmedCounterName = "logs_omission_confirmed_total" + rangeRetriesCounterName = "logs_omission_range_retries_total" +) + +// TestGetEventsByBlockRange_LogsOmissionSplicedFromArbitration covers the end-to-end splice path: the +// eth_getLogs range query silently omits a log for a bloom-positive block, arbitration confirms the +// omission (finds the log by BlockHash) and the recovered log is spliced into the result without +// retrying the range. +func TestGetEventsByBlockRange_LogsOmissionSplicedFromArbitration(t *testing.T) { ctx := context.Background() - d, clientMock := NewTestDownloader(t, time.Millisecond) + const syncerID = "splice-from-arbitration" + sut, clientMock := newSpliceSUT(t, syncerID) + confirmedBefore := omissionCounter(t, confirmedCounterName, syncerID) + retriesBefore := omissionCounter(t, rangeRetriesCounterName, syncerID) blockNum := uint64(10) logC, updateC := generateEvent(uint32(blockNum)) - - header := types.Header{Number: big.NewInt(int64(blockNum)), ParentHash: common.HexToHash("foo")} - blockHash := header.Hash() // matches logC.BlockHash produced by generateEvent - parentHash := common.HexToHash("foo") - - var bloom types.Bloom - bloom.Add(contractAddr.Bytes()) + blockHash := blockHashOf(blockNum) // lastFinalizedBlock (5) < blockNum (10): the block is in the verified, unfinalized zone. clientMock.EXPECT().BlockNumber(mock.Anything, mock.Anything).Return(uint64(5), nil).Once() + // The range query is expected exactly once: no whole-range retry. + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)).Return([]types.Log{}, nil).Once() + clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, blockHash), nil) + clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHash)). + Return([]types.Log{*logC}, nil).Once() - addressQuery := ethereum.FilterQuery{ - Addresses: []common.Address{contractAddr}, - FromBlock: new(big.Int).SetUint64(blockNum), - ToBlock: new(big.Int).SetUint64(blockNum), + blocks := sut.GetEventsByBlockRange(ctx, blockNum, blockNum) + + require.Len(t, blocks, 1) + require.Equal(t, blockNum, blocks[0].Num) + require.Equal(t, []interface{}{updateC}, blocks[0].Events) + require.Equal(t, confirmedBefore+1, omissionCounter(t, confirmedCounterName, syncerID)) + require.Equal(t, retriesBefore, omissionCounter(t, rangeRetriesCounterName, syncerID)) + clientMock.AssertExpectations(t) +} + +// TestGetEventsByBlockRange_LogsOmissionAboveCapFallsBackToRangeRetry verifies that more than +// maxSplicedOmittedBlocks confirmed omissions fall back to the whole-range retry. +func TestGetEventsByBlockRange_LogsOmissionAboveCapFallsBackToRangeRetry(t *testing.T) { + ctx := context.Background() + const syncerID = "splice-above-cap" + sut, clientMock := newSpliceSUT(t, syncerID) + confirmedBefore := omissionCounter(t, confirmedCounterName, syncerID) + retriesBefore := omissionCounter(t, rangeRetriesCounterName, syncerID) + + fromBlock := uint64(10) + toBlock := fromBlock + maxSplicedOmittedBlocks // maxSplicedOmittedBlocks+1 blocks + var all []types.Log + for n := fromBlock; n <= toBlock; n++ { + l, _ := generateEvent(uint32(n)) + all = append(all, *l) + clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(n)). + Return(omissionHeader(n, blockHashOf(n)), nil) + clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHashOf(n))). + Return([]types.Log{*l}, nil) } - // First attempt: eth_getLogs silently omits the log even though the block is bloom-positive. - clientMock.EXPECT().FilterLogs(mock.Anything, addressQuery).Return([]types.Log{}, nil).Once() - // checkLogsCompleteness fetches the header for the (apparently) empty block and finds a - // positive bloom for the queried address. + clientMock.EXPECT().BlockNumber(mock.Anything, mock.Anything).Return(uint64(5), nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(fromBlock, toBlock)).Return([]types.Log{}, nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(fromBlock, toBlock)).Return(all, nil).Once() + + blocks := sut.GetEventsByBlockRange(ctx, fromBlock, toBlock) + + require.Len(t, blocks, int(maxSplicedOmittedBlocks)+1) + require.Equal(t, confirmedBefore+float64(maxSplicedOmittedBlocks+1), omissionCounter(t, confirmedCounterName, syncerID)) + require.Equal(t, retriesBefore+1, omissionCounter(t, rangeRetriesCounterName, syncerID)) + clientMock.AssertExpectations(t) +} + +// TestGetEventsByBlockRange_LogsOmissionUnverifiableRetriesRange verifies that a suspicious block +// whose arbitration cannot execute falls back to the whole-range retry. +func TestGetEventsByBlockRange_LogsOmissionUnverifiableRetriesRange(t *testing.T) { + ctx := context.Background() + const syncerID = "splice-unverifiable" + sut, clientMock := newSpliceSUT(t, syncerID) + retriesBefore := omissionCounter(t, rangeRetriesCounterName, syncerID) + + blockNum := uint64(10) + logC, updateC := generateEvent(uint32(blockNum)) + blockHash := blockHashOf(blockNum) + + clientMock.EXPECT().BlockNumber(mock.Anything, mock.Anything).Return(uint64(5), nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)).Return([]types.Log{}, nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)). + Return([]types.Log{*logC}, nil).Once() clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). - Return(&aggkittypes.BlockHeader{ - Number: blockNum, - Hash: blockHash, - ParentHash: &parentHash, - LogsBloom: &bloom, - }, nil) + Return(omissionHeader(blockNum, blockHash), nil) + clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHash)). + Return(nil, errors.New("blockHash filter not supported")).Times(maxArbitrationAttempts) - // Arbitration re-query by block hash finds the log: the omission is confirmed genuine. - arbitrationQuery := ethereum.FilterQuery{ - BlockHash: &blockHash, - Addresses: []common.Address{contractAddr}, + blocks := sut.GetEventsByBlockRange(ctx, blockNum, blockNum) + + require.Len(t, blocks, 1) + require.Equal(t, []interface{}{updateC}, blocks[0].Events) + require.Equal(t, retriesBefore+1, omissionCounter(t, rangeRetriesCounterName, syncerID)) + clientMock.AssertExpectations(t) +} + +// TestGetEventsByBlockRange_SplicedBlockHashMismatchRetries verifies that a reorg between arbitration +// and block assembly is handled by the existing hash-mismatch retry for spliced logs. +func TestGetEventsByBlockRange_SplicedBlockHashMismatchRetries(t *testing.T) { + ctx := context.Background() + sut, clientMock := newSpliceSUT(t, "splice-hash-mismatch") + + blockNum := uint64(10) + logC, updateC := generateEvent(uint32(blockNum)) + h1 := blockHashOf(blockNum) + h2 := common.HexToHash("0xbeef") + reorgedLog := *logC + reorgedLog.BlockHash = h2 + + clientMock.EXPECT().BlockNumber(mock.Anything, mock.Anything).Return(uint64(5), nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)).Return([]types.Log{}, nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)). + Return([]types.Log{reorgedLog}, nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(h1)).Return([]types.Log{*logC}, nil).Once() + // 1st header call: completeness check (H1). 2nd: assembly of the spliced block, which now + // reports H2 (reorg). Later calls keep reporting H2. + clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, h1), nil).Once() + clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, h2), nil) + + blocks := sut.GetEventsByBlockRange(ctx, blockNum, blockNum) + + require.Len(t, blocks, 1) + require.Equal(t, h2, blocks[0].Hash) + require.Equal(t, []interface{}{updateC}, blocks[0].Events) + clientMock.AssertExpectations(t) +} + +// TestGetEventsByBlockRange_SplicedLogsPassThroughFilterAndHook verifies that spliced logs go through +// the topic filter and the logs hook like range logs. +func TestGetEventsByBlockRange_SplicedLogsPassThroughFilterAndHook(t *testing.T) { + ctx := context.Background() + sut, clientMock := newSpliceSUT(t, "splice-filter-hook") + + blockNum := uint64(10) + logC, updateC := generateEvent(uint32(blockNum)) + blockHash := blockHashOf(blockNum) + logC.Index = 0 + nonQueried := types.Log{ + Address: contractAddr, + BlockNumber: blockNum, + BlockHash: blockHash, + Index: 1, + Topics: []common.Hash{common.HexToHash("0xabc123")}, } - clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQuery).Return([]types.Log{*logC}, nil).Once() - // Second attempt (range retried indefinitely on confirmed omission): the log now comes back. - clientMock.EXPECT().FilterLogs(mock.Anything, addressQuery).Return([]types.Log{*logC}, nil).Once() + var hookLogs []types.Log + sut.SetLogsHook(func(_ context.Context, _, _ uint64, logs []types.Log) []types.Log { + hookLogs = append(hookLogs, logs...) + return logs + }) - blocks := d.GetEventsByBlockRange(ctx, blockNum, blockNum) + clientMock.EXPECT().BlockNumber(mock.Anything, mock.Anything).Return(uint64(5), nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)).Return([]types.Log{}, nil).Once() + clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, blockHash), nil) + clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHash)). + Return([]types.Log{nonQueried, *logC}, nil).Once() + + blocks := sut.GetEventsByBlockRange(ctx, blockNum, blockNum) + require.Len(t, hookLogs, 1) + require.Equal(t, *logC, hookLogs[0]) require.Len(t, blocks, 1) - require.Equal(t, blockNum, blocks[0].Num) require.Equal(t, []interface{}{updateC}, blocks[0].Events) clientMock.AssertExpectations(t) } +// capturedLog is one entry recorded by capturingLogger. +type capturedLog struct { + level string + msg string +} + +// capturingLogger is an aggkitcommon.Logger that records every message with its level. +type capturingLogger struct { + entries []capturedLog +} + +var _ aggkitcommon.Logger = (*capturingLogger)(nil) + +func (c *capturingLogger) add(level, msg string) { + c.entries = append(c.entries, capturedLog{level: level, msg: msg}) +} + +func (c *capturingLogger) count(level, contains string) int { + n := 0 + for _, e := range c.entries { + if e.level == level && strings.Contains(e.msg, contains) { + n++ + } + } + return n +} + +func (c *capturingLogger) Panicf(format string, args ...interface{}) { + c.add("panic", fmt.Sprintf(format, args...)) +} +func (c *capturingLogger) Fatalf(format string, args ...interface{}) { + c.add("fatal", fmt.Sprintf(format, args...)) +} +func (c *capturingLogger) Info(args ...interface{}) { c.add("info", fmt.Sprint(args...)) } +func (c *capturingLogger) Infof(format string, args ...interface{}) { + c.add("info", fmt.Sprintf(format, args...)) +} +func (c *capturingLogger) Error(args ...interface{}) { c.add("error", fmt.Sprint(args...)) } +func (c *capturingLogger) Errorf(format string, args ...interface{}) { + c.add("error", fmt.Sprintf(format, args...)) +} +func (c *capturingLogger) Warn(args ...interface{}) { c.add("warn", fmt.Sprint(args...)) } +func (c *capturingLogger) Warnf(format string, args ...interface{}) { + c.add("warn", fmt.Sprintf(format, args...)) +} +func (c *capturingLogger) Debug(args ...interface{}) { c.add("debug", fmt.Sprint(args...)) } +func (c *capturingLogger) Debugf(format string, args ...interface{}) { + c.add("debug", fmt.Sprintf(format, args...)) +} + +// TestGetEventsByBlockRange_LogsOmissionLogLevels verifies that the splice path logs no Error, one +// Warn per spliced range, and the per-block confirmation at Debug. +func TestGetEventsByBlockRange_LogsOmissionLogLevels(t *testing.T) { + ctx := context.Background() + sut, clientMock := newSpliceSUT(t, "splice-log-levels") + logger := &capturingLogger{} + sut.log = logger + + blockNum := uint64(10) + logC, _ := generateEvent(uint32(blockNum)) + blockHash := blockHashOf(blockNum) + + clientMock.EXPECT().BlockNumber(mock.Anything, mock.Anything).Return(uint64(5), nil).Once() + clientMock.EXPECT().FilterLogs(mock.Anything, rangeQuery(blockNum, blockNum)).Return([]types.Log{}, nil).Once() + clientMock.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, blockHash), nil) + clientMock.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHash)). + Return([]types.Log{*logC}, nil).Once() + + blocks := sut.GetEventsByBlockRange(ctx, blockNum, blockNum) + + require.Len(t, blocks, 1) + require.Zero(t, logger.count("error", "")) + require.Equal(t, 1, logger.count("warn", "")) + require.Equal(t, 1, logger.count("warn", "spliced")) + require.Equal(t, 1, logger.count("debug", "confirmed eth_getLogs omission for block")) +} + // TestGetEventsByBlockRange_LogsBloomFalsePositive covers the deterministic-false-positive path: // the block is bloom-positive but genuinely has no log for the queried address, so arbitration // consistently returns empty. The range must be accepted as-is, with no unbounded retry loop. @@ -144,9 +406,9 @@ func TestCheckLogsCompleteness_FinalizedZoneSkipped(t *testing.T) { sut := newLogsCompletenessSUT(t, mockEthClient) // fromBlock == toBlock == lastFinalizedBlock: entirely within the finalized zone. - confirmed := sut.checkLogsCompleteness(ctx, 10, 10, 10, nil) + res := sut.checkLogsCompleteness(ctx, 10, 10, 10, nil) - require.False(t, confirmed) + require.Equal(t, completenessResult{}, res) mockEthClient.AssertExpectations(t) // no HeaderByNumber/FilterLogs calls expected or made } @@ -173,9 +435,9 @@ func TestCheckLogsCompleteness_NilBloomSkipped(t *testing.T) { // lastFinalizedBlock = blockNum-1 puts blockNum inside the verify window; unfilteredLogs is // empty for it, so the header is fetched, but its nil bloom must skip the check. - confirmed := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, nil) + res := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, nil) - require.False(t, confirmed) + require.Equal(t, completenessResult{}, res) mockEthClient.AssertExpectations(t) // header fetched once; no arbitration FilterLogs call } @@ -195,9 +457,9 @@ func TestCheckLogsCompleteness_NonQueriedTopicNotSuspicious(t *testing.T) { Topics: []common.Hash{common.HexToHash("0xabc123")}, // not eventSignature } - confirmed := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, []types.Log{nonQueriedLog}) + res := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, []types.Log{nonQueriedLog}) - require.False(t, confirmed) + require.Equal(t, completenessResult{}, res) // No HeaderByNumber/FilterLogs calls: the block is already accounted for by the unfiltered log. mockEthClient.AssertExpectations(t) } @@ -235,8 +497,118 @@ func TestCheckLogsCompleteness_UnverifiableSuspicionRetriesRange(t *testing.T) { mockEthClient.EXPECT().FilterLogs(mock.Anything, arbitrationQuery). Return(nil, errors.New("blockHash filter not supported")).Times(maxArbitrationAttempts) - confirmed := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, nil) + res := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, nil) + + require.True(t, res.needsRangeRetry) + require.Empty(t, res.splicedLogs) + require.False(t, res.canceled) + mockEthClient.AssertExpectations(t) +} + +// expectOmittedBlock registers the header and a confirming by-hash arbitration for blockNum. +func expectOmittedBlock(t *testing.T, mockEthClient *aggkittypesmocks.MultiDownloader, blockNum uint64) types.Log { + t.Helper() + l, _ := generateEvent(uint32(blockNum)) + mockEthClient.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, blockHashOf(blockNum)), nil).Once() + mockEthClient.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHashOf(blockNum))). + Return([]types.Log{*l}, nil).Once() + return *l +} + +// TestCheckLogsCompleteness_CollectsAllConfirmedOmissions verifies that every confirmed omission is +// arbitrated and its logs collected, without requesting a range retry. +func TestCheckLogsCompleteness_CollectsAllConfirmedOmissions(t *testing.T) { + ctx := context.Background() + mockEthClient := aggkittypesmocks.NewMultiDownloader(t) + sut := newLogsCompletenessSUT(t, mockEthClient) + + var want []types.Log + for n := uint64(10); n <= 12; n++ { + want = append(want, expectOmittedBlock(t, mockEthClient, n)) + } + + res := sut.checkLogsCompleteness(ctx, 10, 12, 9, nil) - require.True(t, confirmed) + require.False(t, res.needsRangeRetry) + require.False(t, res.canceled) + require.Equal(t, 3, res.omittedBlocks) + require.Equal(t, want, res.splicedLogs) mockEthClient.AssertExpectations(t) } + +// TestCheckLogsCompleteness_ExceedsSpliceCapRequestsRangeRetry verifies that the check stops at the +// first confirmation beyond maxSplicedOmittedBlocks and asks for a range retry without logs. +func TestCheckLogsCompleteness_ExceedsSpliceCapRequestsRangeRetry(t *testing.T) { + ctx := context.Background() + mockEthClient := aggkittypesmocks.NewMultiDownloader(t) + sut := newLogsCompletenessSUT(t, mockEthClient) + + fromBlock := uint64(10) + toBlock := fromBlock + maxSplicedOmittedBlocks + 1 // maxSplicedOmittedBlocks+2 suspicious blocks + // Exactly maxSplicedOmittedBlocks+1 blocks are arbitrated; the last block is never touched (the + // mock fails the test on any unexpected call). + for n := fromBlock; n < toBlock; n++ { + expectOmittedBlock(t, mockEthClient, n) + } + + res := sut.checkLogsCompleteness(ctx, fromBlock, toBlock, fromBlock-1, nil) + + require.True(t, res.needsRangeRetry) + require.Nil(t, res.splicedLogs) + require.Equal(t, maxSplicedOmittedBlocks+1, res.omittedBlocks) + mockEthClient.AssertExpectations(t) +} + +// TestCheckLogsCompleteness_ArbitrationLogWithWrongBlockNumberIsUnverifiable verifies refinement R1: +// a log with the right hash but another block number is never kept. +func TestCheckLogsCompleteness_ArbitrationLogWithWrongBlockNumberIsUnverifiable(t *testing.T) { + ctx := context.Background() + mockEthClient := aggkittypesmocks.NewMultiDownloader(t) + sut := newLogsCompletenessSUT(t, mockEthClient) + + blockNum := uint64(10) + blockHash := blockHashOf(blockNum) + wrong, _ := generateEvent(uint32(blockNum)) + wrong.BlockNumber = blockNum + 1 + + mockEthClient.EXPECT().HeaderByNumber(mock.Anything, aggkittypes.NewBlockNumber(blockNum)). + Return(omissionHeader(blockNum, blockHash), nil).Once() + mockEthClient.EXPECT().FilterLogs(mock.Anything, arbitrationQueryFor(blockHash)). + Return([]types.Log{*wrong}, nil).Times(maxArbitrationAttempts) + + res := sut.checkLogsCompleteness(ctx, blockNum, blockNum, blockNum-1, nil) + + require.True(t, res.needsRangeRetry) + require.Empty(t, res.splicedLogs) + mockEthClient.AssertExpectations(t) +} + +// TestCheckLogsCompleteness_CanceledContext verifies that a canceled context is reported as such. +func TestCheckLogsCompleteness_CanceledContext(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + mockEthClient := aggkittypesmocks.NewMultiDownloader(t) + sut := newLogsCompletenessSUT(t, mockEthClient) + + res := sut.checkLogsCompleteness(ctx, 10, 12, 9, nil) + + require.True(t, res.canceled) + require.False(t, res.needsRangeRetry) + require.Empty(t, res.splicedLogs) +} + +// TestMergeSplicedLogs_OrderAndStability verifies that spliced blocks land between their neighbours, +// range-sourced logs keep their relative order, and spliced logs keep their Index order. +func TestMergeSplicedLogs_OrderAndStability(t *testing.T) { + mk := func(block uint64, index uint) types.Log { return types.Log{BlockNumber: block, Index: index} } + // Block 12 is deliberately not Index-ordered to prove range-sourced logs are never reordered. + rangeLogs := []types.Log{mk(10, 0), mk(12, 5), mk(12, 2)} + spliced := []types.Log{mk(11, 0), mk(11, 1)} + + merged := mergeSplicedLogs(rangeLogs, spliced) + + require.Equal(t, []types.Log{mk(10, 0), mk(11, 0), mk(11, 1), mk(12, 5), mk(12, 2)}, merged) + // Inputs are left untouched. + require.Equal(t, []types.Log{mk(10, 0), mk(12, 5), mk(12, 2)}, rangeLogs) +} diff --git a/sync/metrics/metrics.go b/sync/metrics/metrics.go new file mode 100644 index 000000000..3ebde4f35 --- /dev/null +++ b/sync/metrics/metrics.go @@ -0,0 +1,58 @@ +// Package metrics exposes the Prometheus series of the legacy EVM downloader (package sync). +package metrics + +import ( + "github.com/agglayer/aggkit/prometheus" + prometheusclient "github.com/prometheus/client_golang/prometheus" +) + +const ( + namespace = "sync" + logsOmissionConfirmedName = "logs_omission_confirmed_total" + logsOmissionRangeRetriesName = "logs_omission_range_retries_total" + syncerLabel = "syncer" + logsOmissionConfirmedHelp = "eth_getLogs omissions confirmed by block-hash arbitration " + + "(per check; a block re-confirmed after a range retry counts again)" + logsOmissionRangeRetriesHelp = "Whole-range retries triggered by the eth_getLogs completeness check" +) + +// Register registers the sync downloader metrics. It is idempotent and does nothing until +// prometheus.Init() has run. It deliberately does not use sync.Once: a call made before +// prometheus.Init() must not prevent a later call from registering the series. +func Register() { + if _, ok := prometheus.CounterVec(logsOmissionConfirmedName); ok { + return + } + prometheus.RegisterCounterVecs( + prometheus.CounterVecOpts{ + CounterOpts: prometheusclient.CounterOpts{ + Namespace: namespace, + Name: logsOmissionConfirmedName, + Help: logsOmissionConfirmedHelp, + }, + Labels: []string{syncerLabel}, + }, + prometheus.CounterVecOpts{ + CounterOpts: prometheusclient.CounterOpts{ + Namespace: namespace, + Name: logsOmissionRangeRetriesName, + Help: logsOmissionRangeRetriesHelp, + }, + Labels: []string{syncerLabel}, + }, + ) +} + +// AddLogsOmissionConfirmed adds n to the confirmed eth_getLogs omissions counter of the given syncer. +// It does nothing if n is not positive. +func AddLogsOmissionConfirmed(syncerID string, n int) { + if n <= 0 { + return + } + prometheus.CounterVecAdd(logsOmissionConfirmedName, syncerID, float64(n)) +} + +// IncLogsOmissionRangeRetry increments the omission-triggered range retry counter of the given syncer. +func IncLogsOmissionRangeRetry(syncerID string) { + prometheus.CounterVecInc(logsOmissionRangeRetriesName, syncerID) +} diff --git a/sync/metrics/metrics_test.go b/sync/metrics/metrics_test.go new file mode 100644 index 000000000..56175a907 --- /dev/null +++ b/sync/metrics/metrics_test.go @@ -0,0 +1,55 @@ +package metrics + +import ( + "testing" + + "github.com/agglayer/aggkit/prometheus" + "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/stretchr/testify/require" +) + +func TestRegisterIsIdempotent(t *testing.T) { + prometheus.Init() + Register() + require.NotPanics(t, Register, "duplicate registration must not panic") + + for _, name := range []string{logsOmissionConfirmedName, logsOmissionRangeRetriesName} { + _, ok := prometheus.CounterVec(name) + require.True(t, ok, name) + } +} + +func TestHelpers_UpdateSeries(t *testing.T) { + prometheus.Init() + Register() + + const id = "metrics-test-helpers" + confirmed, ok := prometheus.CounterVec(logsOmissionConfirmedName) + require.True(t, ok) + retries, ok := prometheus.CounterVec(logsOmissionRangeRetriesName) + require.True(t, ok) + + confirmedBefore := testutil.ToFloat64(confirmed.WithLabelValues(id)) + retriesBefore := testutil.ToFloat64(retries.WithLabelValues(id)) + + AddLogsOmissionConfirmed(id, 3) + IncLogsOmissionRangeRetry(id) + + require.Equal(t, confirmedBefore+3, testutil.ToFloat64(confirmed.WithLabelValues(id))) + require.Equal(t, retriesBefore+1, testutil.ToFloat64(retries.WithLabelValues(id))) +} + +func TestAddLogsOmissionConfirmedIgnoresNonPositive(t *testing.T) { + prometheus.Init() + Register() + + const id = "metrics-test-nonpositive" + confirmed, ok := prometheus.CounterVec(logsOmissionConfirmedName) + require.True(t, ok) + before := testutil.ToFloat64(confirmed.WithLabelValues(id)) + + AddLogsOmissionConfirmed(id, 0) + AddLogsOmissionConfirmed(id, -2) + + require.Equal(t, before, testutil.ToFloat64(confirmed.WithLabelValues(id))) +} From b9c9b2da006ed6de34ea42c33d4cfe1b9730766e Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 18:25:35 +0000 Subject: [PATCH 6/8] feat(autoclaim): trace bridges skipped as already claimed (#1889) Both bridge detectors now emit a Debug log line and increment the skipped-already-claimed metric for every bridge skipped because the target already claimed it. L1ToL2 gains PollResult.AlreadyClaimedCount so already-claimed bridges are no longer folded into IgnoredBridgeCount. Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- autoclaim/bridgedetector/l1_to_l2.go | 16 ++++++++++++++- autoclaim/bridgedetector/l1_to_l2_test.go | 22 ++++++++++++++++++-- autoclaim/bridgedetector/l2_to_lx.go | 5 +++++ autoclaim/bridgedetector/l2_to_lx_test.go | 25 ++++++++++++++++++++--- 4 files changed, 62 insertions(+), 6 deletions(-) diff --git a/autoclaim/bridgedetector/l1_to_l2.go b/autoclaim/bridgedetector/l1_to_l2.go index db26424b4..0b4b4399d 100644 --- a/autoclaim/bridgedetector/l1_to_l2.go +++ b/autoclaim/bridgedetector/l1_to_l2.go @@ -113,6 +113,9 @@ type PollResult struct { MatchedBridgeCount int EnqueuedBridgeCount int IgnoredBridgeCount int + // AlreadyClaimedCount counts bridges skipped because the target network already claimed them. They + // are not part of IgnoredBridgeCount, which only counts bridges to unknown destinations. + AlreadyClaimedCount int SkippedBridgeCount int // DeferredBridgeCount counts bridges of a destination that failed earlier in this poll: they were // not evaluated and will be re-evaluated on the next poll. @@ -372,7 +375,10 @@ func (w *L1ToL2) processBridge( return state.err } if claimed { - result.IgnoredBridgeCount++ + result.AlreadyClaimedCount++ + metrics.IncSkippedAlreadyClaimed(metrics.DetectorL1ToL2, exit.DestinationNetwork) + w.logDebugf("autoclaim %s bridge detector: skipped bridge %s (destination %d, global index %s): "+ + "already claimed on target", metrics.DetectorL1ToL2, key, exit.DestinationNetwork, globalIndexString(exit)) return nil } @@ -616,3 +622,11 @@ func maxCursorPosition( } return cursor } + +// globalIndexString renders the exit's global index for logs, or "unknown" when it is not set. +func globalIndexString(exit autoclaimtypes.BridgeExit) string { + if exit.GlobalIndex == nil { + return "unknown" + } + return exit.GlobalIndex.String() +} diff --git a/autoclaim/bridgedetector/l1_to_l2_test.go b/autoclaim/bridgedetector/l1_to_l2_test.go index c2cb2d836..55933e06a 100644 --- a/autoclaim/bridgedetector/l1_to_l2_test.go +++ b/autoclaim/bridgedetector/l1_to_l2_test.go @@ -9,11 +9,14 @@ import ( "testing" "time" + autoclaimmetrics "github.com/agglayer/aggkit/autoclaim/metrics" autoclaimtypes "github.com/agglayer/aggkit/autoclaim/types" "github.com/agglayer/aggkit/bridgesync" bridgesynctypes "github.com/agglayer/aggkit/bridgesync/types" aggkitcommon "github.com/agglayer/aggkit/common" + "github.com/agglayer/aggkit/prometheus" "github.com/ethereum/go-ethereum/common" + "github.com/prometheus/client_golang/prometheus/testutil" "github.com/stretchr/testify/require" ) @@ -277,12 +280,27 @@ func TestPollOnceIgnoresAlreadyClaimedBridgeBeforeEnqueue(t *testing.T) { target: autoclaimtypes.ClaimerTarget{ID: fakeClaimer10ID, DestinationNetwork: 10}, claimed: true, } - detector := newTestDetector(t, source, store, newFakeRegistry(claimer), WithBlockWindow(11)) + log := &capturingLogger{} + detector := newTestDetector(t, source, store, newFakeRegistry(claimer), WithBlockWindow(11), WithLogger(log)) + + prometheus.Init() + autoclaimmetrics.Register() + vec, ok := prometheus.CounterVec("detector_skipped_already_claimed_total") + require.True(t, ok) + skipped := vec.WithLabelValues(string(autoclaimmetrics.DetectorL1ToL2), "10") + before := testutil.ToFloat64(skipped) result, err := detector.PollOnce(ctx) require.NoError(t, err) require.Equal(t, 0, result.EnqueuedBridgeCount) - require.Equal(t, 1, result.IgnoredBridgeCount) + require.Equal(t, 0, result.IgnoredBridgeCount) + require.Equal(t, 1, result.AlreadyClaimedCount) + require.Equal(t, before+1, testutil.ToFloat64(skipped)) + require.Len(t, claimer.claimChecks, 1) + require.Contains(t, log.debugs, fmt.Sprintf( + "autoclaim l1_to_l2 bridge detector: skipped bridge 0:10:1 (destination 10, global index %s): "+ + "already claimed on target", claimer.claimChecks[0].GlobalIndex.String())) + require.Empty(t, log.warns) require.True(t, result.CursorAdvanced) require.Empty(t, claimer.enqueued) require.Len(t, claimer.claimChecks, 1) diff --git a/autoclaim/bridgedetector/l2_to_lx.go b/autoclaim/bridgedetector/l2_to_lx.go index 1505c8051..3ccdf54d8 100644 --- a/autoclaim/bridgedetector/l2_to_lx.go +++ b/autoclaim/bridgedetector/l2_to_lx.go @@ -1030,6 +1030,11 @@ func (w *L2ToLx) enqueueCandidates( } if claimed { result.AlreadyClaimedCount++ + metrics.IncSkippedAlreadyClaimed(metrics.DetectorL2ToLx, exit.DestinationNetwork) + w.logDebugf("autoclaim %s bridge detector: skipped bridge %s (destination %d, global index %s): "+ + "already claimed on target", metrics.DetectorL2ToLx, + autoclaimtypes.DeriveRequestKey(source.sourceID, exit.DestinationNetwork, exit.DepositCount), + exit.DestinationNetwork, globalIndexString(exit)) continue } diff --git a/autoclaim/bridgedetector/l2_to_lx_test.go b/autoclaim/bridgedetector/l2_to_lx_test.go index 9903c99f0..9699ceccf 100644 --- a/autoclaim/bridgedetector/l2_to_lx_test.go +++ b/autoclaim/bridgedetector/l2_to_lx_test.go @@ -732,14 +732,27 @@ func TestL2ToLxAlreadyClaimedSkip(t *testing.T) { } lerStore := newFakePerPairLERStore() enqueuer := newFakeEnqueuer() + log := &capturingLogger{} detector := newTestL2ToLxDetector( t, source, fetcher, newFakeRegistry(claimer0), newMemoryCursorStore(), lerStore, enqueuer, - WithL2ToLxBlockWindow(50), + WithL2ToLxBlockWindow(50), WithL2ToLxLogger(log), ) + prometheus.Init() + autoclaimmetrics.Register() + vec, ok := prometheus.CounterVec("detector_skipped_already_claimed_total") + require.True(t, ok) + skipped := vec.WithLabelValues(string(autoclaimmetrics.DetectorL2ToLx), "0") + before := testutil.ToFloat64(skipped) + result, err := detector.PollOnce(ctx) require.NoError(t, err) require.Equal(t, 1, result.AlreadyClaimedCount) + require.Equal(t, before+1, testutil.ToFloat64(skipped)) + require.Contains(t, log.debugs, + "autoclaim l2_to_lx bridge detector: skipped bridge 1:0:5 (destination 0, global index unknown): "+ + "already claimed on target") + require.Empty(t, log.warns) require.Equal(t, 0, result.EnqueuedCount) require.Empty(t, enqueuer.order) require.Len(t, claimer0.claimChecks, 1) @@ -1855,8 +1868,14 @@ func TestL2ToLx_BackedOffDestinationHoldsBlockCursor(t *testing.T) { requireLERCursorInvariant(t, f) } require.Len(t, f.log.warns, 1, "no Warn while backed off") - require.Len(t, f.log.debugs, 2) - require.Contains(t, f.log.debugs[0], + var backoffDebugs []string + for _, line := range f.log.debugs { + if strings.Contains(line, "backed off until") { + backoffDebugs = append(backoffDebugs, line) + } + } + require.Len(t, backoffDebugs, 2) + require.Contains(t, backoffDebugs[0], "autoclaim l2-to-lx bridge detector: skipping destination 10, backed off until") } From c4c19ee7bcb45561334ae6f29b8d5a4fdb084e78 Mon Sep 17 00:00:00 2001 From: Arnau Bennassar Date: Sun, 4 Oct 2026 18:27:08 +0000 Subject: [PATCH 7/8] docs: document RPC failure handling for autoclaim detection (#1889) Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_017eyBoQ7G2hoShKEzAQvZWM --- docs/autoclaim.md | 58 ++++++++++++++++++++++++++++++++++++++++- docs/e2e_tests.md | 15 +++++++++++ docs/etherman.md | 66 +++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 138 insertions(+), 1 deletion(-) diff --git a/docs/autoclaim.md b/docs/autoclaim.md index 277c24e51..aca99089c 100644 --- a/docs/autoclaim.md +++ b/docs/autoclaim.md @@ -844,12 +844,60 @@ is created for GER tracking. the relevant leaf. - Auto Claim logs startup, API startup, bridge detector polling errors, claimer recovery errors, and per-request errors through the standard Aggkit logger. Request-level error details are also stored in `last_error` and exposed - by the API. The component does not export Prometheus metrics. + by the API. The bridge detectors export a small set of Prometheus metrics (see + [RPC failure handling](#rpc-failure-handling)). - Failed or evicted transaction-manager results are retried while retry budget remains. Exhausted requests become `failed` and require operator investigation. - Use `api-approve` when an operator must explicitly inspect each request before claim submission. Expose the API only on trusted networks or behind access controls; it can approve or reject pending manual requests. +### RPC failure handling + +A failing RPC endpoint of one destination network must not stall detection for the others. Both bridge detectors +(L1-to-L2 and L2-to-Lx) isolate failures per destination: + +- Only failures of the destination's own calls are soft: `IsClaimed` and claimer `Enqueue` for the L1-to-L2 + detector, and `IsClaimed` for the L2-to-Lx detector. Other errors (local database, claimer registry, source + fetch, cursor persistence) still abort the poll as before. +- A destination that fails is paused with a per-destination back-off: the first window is the detector poll period, + doubling on each consecutive failure up to 2 minutes, with +-20 % jitter. A successful poll resets it. HTTP `429` + uses the same curve. A server-provided `Retry-After` is not honoured, because go-ethereum drops the response + headers before the error reaches the detector. +- While a destination is paused its cursor does not advance, so nothing is skipped; healthy destinations keep + advancing normally. When the pause ends, detection resumes from the held cursor. +- Known L2-to-Lx liveness limitation: while a destination stays failed, the shared block window restarts at that + source's verify row on every poll, so verify rows more than `BlockWindow` (default `1000`) L1 blocks later are not + reached until the destination recovers. This is the same behaviour as the existing finder-miss path. + +Log lines to grep for (`` is the destination network ID; the L2-to-Lx detector uses the prefix +`autoclaim l2-to-lx bridge detector:`): + +```text +autoclaim l1-to-l2 bridge detector: detection for destination paused for after error (attempt ): +autoclaim l1-to-l2 bridge detector: detection for destination paused for after rate limiting (HTTP 429, attempt ): +autoclaim l1-to-l2 bridge detector: skipping destination , backed off until