diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml new file mode 100644 index 00000000..07c5e2b5 --- /dev/null +++ b/.github/workflows/ci.yml @@ -0,0 +1,39 @@ +name: CI + +on: + push: + branches: [main, master, dev] + pull_request: + +# The job only reads the code: give its token read access, like build_push.yml. +permissions: + contents: read + +# This repository had no CI at all. Every change to the indexer serving +# mainnet merged without being compiled, vetted or tested by anything but +# whoever wrote it. +jobs: + build-and-test: + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + with: + # go.mod replaces go-relay-client with a local path. + submodules: recursive + + - uses: actions/setup-go@v5 + with: + go-version-file: go.mod + cache: true + + - name: Build + run: go build ./... + + - name: Vet + run: go vet ./... + + - name: Test + # The metrics tests need a live beacon node and skip themselves when + # none answers; set GOTETH_TEST_BN_ENDPOINT (and GOTETH_TEST_EL_ENDPOINT) + # to run them against one. + run: go test -race ./... diff --git a/CITATION.cff b/CITATION.cff new file mode 100644 index 00000000..fe884468 --- /dev/null +++ b/CITATION.cff @@ -0,0 +1,31 @@ +cff-version: 1.2.0 +message: "If you use this software, please cite it using the metadata from this file." +type: software +title: GotEth +abstract: >- + GotEth is a go-written client that indexes all validator-related duties, + parameters and transactions from Ethereum's consensus and execution layers. +authors: + - given-names: Tarun + family-names: Mohandas + affiliation: MigaLabs + - alias: Zyra-V21 + given-names: Ruben + family-names: Planes Llinares + affiliation: MigaLabs + - given-names: Leo + family-names: Bautista-Gomez + affiliation: MigaLabs + - given-names: Mikel + family-names: Cortes + affiliation: MigaLabs +repository-code: "https://github.com/migalabs/goteth" +license: MIT +keywords: + - ethereum + - consensus layer + - beacon chain + - validators + - clickhouse +version: v3.9.0 +date-released: "2026-10-22" diff --git a/README.md b/README.md index 15819635..31fa11e5 100644 --- a/README.md +++ b/README.md @@ -138,9 +138,15 @@ If specific upgrades or downgrades need to be done manually, one could do this w During `v3.0.0` we migrated our database system from PostgreSQL to Clickhouse. If you wish to migrate your existing database, please follow [this](https://migalabs.notion.site/PostgreSQL-to-Clickhouse-migration-611a52a457824cd494d701773365f62f) guide. +# Citation + +[![DOI](https://zenodo.org/badge/DOI/10.5281/zenodo.XXXXXXX.svg)](https://doi.org/10.5281/zenodo.XXXXXXX) + +If you use GotEth in your work, please cite it using the metadata in [CITATION.cff](CITATION.cff), or the "Cite this repository" button on GitHub. + # Maintainers -@santi1234567 +@Zyra-V21 # Contributing diff --git a/cmd/blocks_cmd.go b/cmd/blocks_cmd.go index 70214e55..38d3ee17 100644 --- a/cmd/blocks_cmd.go +++ b/cmd/blocks_cmd.go @@ -99,7 +99,7 @@ var BlocksCommand = &cli.Command{ }, &cli.StringFlag{ Name: "metrics", - Usage: "Metrics to be persisted to the database: epoch,block,rewards,transactions,api_rewards,blob_sidecars", + Usage: "Metrics to be persisted to the database: epoch,block,rewards,transactions,api_rewards,blob_sidecars. blob_sidecars covers blob metadata (t_blob_sidecars); blob p2p arrival timings are always recorded in head mode via the data_column_sidecar event into t_data_column_sidecars_events (the post-Fulu replacement of the dead blob_sidecar event)", EnvVars: []string{"ANALYZER_METRICS"}, DefaultText: "epoch,block", }, diff --git a/cmd/pool_summary_refill_cmd.go b/cmd/pool_summary_refill_cmd.go new file mode 100644 index 00000000..cd520cc3 --- /dev/null +++ b/cmd/pool_summary_refill_cmd.go @@ -0,0 +1,71 @@ +package cmd + +import ( + "fmt" + + "github.com/attestantio/go-eth2-client/spec/phase0" + "github.com/migalabs/goteth/pkg/db" + "github.com/migalabs/goteth/pkg/utils" + "github.com/sirupsen/logrus" + cli "github.com/urfave/cli/v2" +) + +var PoolSummaryRefillCommand = &cli.Command{ + Name: "pool-summary-refill", + Usage: "Recomputes t_pool_summary for an epoch range from the current rewards and pool tags. Deletes the range first so pool renames do not leave ghost rows. Use after pool re-tagging or rewards backfills.", + Action: LaunchPoolSummaryRefill, + Flags: []cli.Flag{ + &cli.StringFlag{ + Name: "log-level", + Usage: "Log level: debug, warn, info, error", + EnvVars: []string{"ANALYZER_LOG_LEVEL"}, + DefaultText: "info", + }, + &cli.StringFlag{ + Name: "db-url", + Usage: "Database where the pool summaries are persisted", + EnvVars: []string{"ANALYZER_DB_URL"}, + DefaultText: "clickhouse://username:password@localhost:9000/goteth?x-multi-statement=true&max_memory_usage=10000000000", + }, + &cli.Uint64Flag{ + Name: "from-epoch", + Usage: "First epoch of the range to recompute (inclusive)", + Required: true, + }, + &cli.Uint64Flag{ + Name: "to-epoch", + Usage: "Last epoch of the range to recompute (inclusive)", + Required: true, + }, + }, +} + +func LaunchPoolSummaryRefill(c *cli.Context) error { + + if c.IsSet("log-level") { + logrus.SetLevel(utils.ParseLogLevel(c.String("log-level"))) + } + + dbUrl := c.String("db-url") + if dbUrl == "" { + return fmt.Errorf("db-url is required") + } + + fromEpoch := phase0.Epoch(c.Uint64("from-epoch")) + toEpoch := phase0.Epoch(c.Uint64("to-epoch")) + if toEpoch < fromEpoch { + return fmt.Errorf("to-epoch (%d) must be greater or equal than from-epoch (%d)", toEpoch, fromEpoch) + } + + dbClient, err := db.New(c.Context, dbUrl) + if err != nil { + return err + } + err = dbClient.Connect() + if err != nil { + return err + } + defer dbClient.Finish() + + return dbClient.RefreshPoolSummaryRange(fromEpoch, toEpoch) +} diff --git a/cmd/validator_window_cmd.go b/cmd/validator_window_cmd.go index 66b82f27..ab794f88 100644 --- a/cmd/validator_window_cmd.go +++ b/cmd/validator_window_cmd.go @@ -43,6 +43,12 @@ var ValidatorWindowCommand = &cli.Command{ EnvVars: []string{"DELETE_CADENCE_EPOCHS"}, DefaultText: "32", }, + &cli.IntFlag{ + Name: "pool-reroll-epochs", + Usage: "Refresh t_pool_summary for the last N epochs whenever the validator->pool mapping in t_eth2_pubkeys changes, so late-tagged validators and pool renames propagate to recent history. Set to 0 to disable.", + EnvVars: []string{"POOL_REROLL_EPOCHS"}, + DefaultText: "0", + }, &cli.StringFlag{ Name: "bn-endpoint", Usage: "Beacon node endpoint (to request the Beacon States and Blocks)", diff --git a/docs/tables.md b/docs/tables.md index 081e7d03..825660a1 100644 --- a/docs/tables.md +++ b/docs/tables.md @@ -156,12 +156,32 @@ Config: `engine = MergeTree ORDER BY f_val_idx` | f_status | uint8 | status (see status table) | | f_slashed | bool | whether the validator has ever been slashed or not | | f_activation_epoch | uint64 | epoch at which the validator was activated | +| f_activation_eligibility_epoch | uint64 | epoch at which the validator became eligible for activation; `FAR_FUTURE_EPOCH` (`18446744073709551615`) means not yet eligible. Combined with `f_activation_epoch`, this splits the pre-activation queue (`f_status = 0`) into the two deposit-lifecycle states described below. | | f_withdrawal_epoch | uint64 | epoch at which the validator can withdraw funds | | f_exit_epoch | uint64 | epoch at which the validator exited the network | | f_public_key | string | public key of the validator | | f_withdrawal_prefix | uint8 | withdrawal prefix of the validator's credentials | | f_withdrawal_credentials | text | withdrawal credentials of the validator (see below) | +## Appendix: deposit-lifecycle status vocabulary + +`f_status` keeps its coarse, stable encoding (`0 in_activation_queue · 1 active · 2 exited · 3 slashed`). +Consumers that want the finer deposit-lifecycle vocabulary derive it from +`f_status` + `f_activation_eligibility_epoch` (and, for pre-registration deposits, from +`t_deposit_requests`). This is a proposed vocabulary the current Beacon API `ValidatorStatus` +enum does not provide — its `pending_initialized` / `pending_queued` predate the post-Electra +deposit pipeline (EIP-6110/EIP-7251) and there is no deposit-queue state: + +| Derived status | Condition | Meaning | +| -------------- | --------- | ------- | +| `deposit_inqueue` | pubkey present in `t_deposit_requests`, absent from `t_validator_last_status` (not yet a registered validator) | Deposit waiting in `state.pending_deposits`; the real churn-limited queue | +| `pending_minBalance` | `f_status = 0` and `f_activation_eligibility_epoch = FAR_FUTURE_EPOCH` | Validator created, effective balance < 32 ETH (not yet eligible) | +| `pending_lookahead` | `f_status = 0` and `f_activation_eligibility_epoch != FAR_FUTURE_EPOCH` | Eligible; fixed `1 + MAX_SEED_LOOKAHEAD` delay (not a queue) | +| `active` / `exited` / `slashed` | `f_status` 1 / 2 / 3 | unchanged | + +`deposit_inqueue` is not a `t_validator_last_status` row because the deposit has no validator index +yet; it is materialised by downstream consumers (e.g. bindeth) joining `t_deposit_requests`. + ## Appendix: Reference for `f_withdrawal_prefix` The `f_withdrawal_prefix` column indicates the type of withdrawal credentials associated with the validator. The possible values are: @@ -307,18 +327,24 @@ Config: `engine = ReplacingMergeTree ORDER BY f_slot, f_index` | f_kzg_proof | string | kzg proof of the blob | | f_ending_0s | uint64 | amount of consecutive 0s at the end of the blob bytes | -# Blob Sidecars Events (`t_blob_sidecars_events`) +# Data Column Sidecars Events (`t_data_column_sidecars_events`) + +Config: `engine = ReplacingMergeTree PARTITION BY intDiv(f_slot, 100000) ORDER BY (f_slot, f_column_index, f_block_root)` + +P2P arrival timings for blob data. Since the Fulu fork (PeerDAS) blobs are no longer gossiped whole: they are erasure-coded into columns and each node custodies a subset, so beacon nodes emit `data_column_sidecar` instead of the now-dead `blob_sidecar` event. One row per **column** arrival (up to 128 per slot), which also exposes the reconstruction curve of each blob rather than a single arrival timestamp. + +Blob *metadata* is unaffected and still comes from the block itself (`t_blob_sidecars`). -Config: `engine = ReplacingMergeTree ORDER BY f_arrival_timestamp_ms, f_blob_hash, f_slot` +| Column Name | Type of Data | Description | | | +| ---------------------- | ------------- | -------------------------------------------------------------- | --- | --- | +| f_arrival_timestamp_ms | uint64 | timestamp at which goteth received the data column event | +| f_slot | uint64 | slot the data column belongs to | +| f_block_root | string | block root hash | +| f_column_index | uint16 | index of the data column (0..127) | +| f_kzg_commitments | array(string) | kzg commitments of the blobs this column carries a piece of | +| f_num_commitments | uint16 | number of commitments (denormalised from the array for queries)| -| Column Name | Type of Data | Description | | | -| ---------------------- | ------------ | ------------------------------------------------- | --- | --- | -| f_arrival_timestamp_ms | uint64 | timestamp at which goteth received the blob event | -| f_blob_hash | string | hash of the blob | -| f_slot | uint64 | slot at which the blob was sent | -| f_block_root | string | block root hash | -| f_index | uint8 | index of the blob | -| f_kzg_commitment | string | kzg commitment of the blob | +> `t_blob_sidecars_events` is the pre-Fulu predecessor of this table (one row per whole blob). It can no longer receive rows because the `blob_sidecar` event is never emitted post-Fulu; migration `000038` renames it to `t_blob_sidecars_events_pre_fulu` to preserve its history. # Block Rewards (`t_block_rewards`) diff --git a/main.go b/main.go index 11720a26..1d22c725 100644 --- a/main.go +++ b/main.go @@ -47,6 +47,7 @@ func main() { Commands: []*cli.Command{ cmd.BlocksCommand, cmd.ValidatorWindowCommand, + cmd.PoolSummaryRefillCommand, }, } diff --git a/pkg/analyzer/chain_analyzer.go b/pkg/analyzer/chain_analyzer.go index 2b1ffa22..0314989b 100644 --- a/pkg/analyzer/chain_analyzer.go +++ b/pkg/analyzer/chain_analyzer.go @@ -3,6 +3,7 @@ package analyzer import ( "context" "sync" + "sync/atomic" "time" "github.com/attestantio/go-eth2-client/spec/phase0" @@ -42,7 +43,7 @@ type ChainAnalyzer struct { // Control Variables wgMainRoutine *sync.WaitGroup // wait group for main routine (either historical or head) wgDownload *sync.WaitGroup // wait group for download routine - stop bool // flag to notify all routine to finish + stop atomic.Bool // flag to notify all routine to finish (read and written from several goroutines) routineClosed chan struct{} // signal that everything was closed succesfully downloadMode string // whether to download historical blocks (defined by user) or follow chain head rewardsAggregationEpochs int // number of epochs to aggregate rewards @@ -51,12 +52,15 @@ type ChainAnalyzer struct { metrics db.DBMetrics // what metrics to be downloaded / processed processerBook *utils.RoutineBook // defines slot to process new metrics into the database, good for monitoring - downloadCache ChainCache // store the blocks and states downloaded + downloadCache ChainCache // store the blocks and states downloaded validatorsRewardsAggregations map[phase0.ValidatorIndex]*spec.ValidatorRewardsAggregation validatorsRewardsAggregationsMu sync.Mutex - advanceFinalizedMu sync.Mutex // serializes AdvanceFinalized so concurrent invocations cannot race CleanUpTo against in-flight Wait()s + advanceFinalizedMu sync.Mutex // serializes AdvanceFinalized so concurrent invocations cannot race CleanUpTo against in-flight Wait()s + handleReorgMu sync.Mutex // serializes HandleReorg so two walks cannot process the same epoch at once and leak processerBook slots (#292) + pendingReprocess map[uint64]bool // epochs whose derived rows went stale when an earlier epoch was rewritten, and that AdvanceFinalized could not reach in that invocation (#285). Guarded by advanceFinalizedMu. + reprocessAttempts map[uint64]int // how many times each pending epoch has been attempted, so a debt that cannot be paid is abandoned loudly rather than retried forever (#291). Guarded by advanceFinalizedMu. aggregatedEpochsInWindow map[phase0.Epoch]bool // set of unique epochs aggregated in current window; prevents double-counting on reprocessing (#255) - epochBoundaryStateRoots sync.Map // slot -> phase0.Root, caches state roots from Head SSE events at epoch boundaries + epochBoundaryStateRoots sync.Map // slot -> phase0.Root, caches state roots from Head SSE events at epoch boundaries initTime time.Time PromMetrics *prom_metrics.PrometheusMetrics // metrics to be stored to prometheus @@ -182,6 +186,7 @@ func NewChainAnalyzer( downloadCache: NewQueue(), validatorsRewardsAggregations: make(map[phase0.ValidatorIndex]*spec.ValidatorRewardsAggregation), aggregatedEpochsInWindow: make(map[phase0.Epoch]bool), + pendingReprocess: make(map[uint64]bool), processerBook: utils.NewRoutineBook(32, "processer"), // one whole epoch wgMainRoutine: &sync.WaitGroup{}, wgDownload: &sync.WaitGroup{}, @@ -218,12 +223,16 @@ func (s *ChainAnalyzer) Run() { // Block requester in finalized slots, not used for now s.wgMainRoutine.Add(1) go s.runHead() + + // Persists data_column_sidecar arrivals in batches, off the head loop (#282). + s.wgMainRoutine.Add(1) + go s.runDataColumnSidecarsPersister() } s.PromMetrics.Start() s.wgMainRoutine.Wait() - s.stop = true + s.stop.Store(true) log.Infof("main routine finished, waiting for downloader...") s.wgDownload.Wait() @@ -241,7 +250,7 @@ func (s *ChainAnalyzer) Run() { func (s *ChainAnalyzer) Close() { log.Info("Sudden closed detected, closing StateAnalyzer") - s.stop = true + s.stop.Store(true) s.cancel() <-s.routineClosed // Wait for services to stop before returning } diff --git a/pkg/analyzer/download.go b/pkg/analyzer/download.go index b4275df6..6dbf2d97 100644 --- a/pkg/analyzer/download.go +++ b/pkg/analyzer/download.go @@ -22,7 +22,7 @@ func (s *ChainAnalyzer) DownloadBlock(slot phase0.Slot) { newBlock, err := s.cli.RequestBeaconBlock(slot) if err != nil { log.Errorf("block error at slot %d: %s", slot, err) - s.stop = true + s.stop.Store(true) s.cancel() return } @@ -63,7 +63,7 @@ func (s *ChainAnalyzer) DownloadState(slot phase0.Slot) { if err != nil { log.Errorf("unable to retrieve beacon state from the beacon node, closing requester routine. %s", err.Error()) - s.stop = true + s.stop.Store(true) s.cancel() return } diff --git a/pkg/analyzer/metrics_test.go b/pkg/analyzer/metrics_test.go index 7ba066be..b5ae4c5b 100644 --- a/pkg/analyzer/metrics_test.go +++ b/pkg/analyzer/metrics_test.go @@ -4,6 +4,7 @@ import ( "context" "fmt" "math/big" + "os" "strings" "testing" @@ -16,6 +17,47 @@ import ( "github.com/stretchr/testify/assert" ) +// These exercise the metrics against a live beacon node, and an execution node +// for the ones that need transactions. The endpoints default to the local ones +// a developer runs, and can be pointed elsewhere: +// +// GOTETH_TEST_BN_ENDPOINT beacon node, default http://localhost:5052 +// GOTETH_TEST_EL_ENDPOINT execution node, default http://localhost:8545 +// +// requireNodes skips when nothing answers there. They used to fail instead, +// which meant `go test ./...` was red on any machine without a node running - +// including CI, which is part of why this repository had none. +func testBNEndpoint() string { + if endpoint := os.Getenv("GOTETH_TEST_BN_ENDPOINT"); endpoint != "" { + return endpoint + } + return "http://localhost:5052" +} + +func testELEndpoint() string { + if endpoint := os.Getenv("GOTETH_TEST_EL_ENDPOINT"); endpoint != "" { + return endpoint + } + return "http://localhost:8545" +} + +// requireNodes returns an analyzer, or skips the test when no beacon node is +// reachable. Skipping rather than failing is the point: an absent node is a +// missing prerequisite, not a defect, and a suite that cannot tell the two +// apart is one nobody can run. +// Returns a pointer: ChainAnalyzer holds an atomic.Bool, so handing back a +// copy trips vet's copylocks check. +func requireNodes(t *testing.T, build func() (ChainAnalyzer, error)) *ChainAnalyzer { + t.Helper() + + analyzer, err := build() + if err != nil { + t.Skipf("no beacon node reachable at %s: %s (set GOTETH_TEST_BN_ENDPOINT to point elsewhere)", + testBNEndpoint(), err) + } + return &analyzer +} + func BuildChainAnalyzer() (ChainAnalyzer, error) { ctx := context.Background() @@ -31,12 +73,12 @@ func BuildChainAnalyzer() (ChainAnalyzer, error) { // generate the httpAPI client cli, err := clientapi.NewAPIClient( ctx, - "http://localhost:5052", + testBNEndpoint(), "", "", "", maxRequestRetries, - clientapi.WithELEndpoint("http://localhost:8545"), + clientapi.WithELEndpoint(testELEndpoint()), clientapi.WithDBMetrics(dbMetrics)) if err != nil { return ChainAnalyzer{}, err @@ -54,7 +96,7 @@ func BuildChainAnalyzerWithEL() (ChainAnalyzer, error) { ctx := context.Background() maxRequestRetries := 3 // generate the httpAPI client - cli, err := clientapi.NewAPIClient(ctx, "http://localhost:5052", "", "", "", maxRequestRetries, clientapi.WithELEndpoint("http://localhost:8545")) + cli, err := clientapi.NewAPIClient(ctx, testBNEndpoint(), "", "", "", maxRequestRetries, clientapi.WithELEndpoint(testELEndpoint())) if err != nil { return ChainAnalyzer{}, err } @@ -102,14 +144,10 @@ func BuildEpochTask(analyzer *ChainAnalyzer, slot phase0.Slot) (metrics.StateMet func TestPhase0Epoch(t *testing.T) { - analyzer, err := BuildChainAnalyzer() - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + analyzer := requireNodes(t, BuildChainAnalyzer) // returns the state in a custom struct for Phase0, Altair of Bellatrix - stateMetrics, err := BuildEpochTask(&analyzer, 320031) // epoch 10000 + stateMetrics, err := BuildEpochTask(analyzer, 320031) // epoch 10000 if err != nil { t.Errorf("could not build epoch task: %s", err) return @@ -123,14 +161,10 @@ func TestPhase0Epoch(t *testing.T) { func TestAltairEpoch(t *testing.T) { - analyzer, err := BuildChainAnalyzer() - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + analyzer := requireNodes(t, BuildChainAnalyzer) // returns the state in a custom struct for Phase0, Altair of Bellatrix - stateMetrics, err := BuildEpochTask(&analyzer, 2375711) // epoch 74240 + stateMetrics, err := BuildEpochTask(analyzer, 2375711) // epoch 74240 if err != nil { t.Errorf("could not build epoch task: %s", err) return @@ -150,14 +184,10 @@ func TestAltairEpoch(t *testing.T) { func TestAltairRewards(t *testing.T) { - analyzer, err := BuildChainAnalyzer() - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + analyzer := requireNodes(t, BuildChainAnalyzer) // returns the state in a custom struct for Phase0, Altair of Bellatrix - stateMetrics, err := BuildEpochTask(&analyzer, 6565759) // epoch 205179 + stateMetrics, err := BuildEpochTask(analyzer, 6565759) // epoch 205179 if err != nil { t.Errorf("could not build epoch task: %s", err) return @@ -244,13 +274,9 @@ func TestAltairRewards(t *testing.T) { func TestAltairNegativeRewards(t *testing.T) { - analyzer, err := BuildChainAnalyzer() - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + analyzer := requireNodes(t, BuildChainAnalyzer) // returns the state in a custom struct for Phase0, Altair of Bellatrix - stateMetrics, err := BuildEpochTask(&analyzer, 6565823) // epoch 205181 + stateMetrics, err := BuildEpochTask(analyzer, 6565823) // epoch 205181 if err != nil { t.Errorf("could not build epoch task: %s", err) return @@ -298,12 +324,7 @@ func TestAltairNegativeRewards(t *testing.T) { func TestCapellaBlock(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzerWithEL() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzerWithEL) // Test regular case @@ -366,12 +387,7 @@ func TestCapellaBlock(t *testing.T) { func TestBellatrixBlock(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzer() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzer) // Test regular case @@ -435,16 +451,11 @@ func TestBellatrixBlock(t *testing.T) { func TestAltairBlock(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzer() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzer) // Test regular case - block, err := blockAnalyzer.cli.RequestBeaconBlock(4636687) + block, _ := blockAnalyzer.cli.RequestBeaconBlock(4636687) assert.Equal(t, block.Proposed, true) @@ -465,7 +476,7 @@ func TestAltairBlock(t *testing.T) { // Test missed - block, err = blockAnalyzer.cli.RequestBeaconBlock(4709992) + block, _ = blockAnalyzer.cli.RequestBeaconBlock(4709992) assert.Equal(t, block.Proposed, false) @@ -487,16 +498,11 @@ func TestAltairBlock(t *testing.T) { func TestPhase0Block(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzer() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzer) // Test regular case - block, err := blockAnalyzer.cli.RequestBeaconBlock(2372310) + block, _ := blockAnalyzer.cli.RequestBeaconBlock(2372310) assert.Equal(t, block.Proposed, true) @@ -517,7 +523,7 @@ func TestPhase0Block(t *testing.T) { // Test missed - block, err = blockAnalyzer.cli.RequestBeaconBlock(2372309) + block, _ = blockAnalyzer.cli.RequestBeaconBlock(2372309) assert.Equal(t, block.Proposed, false) @@ -538,12 +544,7 @@ func TestPhase0Block(t *testing.T) { } func TestTransactionGasWhenELIsProvided(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzerWithEL() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzerWithEL) // Test regular case block, err := blockAnalyzer.cli.RequestBeaconBlock(8020631) //block number 18826815 @@ -578,12 +579,7 @@ func TestTransactionGasWhenELIsProvided(t *testing.T) { } func TestTransactionGasWhenELNotProvided(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzer() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzer) // Test regular case block, err := blockAnalyzer.cli.RequestBeaconBlock(8020631) //block number 18826815 @@ -618,24 +614,14 @@ func TestTransactionGasWhenELNotProvided(t *testing.T) { } func TestBlockSizeIsSetWhenELIsProvided(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzerWithEL() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzerWithEL) block, _ := blockAnalyzer.cli.RequestBeaconBlock(5610381) //block number 16442285 assert.Equal(t, block.ExecutionPayload.PayloadSize, uint32(69157)) } func TestBlockSizeNotSetWhenELNotProvided(t *testing.T) { - blockAnalyzer, err := BuildChainAnalyzer() - - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + blockAnalyzer := requireNodes(t, BuildChainAnalyzer) block, _ := blockAnalyzer.cli.RequestBeaconBlock(5610381) //block number 16442285 assert.Equal(t, block.ExecutionPayload.PayloadSize, uint32(0)) @@ -643,11 +629,7 @@ func TestBlockSizeNotSetWhenELNotProvided(t *testing.T) { func TestBlockGasFees(t *testing.T) { - analyzer, err := BuildChainAnalyzer() - if err != nil { - t.Errorf("could not build analyzer: %s", err) - return - } + analyzer := requireNodes(t, BuildChainAnalyzer) block, err := analyzer.cli.RequestBeaconBlock(8790975) if err != nil { diff --git a/pkg/analyzer/process_block.go b/pkg/analyzer/process_block.go index 3f2154a3..3774372d 100644 --- a/pkg/analyzer/process_block.go +++ b/pkg/analyzer/process_block.go @@ -63,7 +63,7 @@ func (s *ChainAnalyzer) ProcessETH1Data(block *spec.AgnosticBlock) { } if block.HardForkVersion >= eth2_client_spec.DataVersionDeneb && s.metrics.BlobSidecars { - s.processBlobSidecars(block, block.ExecutionPayload.AgnosticTransactions) + s.processBlobSidecars(block) } } @@ -212,7 +212,7 @@ func (s *ChainAnalyzer) recoverBlockReceipts(block *spec.AgnosticBlock) { log.Infof("slot %d: recovered %d transaction receipts for fee calculation", block.Slot, len(txs)) } -func (s *ChainAnalyzer) processBlobSidecars(block *spec.AgnosticBlock, txs []spec.AgnosticTransaction) { +func (s *ChainAnalyzer) processBlobSidecars(block *spec.AgnosticBlock) { var blobs []*spec.AgnosticBlobSidecar var err error @@ -226,10 +226,11 @@ func (s *ChainAnalyzer) processBlobSidecars(block *spec.AgnosticBlock, txs []spe log.Errorf("could not download blobs for slot %d: %s", block.Slot, err) } if len(blobs) > 0 { - if len(txs) > 0 { - for _, blob := range blobs { - blob.GetTxHash(txs) - } + // The block's own transaction list, not AgnosticTransactions: the + // latter is filtered by which EL receipts arrived, and a missing + // receipt would cost this slot every one of its blob attributions. + if err := spec.AssignTxHashes(blobs, block.ExecutionPayload.Transactions); err != nil { + log.Errorf("slot %d: could not attribute blob sidecars to transactions: %s", block.Slot, err) } s.dbClient.PersistBlobSidecars(blobs) } diff --git a/pkg/analyzer/process_state.go b/pkg/analyzer/process_state.go index 74bbb25d..0fc8b921 100644 --- a/pkg/analyzer/process_state.go +++ b/pkg/analyzer/process_state.go @@ -17,10 +17,15 @@ var ( // We always provide the epoch we transition to // To process the transition from epoch 9 to 10, we provide 10 and we retrieve 8, 9, 10 -func (s *ChainAnalyzer) ProcessStateTransitionMetrics(epoch phase0.Epoch) { +// ProcessStateTransitionMetrics reports whether it wrote the metrics for this +// epoch. It writes nothing when any of the three states it needs is missing, +// and a caller that deleted the old rows first has to know that happened: +// otherwise the rows are gone, nothing replaced them, and nothing retries +// (migalabs/goteth#291). +func (s *ChainAnalyzer) ProcessStateTransitionMetrics(epoch phase0.Epoch) bool { if !s.metrics.Epoch { - return + return false } routineKey := fmt.Sprintf("%s%d", epochProcesserTag, epoch) @@ -51,7 +56,7 @@ func (s *ChainAnalyzer) ProcessStateTransitionMetrics(epoch phase0.Epoch) { if err != nil { s.processerBook.FreePage(routineKey) log.Errorf("context cancelled waiting for state at epoch %d: %s", epoch-2, err) - return + return false } } if epoch >= 1 && epoch-1 >= phase0.Epoch(s.initSlot/spec.SlotsPerEpoch) { @@ -59,31 +64,29 @@ func (s *ChainAnalyzer) ProcessStateTransitionMetrics(epoch phase0.Epoch) { if err != nil { s.processerBook.FreePage(routineKey) log.Errorf("context cancelled waiting for state at epoch %d: %s", epoch-1, err) - return + return false } } nextState, err = s.downloadCache.StateHistory.Wait(s.ctx, EpochTo[uint64](epoch)) if err != nil { s.processerBook.FreePage(routineKey) log.Errorf("context cancelled waiting for state at epoch %d: %s", epoch, err) - return + return false } bundle, err := metrics.StateMetricsByForkVersion(nextState, currentState, prevState, s.cli.Api) if err != nil { s.processerBook.FreePage(routineKey) log.Errorf("could not parse bundle metrics at epoch: %s", err) - s.stop = true + s.stop.Store(true) s.cancel() - return + return false } // If prevState, currentState and nextState are filled, we can process proposer duties, epoch metrics and validator rewards - // Log the boolean values to see what's happening - log.Infof("Boolean values - !nextState.EmptyStateRoot(): %v, !currentState.EmptyStateRoot(): %v, !prevState.EmptyStateRoot(): %v", - !nextState.EmptyStateRoot(), !currentState.EmptyStateRoot(), !prevState.EmptyStateRoot()) - + wrote := false if !nextState.EmptyStateRoot() && !currentState.EmptyStateRoot() && !prevState.EmptyStateRoot() { + wrote = true s.processEpochDuties(bundle) s.processValLastStatus(bundle) s.processEpochMetrics(bundle) @@ -101,7 +104,7 @@ func (s *ChainAnalyzer) ProcessStateTransitionMetrics(epoch phase0.Epoch) { } s.processerBook.FreePage(routineKey) - + return wrote } func (s *ChainAnalyzer) processSlashings(bundle metrics.StateMetrics) { @@ -238,17 +241,18 @@ func (s *ChainAnalyzer) processValLastStatus(bundle metrics.StateMetrics) { for i, validator := range nextState.Validators { valIdx := phase0.ValidatorIndex(i) newVal := spec.ValidatorLastStatus{ - ValIdx: valIdx, - Epoch: nextState.Epoch, - CurrentBalance: nextState.Balances[valIdx], - EffectiveBalance: validator.EffectiveBalance, - CurrentStatus: nextState.GetValStatus(valIdx), - Slashed: validator.Slashed, - ActivationEpoch: validator.ActivationEpoch, - WithdrawalEpoch: validator.WithdrawableEpoch, - ExitEpoch: validator.ExitEpoch, - PublicKey: validator.PublicKey, - WithdrawalCredentials: validator.WithdrawalCredentials, + ValIdx: valIdx, + Epoch: nextState.Epoch, + CurrentBalance: nextState.Balances[valIdx], + EffectiveBalance: validator.EffectiveBalance, + CurrentStatus: nextState.GetValStatus(valIdx), + Slashed: validator.Slashed, + ActivationEpoch: validator.ActivationEpoch, + ActivationEligibilityEpoch: validator.ActivationEligibilityEpoch, + WithdrawalEpoch: validator.WithdrawableEpoch, + ExitEpoch: validator.ExitEpoch, + PublicKey: validator.PublicKey, + WithdrawalCredentials: validator.WithdrawalCredentials, } valStatusArr = append(valStatusArr, newVal) } @@ -417,7 +421,7 @@ func (s *ChainAnalyzer) getSingleBlockRewards( RewardFees: rewardFees, BurntFees: burntFees, Relays: relayAddresses, - BidCommission: bidCommission, + BidCommission: bidCommission, BuilderPubkeys: builderPubkeys, } } diff --git a/pkg/analyzer/prometheus_metrics.go b/pkg/analyzer/prometheus_metrics.go index fbfdf013..ac8a1b03 100644 --- a/pkg/analyzer/prometheus_metrics.go +++ b/pkg/analyzer/prometheus_metrics.go @@ -25,6 +25,12 @@ var ( Name: "block_queue_length", Help: "The number of blocks int the history queue", }) + DataColumnSubscriptionActive = prometheus.NewGauge(prometheus.GaugeOpts{ + Namespace: strings.ToLower(utils.CliName), + Subsystem: modName, + Name: "data_column_subscription_active", + Help: "1 while the data_column_sidecar SSE subscription is established; blob arrival timings are not recorded while 0", + }) ) func (c *ChainAnalyzer) GetPrometheusMetrics() *metrics.MetricsModule { @@ -36,6 +42,7 @@ func (c *ChainAnalyzer) GetPrometheusMetrics() *metrics.MetricsModule { metricsMod.AddIndvMetric(c.getStateHistoryLength()) metricsMod.AddIndvMetric(c.getBlockHistoryLength()) + metricsMod.AddIndvMetric(c.getDataColumnSubscriptionActive()) return metricsMod } @@ -66,6 +73,39 @@ func (p *ChainAnalyzer) getStateHistoryLength() *metrics.IndvMetrics { return indvMetr } +// getDataColumnSubscriptionActive makes a silent data_column_sidecar +// subscription failure visible: the subscribe path logs and skips instead of +// crashing, so without this gauge an operator could miss that blob arrival +// timings stopped being recorded (the exact silent-loss failure mode of #280). +func (p *ChainAnalyzer) getDataColumnSubscriptionActive() *metrics.IndvMetrics { + + initFn := func() error { + prometheus.MustRegister(DataColumnSubscriptionActive) + return nil + } + + updateFn := func() (interface{}, error) { + active := 0 + if p.eventsObj.SubscribedDataColumns.Load() { + active = 1 + } + DataColumnSubscriptionActive.Set(float64(active)) + return active, nil + } + + indvMetr, err := metrics.NewIndvMetrics( + "data_column_subscription_active", + initFn, + updateFn, + ) + if err != nil { + log.Error(errors.Wrap(err, "unable to init data_column_subscription_active")) + return nil + } + + return indvMetr +} + func (p *ChainAnalyzer) getBlockHistoryLength() *metrics.IndvMetrics { initFn := func() error { diff --git a/pkg/analyzer/reorg.go b/pkg/analyzer/reorg.go index 6990fbf6..bf45efad 100644 --- a/pkg/analyzer/reorg.go +++ b/pkg/analyzer/reorg.go @@ -29,6 +29,8 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { stateKeys := s.downloadCache.StateHistory.GetKeyList() + stateKeys = epochsToVisit(stateKeys, s.pendingReprocess, s.downloadCache.StateHistory.Available) + // Sort keys so we process epochs in ascending order. This guarantees // that when we reach epoch E, we already know whether blocks in // earlier epochs (E-1, E-2) changed and can propagate reprocessing. @@ -36,6 +38,10 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { advance := false epochsWithChangedBlocks := make(map[uint64]bool) + // Epochs whose state object this invocation replaced, by re-download or by + // refreshing its blocks. The rows derived from those states are what goes + // stale, so this, not epochsWithChangedBlocks, is what gets carried. + epochsWithChangedState := make(map[uint64]bool) for _, epoch := range stateKeys { if epoch >= uint64(finalizedEpoch) { @@ -43,6 +49,24 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { } advance = true // only set flag if there is something to do + // Re-added from the carried set above and evicted since. Both the + // block loop and the state root check below Wait on entries that are + // no longer in the cache, so they have to be back before either runs. + if !s.downloadCache.StateHistory.Available(epoch) { + s.ensureDependencyStates(epoch) + + // DownloadState adds the state inline, so still missing here means + // it could not be fetched. Falling through would Wait on it + // forever while holding advanceFinalizedMu, which stops every + // later invocation too - the failure mode this loop already + // documents elsewhere. Count the attempt and move on. + if !s.downloadCache.StateHistory.Available(epoch) { + log.Errorf("carried epoch %d could not be restored to the cache; skipping it this pass", epoch) + s.settleReprocess(epoch, false) + continue + } + } + // --- Step 1: verify block roots FIRST --- // Blocks must be checked before state metrics are (re)processed, // because state processing reads block data (e.g. isFlagPossible @@ -72,10 +96,21 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { if blocksChanged { epochsWithChangedBlocks[epoch] = true + // Refreshing the blocks below rewrites the derived fields of state + // epoch, so record it here rather than after the state root check: + // that check can fail and skip the rest of this iteration. + epochsWithChangedState[epoch] = true // Refresh the state's Blocks array so it points to the newly // downloaded block objects instead of the stale pre-reorg ones. if err := s.downloadCache.RefreshStateBlocks(s.ctx, epoch); err != nil { + // The state still points at the pre-reorg blocks, so anything + // derived from it now would be built on the orphaned chain. + // Carry it rather than rewrite it: the old rows stay, which is + // wrong, but the retry can replace them with correct ones, + // whereas rewriting now records the wrong values as final. log.Errorf("failed to refresh state blocks for epoch %d: %s", epoch, err) + s.settleReprocess(epoch, false) + continue } } @@ -88,6 +123,12 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { finalizedStateRoot, err := s.cli.RequestStateRoot(phase0.Slot(cacheState.Slot)) if err != nil { log.Errorf("could not get state root at slot %d: %s", cacheState.Slot, err) + // This epoch is unresolved: its state may be stale and nothing here + // can tell. Rewriting anyway would derive the rows from what may + // still be the pre-reorg copy, so carry it instead. The loop can + // revisit an evicted epoch now, which is what makes a debt below + // the finalized boundary payable at all. + s.settleReprocess(epoch, false) continue } @@ -100,6 +141,10 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { // nextState (E) — proposer duties, epoch metrics // If blocks changed in any of those epochs, the derived metrics // for epoch E are stale and must be recomputed. + if stateRootChanged { + epochsWithChangedState[epoch] = true + } + needsReprocess := stateRootChanged || blocksChanged if epoch >= 1 && epochsWithChangedBlocks[epoch-1] { needsReprocess = true @@ -107,6 +152,9 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { if epoch >= 2 && epochsWithChangedBlocks[epoch-2] { needsReprocess = true } + if s.carriedEpoch(epoch) { + needsReprocess = true + } if needsReprocess { if stateRootChanged { @@ -132,10 +180,17 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { log.Infof("rewriting metrics for epoch %d (stateRootChanged=%t, blocksChanged=%t, dep=%t)", epoch, stateRootChanged, blocksChanged, (epoch >= 1 && epochsWithChangedBlocks[epoch-1]) || (epoch >= 2 && epochsWithChangedBlocks[epoch-2])) - s.ProcessStateTransitionMetrics(phase0.Epoch(epoch)) + wrote := s.ProcessStateTransitionMetrics(phase0.Epoch(epoch)) + // The rows were deleted just above. If nothing replaced them the + // epoch is a hole, and the debt is what gets it rewritten later. + // Settling only here is the point: clearing it on the way in threw + // the debt away before knowing whether it had been paid (#291). + s.settleReprocess(epoch, wrote) } } + s.carryStaleDependents(epochsWithChangedState, uint64(finalizedEpoch)) + s.downloadCache.CleanUpTo(newFinalizedSlot) if advance { @@ -143,6 +198,120 @@ func (s *ChainAnalyzer) AdvanceFinalized(newFinalizedSlot phase0.Slot) { } } +// epochsToVisit returns the epochs an invocation should examine: everything +// still in the cache, plus any carried debt whose state has been evicted since +// it was recorded. +// +// Without the second half a debt below the finalized boundary could never be +// paid: CleanUpTo evicts those states at the end of the invocation that +// recorded them, so they are absent from GetKeyList on every later pass and the +// loop never visits them again (migalabs/goteth#291). +func epochsToVisit(cached []uint64, pending map[uint64]bool, available func(uint64) bool) []uint64 { + visit := cached + for epoch := range pending { + if !available(epoch) { + visit = append(visit, epoch) + } + } + return visit +} + +// maxReprocessAttempts bounds the retry. A debt still unpaid after this many +// finalized events is not going to be paid by trying again - most often the +// beacon node no longer serves that state - and an unbounded debt would +// re-download and re-delete the same epoch on every finalized event for the +// life of the process. +const maxReprocessAttempts = 3 + +// carriedEpoch reports whether this epoch is owed a reprocess. It does not +// clear the debt: settleReprocess does that, and only once something is known +// to have been written. Clearing it here meant an epoch whose rewrite wrote +// nothing had its rows deleted and its debt forgotten in the same pass (#291). +func (s *ChainAnalyzer) carriedEpoch(epoch uint64) bool { + if !s.pendingReprocess[epoch] { + return false + } + log.Infof("reprocessing epoch %d carried over from an earlier AdvanceFinalized", epoch) + return true +} + +// settleReprocess records the outcome of an attempt to rewrite an epoch. +// +// A successful write clears the debt. A failure keeps it so a later invocation +// retries, up to maxReprocessAttempts, after which the epoch is abandoned with +// an error: its rows are missing, which is at least detectable, and repeating +// the attempt forever would not make them appear. +func (s *ChainAnalyzer) settleReprocess(epoch uint64, wrote bool) { + if s.pendingReprocess == nil { + s.pendingReprocess = make(map[uint64]bool) + } + if s.reprocessAttempts == nil { + s.reprocessAttempts = make(map[uint64]int) + } + + if wrote { + delete(s.pendingReprocess, epoch) + delete(s.reprocessAttempts, epoch) + return + } + + s.reprocessAttempts[epoch]++ + attempts := s.reprocessAttempts[epoch] + if attempts >= maxReprocessAttempts { + delete(s.pendingReprocess, epoch) + delete(s.reprocessAttempts, epoch) + log.Errorf("epoch %d could not be reprocessed after %d attempts; its derived rows are missing and nothing further will retry them", + epoch, maxReprocessAttempts) + return + } + + s.pendingReprocess[epoch] = true + log.Warnf("epoch %d could not be reprocessed (attempt %d of %d); carrying it to the next finalized event", + epoch, attempts, maxReprocessAttempts) +} + +// carryStaleDependents records the epochs whose derived rows this invocation +// made stale but could not rewrite itself. +// +// Replacing the state at epoch E leaves rows belonging to later epochs stale: +// the epoch row for E is written by processing E+1 (ExportToEpoch reads +// CurrentState), and the validator rewards for E+1 and E+2 by processing E+1 +// and E+2, both of which read state E. AdvanceFinalized reprocesses those when +// its loop reaches them, but it skips everything at or past the finalized +// boundary, and the flags that would have marked them do not survive the call, +// so the next invocation no longer knows they are stale. Carrying them is what +// makes a later invocation rewrite them (#285). +// +// The caller passes the epochs whose state object it replaced, whether by +// re-downloading it after a state root mismatch or by refreshing its blocks. +// Both rewrite state E, and it is state E the stale rows derive from. Epochs +// reprocessed only because a predecessor changed do not belong here: their own +// state is untouched, so nothing downstream of them went stale. +// +// Only dependents at or past the boundary are carried, because the loop already +// reached the ones below it in this same invocation and carrying them would +// repeat work. +// +// This used to have a second reason: a debt below the boundary was unpayable, +// since CleanUpTo evicts those states and the loop only iterated what was still +// cached. That no longer holds - epochsToVisit re-adds an evicted debt and +// ensureDependencyStates re-downloads it - so the boundary is now about +// avoiding duplicate work rather than about what can be paid at all. +// +// Callers must hold advanceFinalizedMu. +func (s *ChainAnalyzer) carryStaleDependents(changed map[uint64]bool, finalizedEpoch uint64) { + if s.pendingReprocess == nil { + s.pendingReprocess = make(map[uint64]bool) + } + for epoch := range changed { + for _, dependent := range []uint64{epoch + 1, epoch + 2} { + if dependent >= finalizedEpoch { + s.pendingReprocess[dependent] = true + } + } + } +} + // ensureDependencyStates checks that the states required by // ProcessStateTransitionMetrics (epoch, epoch-1, epoch-2) are present in the // in-memory cache. Any missing state is re-downloaded from the beacon node, @@ -177,7 +346,38 @@ func (s *ChainAnalyzer) ensureDependencyStates(epoch uint64) { } } +// slotBarrierKey and epochBarrierKey build the processerBook keys HandleReorg +// waits on before replacing what a processor may still be reading. +// +// Both take a slot, because HandleReorg walks slots, and the conversion for the +// epoch one belongs here rather than at the call site. Leaving it to the caller +// is exactly how it went wrong: the epoch barrier was built from the raw slot, +// so it asked for "epoch=15096543" while the processor had registered +// "epoch=471766". No such key is ever in the book, so that wait returned +// immediately every time it ran and the state was replaced underneath a live +// reader (migalabs/goteth#292). +func slotBarrierKey(slot phase0.Slot) string { + return fmt.Sprintf("%s%d", slotProcesserTag, uint64(slot)) +} + +func epochBarrierKey(slot phase0.Slot) string { + return fmt.Sprintf("%s%d", epochProcesserTag, uint64(slot)/spec.SlotsPerEpoch) +} + func (s *ChainAnalyzer) HandleReorg(newReorg v1.ChainReorgEvent) { + // Each reorg event fires its own goroutine, and two arriving close together + // walk overlapping slot ranges. Both then call + // ProcessStateTransitionMetrics for the same epoch, which takes two + // processerBook tokens for one key and, before #292, returned only one. + // + // Serialized rather than skipped, which is where this differs from + // AdvanceFinalized: that one is monotonic, so an invocation it drops is + // covered by the next finalized event. A dropped reorg is not covered by + // anything - nothing else rewrites those slots - so the second walk waits + // and then runs against the state the first one left. + s.handleReorgMu.Lock() + defer s.handleReorgMu.Unlock() + depth := newReorg.Depth reorgSlot := newReorg.Slot @@ -186,6 +386,10 @@ func (s *ChainAnalyzer) HandleReorg(newReorg v1.ChainReorgEvent) { cacheHeadBlock := s.downloadCache.GetHeadBlock() i := cacheHeadBlock.Slot + // Epochs whose state the reorg replaced, collected here and rewritten after + // the walk. See rewriteStateMetrics for why not during it. + replaced := make([]phase0.Epoch, 0) + for reorgedSlots <= depth { // for every slot in the reorg block, err := s.downloadCache.BlockHistory.Wait(s.ctx, SlotTo[uint64](i)) // first check that it was already in the cache @@ -196,7 +400,7 @@ func (s *ChainAnalyzer) HandleReorg(newReorg v1.ChainReorgEvent) { if i < reorgSlot && block.Proposed { reorgedSlots += 1 // only count as reorged slot if there was a block porposed and we are not at the reorg slot } - s.processerBook.WaitUntilInactive(fmt.Sprintf("%s%d", slotProcesserTag, i)) // wait until has been processed + s.processerBook.WaitUntilInactive(slotBarrierKey(i)) // wait until has been processed oldBlock := *block s.DownloadBlock(i) // -> inserts into the queue and replaces old block @@ -226,7 +430,7 @@ func (s *ChainAnalyzer) HandleReorg(newReorg v1.ChainReorgEvent) { log.Errorf("context cancelled waiting for state at epoch %d: %s", epoch, err) return } - s.processerBook.WaitUntilInactive(fmt.Sprintf("%s%d", epochProcesserTag, i)) // wait until has been processed + s.processerBook.WaitUntilInactive(epochBarrierKey(i)) oldState := *state s.DownloadState(i) // -> inserts into the queue and replaces old block newState, err := s.downloadCache.StateHistory.Wait(s.ctx, EpochTo[uint64](epoch)) @@ -235,14 +439,82 @@ func (s *ChainAnalyzer) HandleReorg(newReorg v1.ChainReorgEvent) { return } + // Only note it here. Rewriting the metrics now would read the two + // preceding states, which sit at lower slots this walk has not + // reached yet and so are still the pre-reorg copies. if newState.StateRoot != oldState.StateRoot { - s.dbClient.DeleteStateMetrics(epoch) - log.Infof("rewriting metrics for epoch %d", epoch) - // write epoch metrics - s.ProcessStateTransitionMetrics(epoch) + replaced = append(replaced, epoch) } } i -= 1 } + s.rewriteStateMetrics(replaced) +} + +// rewriteStateMetrics rewrites the epoch metrics for every state the reorg +// replaced, once every replacement has been downloaded and in ascending epoch +// order. +// +// Both conditions matter, for different reasons. +// +// The walk above runs backwards, so it reaches a higher epoch before the lower +// ones it derives from. ProcessStateTransitionMetrics(E) reads the states for +// E, E-1 and E-2 out of the cache, so rewriting E during the walk computes it +// from whichever of those the walk has not replaced yet: the stale pre-reorg +// copies. Deferring every rewrite until the walk has finished means each one +// reads states that have all been brought up to date. +// +// Ascending order is the second half. ProcessStateTransitionMetrics already +// waits for epoch-1 to finish before starting, because ProcessAttestations +// writes ManualReward onto block objects that the following epoch reads back +// (goteth#242). Running E before E-1 satisfies that barrier trivially - E-1 has +// not started - and then lets E-1 mutate blocks E has already read. +func (s *ChainAnalyzer) rewriteStateMetrics(epochs []phase0.Epoch) { + // Make sure the states are present before deleting anything. Deferring the + // rewrites until after the walk widened the gap between downloading a state + // and using it, and HandleReorg holds no lock: a concurrent + // AdvanceFinalized can CleanUpTo in between and evict one. Missing states + // would make ProcessStateTransitionMetrics either block forever inside + // StateHistory.Wait, holding processerBook slots (#245), or write nothing + // at all - after the rows had already been deleted. + // + // Ensuring before the delete rather than before the process is what keeps + // that last case from turning into a hole. + ensureThenDelete := func(epoch phase0.Epoch) error { + s.ensureDependencyStates(uint64(epoch)) + return s.dbClient.DeleteStateMetrics(epoch) + } + rewriteInOrder(epochs, ensureThenDelete, s.ProcessStateTransitionMetrics) +} + +// rewriteInOrder deletes and rewrites each epoch's metrics, lowest first, and +// deletes an epoch's rows immediately before rewriting them rather than +// clearing everything up front. Taking the two apart would leave every epoch +// after the first deleted and not yet written, which is the orphaning this +// branch exists to stop, for as long as the rewrites take. +// +// The delete and the process are passed in so the order can be asserted without +// a database or a beacon node. +func rewriteInOrder(epochs []phase0.Epoch, del func(phase0.Epoch) error, process func(phase0.Epoch) bool) { + for _, epoch := range ascendingEpochs(epochs) { + if err := del(epoch); err != nil { + log.Errorf("could not delete metrics for epoch %d before rewriting them: %s", epoch, err) + } + log.Infof("rewriting metrics for epoch %d", epoch) + process(epoch) + } +} + +// ascendingEpochs returns the epochs in the order they must be processed. The +// reorg walk collects them from the head downwards, which is the reverse of the +// order each epoch's inputs become correct in. +// +// It copies rather than sorting in place: the caller's slice records what the +// walk found, and reordering that under it would make the two disagree. +func ascendingEpochs(epochs []phase0.Epoch) []phase0.Epoch { + ordered := make([]phase0.Epoch, len(epochs)) + copy(ordered, epochs) + sort.Slice(ordered, func(i, j int) bool { return ordered[i] < ordered[j] }) + return ordered } diff --git a/pkg/analyzer/reorg_barrier_test.go b/pkg/analyzer/reorg_barrier_test.go new file mode 100644 index 00000000..58eaa6d4 --- /dev/null +++ b/pkg/analyzer/reorg_barrier_test.go @@ -0,0 +1,89 @@ +package analyzer + +import ( + "fmt" + "testing" + + "github.com/attestantio/go-eth2-client/spec/phase0" + "github.com/migalabs/goteth/pkg/spec" + "github.com/migalabs/goteth/pkg/utils" +) + +// HandleReorg replaces the state at the end of an epoch while a processor may +// still be reading it, so it waits for that processor first. It walks slots, +// while ProcessStateTransitionMetrics registers epochs, and the conversion was +// left to the call site and not done: the barrier asked for the slot number +// under the epoch tag. No such key is ever in the book, so the wait returned +// immediately every time it ran (migalabs/goteth#292). + +// The key the processor actually registers, built the way process_state.go +// builds it. If that ever changes, this test fails and says so. +func processorEpochKey(epoch uint64) string { + return fmt.Sprintf("%s%d", epochProcesserTag, epoch) +} + +func processorSlotKey(slot uint64) string { + return fmt.Sprintf("%s%d", slotProcesserTag, slot) +} + +func TestTheEpochBarrierAsksForTheKeyTheProcessorRegistered(t *testing.T) { + const epoch uint64 = 471766 + lastSlot := phase0.Slot((epoch+1)*spec.SlotsPerEpoch - 1) + + got := epochBarrierKey(lastSlot) + want := processorEpochKey(epoch) + + if got != want { + t.Errorf("barrier waits on %q while the processor registered %q; "+ + "the wait matches nothing and the state is replaced under a live reader", + got, want) + } +} + +// Every slot of an epoch must resolve to that epoch's key, not just the last +// one: the barrier runs at the end-of-epoch boundary but the conversion has to +// hold wherever it is called from. +func TestEverySlotOfAnEpochResolvesToItsEpochKey(t *testing.T) { + const epoch uint64 = 100 + want := processorEpochKey(epoch) + + for offset := uint64(0); offset < spec.SlotsPerEpoch; offset++ { + slot := phase0.Slot(epoch*spec.SlotsPerEpoch + offset) + if got := epochBarrierKey(slot); got != want { + t.Fatalf("slot %d gave %q, want %q", slot, got, want) + } + } +} + +func TestTheSlotBarrierAsksForTheSlotKey(t *testing.T) { + const slot uint64 = 15096543 + + if got, want := slotBarrierKey(phase0.Slot(slot)), processorSlotKey(slot); got != want { + t.Errorf("slot barrier waits on %q, want %q", got, want) + } +} + +// The two barriers must not collapse onto one another: a slot key and an epoch +// key are different namespaces, and waiting on the wrong one is the bug. +func TestTheTwoBarriersDoNotShareAKey(t *testing.T) { + slot := phase0.Slot(15096543) + + if slotBarrierKey(slot) == epochBarrierKey(slot) { + t.Error("the slot and epoch barriers built the same key") + } +} + +// End to end through the book: a processor registered for the epoch must be +// visible to the barrier that is meant to wait for it. +func TestTheBarrierSeesALiveProcessor(t *testing.T) { + const epoch uint64 = 471766 + lastSlot := phase0.Slot((epoch+1)*spec.SlotsPerEpoch - 1) + + book := utils.NewRoutineBook(4, "test") + book.Acquire(processorEpochKey(epoch)) + + if !book.CheckPageActive(epochBarrierKey(lastSlot)) { + t.Error("the barrier cannot see the processor holding that epoch, so it " + + "would replace the state while the processor is still reading it") + } +} diff --git a/pkg/analyzer/reorg_order_test.go b/pkg/analyzer/reorg_order_test.go new file mode 100644 index 00000000..9d732067 --- /dev/null +++ b/pkg/analyzer/reorg_order_test.go @@ -0,0 +1,163 @@ +package analyzer + +import ( + "errors" + "testing" + + "github.com/attestantio/go-eth2-client/spec/phase0" +) + +var errDeleteFailed = errors.New("delete failed") + +// HandleReorg walks slots from the head downwards, so it meets a higher epoch +// before the lower ones that epoch derives from. Rewriting in that order +// computes each epoch from predecessors the walk has not corrected yet, so the +// epochs are collected during the walk and ordered before anything is written. + +func TestCollectedEpochsAreRewrittenLowestFirst(t *testing.T) { + // The order a backward walk produces. + walked := []phase0.Epoch{102, 101, 100} + + got := ascendingEpochs(walked) + + want := []phase0.Epoch{100, 101, 102} + for i := range want { + if got[i] != want[i] { + t.Fatalf("processing order %v, want %v", got, want) + } + } +} + +func TestOrderingLeavesTheCollectedSliceAlone(t *testing.T) { + // The caller's slice records what the walk found. Sorting it in place would + // make the record disagree with the walk. + walked := []phase0.Epoch{102, 101, 100} + + ascendingEpochs(walked) + + for i, want := range []phase0.Epoch{102, 101, 100} { + if walked[i] != want { + t.Errorf("the collected slice was reordered: %v", walked) + break + } + } +} + +func TestOrderingHandlesNothingToRewrite(t *testing.T) { + // A reorg that replaced no state at all is the common case: block roots + // changed, state roots did not. + if got := ascendingEpochs(nil); len(got) != 0 { + t.Errorf("got %v, want nothing to rewrite", got) + } + if got := ascendingEpochs([]phase0.Epoch{}); len(got) != 0 { + t.Errorf("got %v, want nothing to rewrite", got) + } +} + +func TestOrderingKeepsEveryEpochItWasGiven(t *testing.T) { + // Dropping one would leave an epoch deleted-but-not-rewritten, which is the + // orphaning this branch exists to stop. + walked := []phase0.Epoch{5, 3, 4, 1, 2} + + got := ascendingEpochs(walked) + + if len(got) != len(walked) { + t.Fatalf("got %d epochs, want %d: %v", len(got), len(walked), got) + } + seen := make(map[phase0.Epoch]bool, len(got)) + for _, e := range got { + seen[e] = true + } + for _, e := range walked { + if !seen[e] { + t.Errorf("epoch %d was collected but would never be rewritten", e) + } + } +} + +func TestOrderingIsAscendingWhateverTheInput(t *testing.T) { + // A reorg spanning several epochs can meet them in any order once the walk + // crosses boundaries, so the ordering must not assume the input is reversed. + for _, input := range [][]phase0.Epoch{ + {1, 2, 3}, + {3, 1, 2}, + {7}, + {9, 9, 8}, + } { + got := ascendingEpochs(input) + for i := 1; i < len(got); i++ { + if got[i-1] > got[i] { + t.Errorf("input %v produced %v, which is not ascending", input, got) + break + } + } + } +} + +// record captures the sequence of operations rewriteInOrder performs, so the +// order and the pairing can be asserted without a database. +type record struct{ steps []string } + +func (r *record) del(e phase0.Epoch) error { + r.steps = append(r.steps, "delete "+epochStr(e)) + return nil +} + +func (r *record) process(e phase0.Epoch) bool { + r.steps = append(r.steps, "process "+epochStr(e)) + return true +} + +func epochStr(e phase0.Epoch) string { + return string(rune('0' + int(e))) +} + +func TestEachEpochIsDeletedImmediatelyBeforeItIsRewritten(t *testing.T) { + // Deleting everything up front would leave every epoch after the first + // deleted and not yet rewritten for as long as the rewrites take, which is + // the orphaning this branch exists to stop. + var r record + + rewriteInOrder([]phase0.Epoch{3, 1, 2}, r.del, r.process) + + want := []string{ + "delete 1", "process 1", + "delete 2", "process 2", + "delete 3", "process 3", + } + if len(r.steps) != len(want) { + t.Fatalf("got %v, want %v", r.steps, want) + } + for i := range want { + if r.steps[i] != want[i] { + t.Fatalf("got %v, want %v", r.steps, want) + } + } +} + +func TestARewriteStillHappensWhenTheDeleteFails(t *testing.T) { + // A failed delete must not skip the rewrite. Skipping would leave the + // pre-reorg rows in place with nothing to correct them, which is the silent + // wrong value this whole change is about. + var processed []phase0.Epoch + failing := func(phase0.Epoch) error { return errDeleteFailed } + + rewriteInOrder([]phase0.Epoch{4}, failing, func(e phase0.Epoch) bool { + processed = append(processed, e) + return true + }) + + if len(processed) != 1 || processed[0] != 4 { + t.Errorf("epoch 4 was not rewritten after its delete failed: %v", processed) + } +} + +func TestNothingIsTouchedWhenNoStateWasReplaced(t *testing.T) { + var r record + + rewriteInOrder(nil, r.del, r.process) + + if len(r.steps) != 0 { + t.Errorf("a reorg that replaced no state still touched the database: %v", r.steps) + } +} diff --git a/pkg/analyzer/reorg_pending_test.go b/pkg/analyzer/reorg_pending_test.go new file mode 100644 index 00000000..7cc24070 --- /dev/null +++ b/pkg/analyzer/reorg_pending_test.go @@ -0,0 +1,180 @@ +package analyzer + +import "testing" + +// AdvanceFinalized rewrites epoch E, which leaves rows derived from E stale: +// the epoch row for E is written by processing E+1, and the validator rewards +// for E+1 and E+2 by processing E+1 and E+2. Epochs at or past the finalized +// boundary are skipped, and the in-function flags that would have marked them +// do not survive the call. Without carrying that debt, nothing ever rewrites +// them (migalabs/goteth#285). + +func TestDependentsBelowTheBoundaryAreNotCarried(t *testing.T) { + // The loop reached them itself, so there is no debt to record. Note the + // second reason this once had - that a debt below the boundary could never + // be paid, because CleanUpTo evicts those states - no longer holds: + // epochsToVisit re-adds an evicted debt and ensureDependencyStates + // re-downloads it. Not carrying these is now purely about not repeating + // work already done in this invocation. + s := &ChainAnalyzer{} + + s.carryStaleDependents(map[uint64]bool{100: true}, 200) + + if len(s.pendingReprocess) != 0 { + t.Errorf("carried %v; those epochs were processed in the same invocation", s.pendingReprocess) + } +} + +func TestDependentsAtTheBoundaryAreCarried(t *testing.T) { + // Blocks changed at 199 while 200 is the first unfinalized epoch, so 200 + // and 201 were skipped and their rows are stale. + s := &ChainAnalyzer{} + + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + for _, epoch := range []uint64{200, 201} { + if !s.pendingReprocess[epoch] { + t.Errorf("epoch %d was not carried; nothing would ever rewrite its rows", epoch) + } + } +} + +func TestOnlyTheUnreachableDependentIsCarried(t *testing.T) { + // 199 is below the boundary and was processed; 200 was not. + s := &ChainAnalyzer{} + + s.carryStaleDependents(map[uint64]bool{198: true}, 200) + + if s.pendingReprocess[199] { + t.Error("199 is below the boundary and was already processed; carrying it repeats work") + } + if !s.pendingReprocess[200] { + t.Error("200 is past the boundary and its rows are stale; it must be carried") + } +} + +// A carried epoch that was actually rewritten must be forgotten. Leaving the +// debt in place would retry it on every finalized event for the life of the +// process. +func TestACarriedEpochIsForgottenOnceItIsWritten(t *testing.T) { + s := &ChainAnalyzer{} + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + if !s.carriedEpoch(200) { + t.Fatal("the carried epoch was not reported as needing reprocessing") + } + s.settleReprocess(200, true) + + if s.carriedEpoch(200) { + t.Error("the same epoch was reported again after being written; the debt was never cleared") + } +} + +// The failure this exists for: the debt used to be cleared when the epoch was +// reached, before anything was known to have been written. A rewrite that wrote +// nothing then left the rows deleted and no debt to retry, so the hole was +// permanent (migalabs/goteth#291). +func TestAnEpochThatWroteNothingKeepsItsDebt(t *testing.T) { + s := &ChainAnalyzer{} + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + if !s.carriedEpoch(200) { + t.Fatal("the carried epoch was not reported as needing reprocessing") + } + s.settleReprocess(200, false) + + if !s.carriedEpoch(200) { + t.Error("the debt was cleared even though nothing was written; " + + "the rows are deleted and nothing will ever rewrite them") + } +} + +// Reading the debt must not clear it, or the caller cannot report an outcome. +func TestReadingTheDebtDoesNotClearIt(t *testing.T) { + s := &ChainAnalyzer{} + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + if !s.carriedEpoch(200) || !s.carriedEpoch(200) { + t.Error("reading the debt cleared it, so a failed rewrite could not carry it forward") + } +} + +// An unpayable debt must not be retried forever: the epoch would be +// re-downloaded and re-deleted on every finalized event for the life of the +// process. It is abandoned loudly instead, leaving a hole, which is detectable. +func TestAnUnpayableDebtIsAbandonedAfterABoundedNumberOfAttempts(t *testing.T) { + s := &ChainAnalyzer{} + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + for attempt := 1; attempt < maxReprocessAttempts; attempt++ { + s.settleReprocess(200, false) + if !s.carriedEpoch(200) { + t.Fatalf("the debt was dropped after %d attempts, before the bound", attempt) + } + } + s.settleReprocess(200, false) + + if s.carriedEpoch(200) { + t.Errorf("the debt survived %d attempts; it would be retried on every "+ + "finalized event forever", maxReprocessAttempts) + } +} + +// A retry that succeeds must reset the count, or an epoch that fails +// intermittently exhausts its budget across unrelated incidents. +func TestASuccessfulRetryResetsTheAttemptCount(t *testing.T) { + s := &ChainAnalyzer{} + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + s.settleReprocess(200, false) + s.settleReprocess(200, true) + + if s.reprocessAttempts[200] != 0 { + t.Errorf("attempt count survived a successful write: %d", s.reprocessAttempts[200]) + } +} + +func TestAnEpochThatWasNeverCarriedIsNotReprocessed(t *testing.T) { + s := &ChainAnalyzer{} + + if s.carriedEpoch(200) { + t.Error("an epoch nothing made stale was queued for reprocessing") + } +} + +// A state root mismatch makes AdvanceFinalized delete and re-download the state +// for that epoch, even when none of its blocks changed. The rows derived from +// that state go stale exactly as they would after a block change, so the carry +// keys on the state having been replaced rather than on the blocks. +func TestAStateReplacedWithoutBlockChangesIsStillCarried(t *testing.T) { + s := &ChainAnalyzer{} + + // What AdvanceFinalized records for an epoch where only the root differed. + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + for _, epoch := range []uint64{200, 201} { + if !s.pendingReprocess[epoch] { + t.Errorf("epoch %d was not carried after the state at 199 was replaced; "+ + "its rows keep pre-reorg values and nothing rewrites them", epoch) + } + } +} + +// Consuming a carried epoch must not enqueue its own dependents: it is being +// reprocessed because a predecessor changed, not because its own blocks did. +// Propagating from it would cascade forward with no end. +func TestSettlingACarriedEpochDoesNotCascade(t *testing.T) { + s := &ChainAnalyzer{} + s.carryStaleDependents(map[uint64]bool{199: true}, 200) + + s.settleReprocess(200, true) + s.settleReprocess(201, true) + + // The consumed epochs are not added to epochsWithChangedBlocks, so the + // next invocation carries nothing on their behalf. + s.carryStaleDependents(map[uint64]bool{}, 202) + + if len(s.pendingReprocess) != 0 { + t.Errorf("settling carried epochs left %v queued", s.pendingReprocess) + } +} diff --git a/pkg/analyzer/reorg_visit_test.go b/pkg/analyzer/reorg_visit_test.go new file mode 100644 index 00000000..ff6d6432 --- /dev/null +++ b/pkg/analyzer/reorg_visit_test.go @@ -0,0 +1,68 @@ +package analyzer + +import ( + "sort" + "testing" +) + +// The loop iterates what GetKeyList returns. A carried epoch whose state was +// evicted by CleanUpTo is not in that list, so before this it was never +// visited again and its debt could not be paid, no matter how many finalized +// events went by (migalabs/goteth#291). + +func inCache(epochs ...uint64) func(uint64) bool { + present := make(map[uint64]bool, len(epochs)) + for _, e := range epochs { + present[e] = true + } + return func(e uint64) bool { return present[e] } +} + +func sorted(in []uint64) []uint64 { + out := append([]uint64(nil), in...) + sort.Slice(out, func(i, j int) bool { return out[i] < out[j] }) + return out +} + +func TestAnEvictedCarriedEpochIsVisitedAgain(t *testing.T) { + got := epochsToVisit([]uint64{300, 301}, map[uint64]bool{200: true}, inCache(300, 301)) + + want := []uint64{200, 300, 301} + if len(got) != len(want) { + t.Fatalf("got %v, want %v; the evicted debt at 200 would never be revisited", sorted(got), want) + } + for i, e := range sorted(got) { + if e != want[i] { + t.Errorf("got %v, want %v", sorted(got), want) + break + } + } +} + +func TestACarriedEpochStillInTheCacheIsNotAddedTwice(t *testing.T) { + // It is already in the key list; adding it again would process it twice in + // one invocation, which is how a processerBook slot leaks (#292). + got := epochsToVisit([]uint64{200, 201}, map[uint64]bool{200: true}, inCache(200, 201)) + + if len(got) != 2 { + t.Errorf("got %v; epoch 200 is in the cache already and was added a second time", sorted(got)) + } +} + +func TestNoDebtMeansNothingIsAdded(t *testing.T) { + got := epochsToVisit([]uint64{200, 201}, nil, inCache(200, 201)) + + if len(got) != 2 { + t.Errorf("got %v, want just the cached epochs", sorted(got)) + } +} + +func TestADebtWithAnEmptyCacheIsStillVisited(t *testing.T) { + // Every state evicted, one debt outstanding: the invocation exists purely + // to pay it, and an empty key list must not mean an empty loop. + got := epochsToVisit(nil, map[uint64]bool{200: true}, inCache()) + + if len(got) != 1 || got[0] != 200 { + t.Errorf("got %v, want [200]", got) + } +} diff --git a/pkg/analyzer/routines.go b/pkg/analyzer/routines.go index 27f601cb..59539567 100644 --- a/pkg/analyzer/routines.go +++ b/pkg/analyzer/routines.go @@ -18,6 +18,7 @@ func (s *ChainAnalyzer) runDownloadBlocks() { defer s.wgDownload.Done() log.Info("Launching Beacon Block Requester") ticker := time.NewTicker(utils.RoutineFlushTimeout) + defer ticker.Stop() // lives as long as the routine; stopped for a clean shutdown downloadRoutine: for { @@ -37,7 +38,7 @@ downloadRoutine: go s.ProcessStateTransitionMetrics(phase0.Epoch(downloadSlot / spec.SlotsPerEpoch)) } case <-ticker.C: // every certain amount of time check if need to finish - if s.stop && len(s.downloadTaskChan) == 0 && s.cli.ActiveReqNum() == 0 && s.processerBook.ActivePages() == 0 { + if s.stop.Load() && len(s.downloadTaskChan) == 0 && s.cli.ActiveReqNum() == 0 && s.processerBook.ActivePages() == 0 { break downloadRoutine } } @@ -78,8 +79,9 @@ func (s *ChainAnalyzer) runHead() { s.eventsObj.SubscribeToHeadEvents() s.eventsObj.SubscribeToFinalizedCheckpointEvents() s.eventsObj.SubscribeToReorgsEvents() - s.eventsObj.SubscribeToBlobSidecarsEvents() + s.eventsObj.SubscribeToDataColumnSidecarsEvents() ticker := time.NewTicker(utils.RoutineFlushTimeout) + defer ticker.Stop() // lives as long as the routine; stopped for a clean shutdown // loop over the list of slots that we need to analyze for { @@ -117,15 +119,12 @@ func (s *ChainAnalyzer) runHead() { s.dbClient.PersistReorgs([]v1.ChainReorgEvent{newReorg}) go s.HandleReorg(newReorg) - case newBlobSidecarEvent := <-s.eventsObj.BlobSidecarChan: - s.dbClient.PersistBlobSidecarsEvents([]spec.BlobSideCarEventWraper{newBlobSidecarEvent}) - case <-s.ctx.Done(): log.Info("context has died, closing block requester routine") return case <-ticker.C: - if s.stop { + if s.stop.Load() { log.Info("sudden shutdown detected, block downloader routine") return } @@ -134,6 +133,104 @@ func (s *ChainAnalyzer) runHead() { } } +// dataColumnMaxBatch flushes as soon as one full-custody per-slot burst +// (NUMBER_OF_COLUMNS = 128) has accumulated, without waiting for the ticker. +const dataColumnMaxBatch = 128 + +// runDataColumnSidecarsPersister drains DataColumnSidecarChan and persists the +// events in batches, off the head loop. Under PeerDAS a full-custody node emits +// up to 128 data_column_sidecar events per slot; persisting them one by one from +// runHead meant one synchronous ClickHouse INSERT per event on the same loop +// that dispatches block downloads (#282). +func (s *ChainAnalyzer) runDataColumnSidecarsPersister() { + defer s.wgMainRoutine.Done() + log.Info("launching data column sidecars persister routine") + + ticker := time.NewTicker(utils.RoutineFlushTimeout) + defer ticker.Stop() + + batchDataColumnSidecarEvents( + s.eventsObj.DataColumnSidecarChan, + ticker.C, + s.ctx.Done(), + func() bool { return s.stop.Load() }, + dataColumnMaxBatch, + func(batch []spec.DataColumnSidecarEventWrapper) { + if err := s.dbClient.PersistDataColumnSidecarsEvents(batch); err != nil { + log.Errorf("error persisting data column sidecar events batch: %s", err) + } + }, + ) + + log.Info("data column sidecars persister routine finished") +} + +// batchDataColumnSidecarEvents accumulates events from the channel and flushes +// them in batches: immediately when maxBatch is reached, and on every tick when +// the buffer is non-empty. It returns when done fires or when stopped() reports +// true on a tick; in both cases it first drains whatever sits in the channel and +// does a best-effort final flush (on the done path the write can fail if the DB +// context is already cancelled, which the flush callback logs). +func batchDataColumnSidecarEvents( + events <-chan spec.DataColumnSidecarEventWrapper, + tick <-chan time.Time, + done <-chan struct{}, + stopped func() bool, + maxBatch int, + flush func([]spec.DataColumnSidecarEventWrapper), +) { + buffer := make([]spec.DataColumnSidecarEventWrapper, 0, maxBatch) + + // Reusing the backing array is safe: the persist path copies every value + // into its insert columns before returning. + flushBuffer := func() { + if len(buffer) == 0 { + return + } + flush(buffer) + buffer = buffer[:0] + } + + // drain moves everything currently sitting in the channel into the buffer, + // flushing at maxBatch so the final batches stay bounded. + drain := func() { + for { + select { + case ev := <-events: + buffer = append(buffer, ev) + if len(buffer) >= maxBatch { + flushBuffer() + } + default: + return + } + } + } + + for { + select { + case ev := <-events: + buffer = append(buffer, ev) + if len(buffer) >= maxBatch { + flushBuffer() + } + + case <-tick: + flushBuffer() + if stopped() { + drain() + flushBuffer() + return + } + + case <-done: + drain() + flushBuffer() + return + } + } +} + func (s *ChainAnalyzer) fillToHead() phase0.Slot { // ------ fill from last epoch in database to current head ------- @@ -196,7 +293,7 @@ func (s *ChainAnalyzer) fillToHead() phase0.Slot { // runHistorical again — and since the chain keeps advancing, // handoffThreshold is always exceeded and the loop spins // indefinitely on shutdown. - if s.stop { + if s.stop.Load() { return headSlot } @@ -218,14 +315,16 @@ func (s *ChainAnalyzer) runHistorical(init phase0.Slot, end phase0.Slot) { i := init for i <= end { - if s.stop { + if s.stop.Load() { log.Info("sudden shutdown detected, block downloader routine") return } if s.processerBook.NumFreePages() == 0 { log.Debugf("hit limit of concurrent processers") - limitTicker := time.NewTicker(utils.RoutineFlushTimeout) - <-limitTicker.C // if rate limit, wait for ticker + // One-shot wait, so a sleep rather than a ticker nothing stops. + // This is the rate-limit path, so it fires exactly when the node is + // already under load and the leaks accumulate fastest. + time.Sleep(utils.RoutineFlushTimeout) continue } if i%spec.SlotsPerEpoch == 0 { // every time a new epoch is crossed diff --git a/pkg/analyzer/routines_test.go b/pkg/analyzer/routines_test.go new file mode 100644 index 00000000..6a517ae5 --- /dev/null +++ b/pkg/analyzer/routines_test.go @@ -0,0 +1,166 @@ +package analyzer + +import ( + "sync" + "testing" + "time" + + "github.com/migalabs/goteth/pkg/spec" +) + +// flushRecorder is a thread-safe fake flush target for +// batchDataColumnSidecarEvents. It records call and row counts only; the +// batch slice itself is reused by the batcher and must not be retained. +type flushRecorder struct { + mu sync.Mutex + calls int + rows int +} + +func (r *flushRecorder) flush(batch []spec.DataColumnSidecarEventWrapper) { + r.mu.Lock() + defer r.mu.Unlock() + r.calls++ + r.rows += len(batch) +} + +func (r *flushRecorder) snapshot() (calls int, rows int) { + r.mu.Lock() + defer r.mu.Unlock() + return r.calls, r.rows +} + +// waitFor polls cond until it is true or the timeout expires. +func waitFor(t *testing.T, timeout time.Duration, cond func() bool, msg string) { + t.Helper() + deadline := time.Now().Add(timeout) + for time.Now().Before(deadline) { + if cond() { + return + } + time.Sleep(2 * time.Millisecond) + } + t.Fatalf("timed out waiting for: %s", msg) +} + +type batcherHarness struct { + events chan spec.DataColumnSidecarEventWrapper + tick chan time.Time + done chan struct{} + stopped func() bool + rec *flushRecorder + finished chan struct{} +} + +func startBatcher(maxBatch int, stopped func() bool) *batcherHarness { + h := &batcherHarness{ + events: make(chan spec.DataColumnSidecarEventWrapper, 1024), + tick: make(chan time.Time), + done: make(chan struct{}), + stopped: stopped, + rec: &flushRecorder{}, + finished: make(chan struct{}), + } + go func() { + batchDataColumnSidecarEvents(h.events, h.tick, h.done, h.stopped, maxBatch, h.rec.flush) + close(h.finished) + }() + return h +} + +func (h *batcherHarness) sendEvents(n int) { + for i := 0; i < n; i++ { + h.events <- spec.DataColumnSidecarEventWrapper{Timestamp: time.Now()} + } +} + +func (h *batcherHarness) waitFinished(t *testing.T) { + t.Helper() + select { + case <-h.finished: + case <-time.After(2 * time.Second): + t.Fatal("batcher did not return") + } +} + +// A burst larger than maxBatch flushes in maxBatch-sized batches without any +// tick, and the tick then flushes the remainder: far fewer flushes than events. +func TestBatchDataColumnEventsFlushesAtMaxBatch(t *testing.T) { + h := startBatcher(128, func() bool { return false }) + h.sendEvents(300) + + // The two full 128-event batches flush without any tick. + waitFor(t, time.Second, func() bool { _, rows := h.rec.snapshot(); return rows == 256 }, + "two maxBatch flushes (256 rows)") + + // Wait until the loop has consumed the whole burst, then tick to flush the + // remaining 44 (sending the tick earlier could reach the select while part + // of the burst still sits in the channel, splitting the last flush). + waitFor(t, time.Second, func() bool { return len(h.events) == 0 }, "channel drained") + h.tick <- time.Time{} + waitFor(t, time.Second, func() bool { _, rows := h.rec.snapshot(); return rows == 300 }, + "tick flush of the remainder (300 rows total)") + + calls, rows := h.rec.snapshot() + if rows != 300 { + t.Fatalf("expected 300 rows flushed, got %d", rows) + } + if calls != 3 { + t.Fatalf("expected 3 flush calls (128+128+44), got %d", calls) + } + + close(h.done) + h.waitFinished(t) +} + +// A partial buffer is flushed once per tick, not once per event. +func TestBatchDataColumnEventsTickFlushesPartialBuffer(t *testing.T) { + h := startBatcher(128, func() bool { return false }) + h.sendEvents(5) + + // Once the channel is empty every sent event is either appended already or + // being appended by the current loop iteration; the blocking tick send below + // is only received after that iteration finishes. + waitFor(t, time.Second, func() bool { return len(h.events) == 0 }, "channel drained") + h.tick <- time.Time{} + + waitFor(t, time.Second, func() bool { calls, rows := h.rec.snapshot(); return calls == 1 && rows == 5 }, + "single flush of 5 rows") + + close(h.done) + h.waitFinished(t) +} + +// When stopped() reports true on a tick, pending channel events are drained and +// flushed before returning. +func TestBatchDataColumnEventsStopDrainsChannel(t *testing.T) { + var mu sync.Mutex + stop := false + setStop := func(v bool) { mu.Lock(); stop = v; mu.Unlock() } + getStop := func() bool { mu.Lock(); defer mu.Unlock(); return stop } + + h := startBatcher(128, getStop) + h.sendEvents(10) + setStop(true) + h.tick <- time.Time{} + + h.waitFinished(t) + _, rows := h.rec.snapshot() + if rows != 10 { + t.Fatalf("expected all 10 rows flushed on stop, got %d", rows) + } +} + +// When done fires, pending channel events are drained and flushed before +// returning. +func TestBatchDataColumnEventsDoneDrainsChannel(t *testing.T) { + h := startBatcher(128, func() bool { return false }) + h.sendEvents(7) + close(h.done) + + h.waitFinished(t) + _, rows := h.rec.snapshot() + if rows != 7 { + t.Fatalf("expected all 7 rows flushed on done, got %d", rows) + } +} diff --git a/pkg/clientapi/blob.go b/pkg/clientapi/blob.go index ce87d010..6e77e113 100644 --- a/pkg/clientapi/blob.go +++ b/pkg/clientapi/blob.go @@ -19,7 +19,7 @@ func (s *APIClient) RequestBlobSidecars(slot phase0.Slot) ([]*local_spec.Agnosti }) if err != nil { - if response404(err.Error()) { + if isNotFound(err) { return agnosticBlobs, nil } return nil, fmt.Errorf("could not retrieve blob sidecars for slot %d: %s", slot, err) @@ -47,7 +47,7 @@ func (s *APIClient) requestKZGCommitmentFromSignedBlock(slot phase0.Slot) ([]den }) if err != nil { - if response404(err.Error()) { + if isNotFound(err) { return nil, nil } return nil, fmt.Errorf("could not retrieve KZGCommitments for slot %d: %s", slot, err) @@ -65,7 +65,7 @@ func (s *APIClient) RequestFuluBlobs(slot phase0.Slot) ([]*local_spec.AgnosticBl }) if err != nil { - if response404(err.Error()) { + if isNotFound(err) { return blobs, nil } return nil, fmt.Errorf("could not retrieve blobs for slot %d: %s", slot, err) diff --git a/pkg/clientapi/block.go b/pkg/clientapi/block.go index c082abeb..868e2334 100644 --- a/pkg/clientapi/block.go +++ b/pkg/clientapi/block.go @@ -3,7 +3,6 @@ package clientapi import ( "errors" "fmt" - "strings" "time" "github.com/attestantio/go-eth2-client/api" @@ -41,7 +40,7 @@ func (s *APIClient) RequestBeaconBlock(slot phase0.Slot) (*local_spec.AgnosticBl Block: fmt.Sprintf("%d", slot), }) if err != nil { - if response404(err.Error()) { + if isNotFound(err) { if attempts < s.maxRetries-1 { // Retry on 404: with Lighthouse v8.1.0+ the Head SSE event can // fire before the block is queryable via the API. @@ -55,9 +54,11 @@ func (s *APIClient) RequestBeaconBlock(slot phase0.Slot) (*local_spec.AgnosticBl } timeoutTime := utils.RoutineFlushTimeout * time.Duration(attempts+1) - ticker := time.NewTicker(timeoutTime) log.Warnf("retrying request: %s. Attempt number: %d", routineKey, attempts) - <-ticker.C + // A plain sleep, like the 404 retry above. A ticker here was never + // stopped, so every retry left one waking the runtime once a second + // for the life of the process. + time.Sleep(timeoutTime) } attempts += 1 @@ -122,7 +123,7 @@ func (s *APIClient) RequestBlockRoot(slot phase0.Slot) phase0.Root { Block: fmt.Sprintf("%d", slot), }) if err != nil { - if strings.Contains(err.Error(), "404") { + if isNotFound(err) { // block was not found => block does not exist return phase0.Root{} } diff --git a/pkg/clientapi/state.go b/pkg/clientapi/state.go index b706161b..ff8aca3a 100644 --- a/pkg/clientapi/state.go +++ b/pkg/clientapi/state.go @@ -47,9 +47,9 @@ func (s *APIClient) requestBeaconStateWithID(slot phase0.Slot, stateID string, k }) if errors.Is(err, context.DeadlineExceeded) { - ticker := time.NewTicker(utils.RoutineFlushTimeout) log.Warnf("retrying request: %s", routineKey) - <-ticker.C + // One-shot wait, so a sleep rather than a ticker nothing stops. + time.Sleep(utils.RoutineFlushTimeout) } attempts += 1 diff --git a/pkg/clientapi/transaction.go b/pkg/clientapi/transaction.go index 9ea20ac4..2f91d95a 100644 --- a/pkg/clientapi/transaction.go +++ b/pkg/clientapi/transaction.go @@ -84,9 +84,9 @@ func (s *APIClient) GetTransactionReceipt(iTx bellatrix.Transaction, receipt, err = s.ELApi.TransactionReceipt(s.ctx, parsedTx.Hash()) if err != nil { - ticker := time.NewTicker(utils.RoutineFlushTimeout) log.Warnf("retrying transaction request: %s", parsedTx.Hash().String()) - <-ticker.C + // One-shot wait, so a sleep rather than a ticker nothing stops. + time.Sleep(utils.RoutineFlushTimeout) } attempts += 1 diff --git a/pkg/clientapi/utils.go b/pkg/clientapi/utils.go index 8ba1f9a9..9f1a302f 100644 --- a/pkg/clientapi/utils.go +++ b/pkg/clientapi/utils.go @@ -1,11 +1,38 @@ package clientapi -import "strings" +import ( + "errors" + "net/http" -const ( - missingData = "404" + "github.com/attestantio/go-eth2-client/api" ) -func response404(err string) bool { - return strings.Contains(err, missingData) +// isNotFound reports whether a beacon API call failed because the resource +// does not exist, as opposed to failing to reach the node at all. +// +// It asks the error for its status code rather than searching the rendered +// message for "404". The message is not a safe place to look: the beacon node +// is addressed by slot, so on a transport failure go-eth2-client joins in the +// error from net/http, which carries the full request URL. Every slot whose +// decimal form contains "404" (about one in two hundred) then produced a +// message matching a substring search, and an unreachable node was recorded as +// a missing block instead of being retried. The port, the peer address and any +// hex root echoed back in an error body could do the same. +// +// go-eth2-client declares Error() on the value receiver, so both api.Error and +// *api.Error satisfy the error interface. It returns the pointer form today; +// both are matched here so that changing which one is returned cannot quietly +// turn every genuine 404 into a retry loop. +func isNotFound(err error) bool { + var apiErr *api.Error + if errors.As(err, &apiErr) { + return apiErr.StatusCode == http.StatusNotFound + } + + var apiErrValue api.Error + if errors.As(err, &apiErrValue) { + return apiErrValue.StatusCode == http.StatusNotFound + } + + return false } diff --git a/pkg/clientapi/utils_test.go b/pkg/clientapi/utils_test.go new file mode 100644 index 00000000..3b6080dd --- /dev/null +++ b/pkg/clientapi/utils_test.go @@ -0,0 +1,169 @@ +package clientapi + +import ( + "errors" + "fmt" + "net" + nethttp "net/http" + "net/url" + "strings" + "testing" + + "github.com/attestantio/go-eth2-client/api" +) + +// apiError builds the error go-eth2-client returns for a non-2xx response. +// It constructs the pointer form because that is what http.go returns. +func apiError(status int, body string) error { + return &api.Error{ + Method: nethttp.MethodGet, + StatusCode: status, + Endpoint: "/eth/v2/beacon/blocks/12345", + Data: []byte(body), + } +} + +// transportError builds the error go-eth2-client returns when the request +// never reached the node: it joins its own note to the error from net/http, +// which is a *url.Error carrying the full request URL. The slot is in that URL +// because blocks are addressed by slot. +// +// TestTransportErrorMatchesARealFailedRequest proves this construction still +// matches what a real failed request produces. +func transportError(slot string) error { + return errors.Join( + errors.New("failed to call GET endpoint"), + &url.Error{ + Op: "Get", + URL: "http://beacon:5052/eth/v2/beacon/blocks/" + slot, + Err: errors.New("dial tcp 10.0.0.5:5052: connect: connection refused"), + }, + ) +} + +// A missing block is the one case that may be recorded as missing. Everything +// else has to stay an error so the caller retries. +func TestIsNotFoundAcceptsOnlyAGenuine404(t *testing.T) { + for _, tc := range []struct { + name string + err error + want bool + }{ + {"a 404 with no body", apiError(404, ""), true}, + {"a 404 with the node's body", apiError(404, `{"code":404,"message":"NOT_FOUND: beacon block"}`), true}, + {"a 500", apiError(500, `{"code":500,"message":"internal error"}`), false}, + {"a 503 while syncing", apiError(503, `{"code":503,"message":"syncing"}`), false}, + {"a 400", apiError(400, `{"code":400,"message":"invalid block ID"}`), false}, + {"no error at all", nil, false}, + {"an unrelated error", errors.New("something went wrong"), false}, + } { + t.Run(tc.name, func(t *testing.T) { + if got := isNotFound(tc.err); got != tc.want { + t.Fatalf("isNotFound(%v) = %v, want %v", tc.err, got, tc.want) + } + }) + } +} + +// These are the cases the previous implementation got wrong. It searched the +// rendered message for the substring "404", and the slot is part of the +// request URL, so an unreachable beacon node was reported as a missing block +// for roughly one slot in two hundred. Each of these returned true before the +// fix and must return false now. +func TestIsNotFoundIgnoresA404ThatIsNotAStatusCode(t *testing.T) { + for _, tc := range []struct { + name string + err error + }{ + {"the node is unreachable while fetching slot 404", transportError("404")}, + {"the node is unreachable while fetching slot 4040", transportError("4040")}, + {"the node is unreachable while fetching slot 1404000", transportError("1404000")}, + {"a 500 whose body names slot 4040", apiError(500, `{"code":500,"message":"error processing slot 4040"}`)}, + {"a 500 whose body names a root containing 404", apiError(500, `{"message":"bad root 0x404a1b"}`)}, + {"a timeout on a 404-shaped slot", errors.Join( + errors.New("failed to call GET endpoint"), + &url.Error{Op: "Get", URL: "http://beacon:5052/eth/v2/beacon/blocks/404", Err: errors.New("context deadline exceeded")}, + )}, + } { + t.Run(tc.name, func(t *testing.T) { + if !strings.Contains(tc.err.Error(), "404") { + t.Fatalf("this case is meant to contain the substring 404 but does not: %v", tc.err) + } + if isNotFound(tc.err) { + t.Errorf("isNotFound reported a missing block for a failure that is not a 404: %v", tc.err) + } + }) + } +} + +// The error reaches isNotFound through whatever the call stack wrapped it in, +// so the status has to be found through the chain rather than only at the top. +func TestIsNotFoundLooksThroughWrapping(t *testing.T) { + notFound := apiError(404, "") + + for _, tc := range []struct { + name string + err error + }{ + {"fmt.Errorf with %w", fmt.Errorf("downloading block at slot 12345: %w", notFound)}, + {"two levels deep", fmt.Errorf("epoch 380: %w", fmt.Errorf("slot 12345: %w", notFound))}, + {"joined with another error", errors.Join(errors.New("failed to call GET endpoint"), notFound)}, + } { + t.Run(tc.name, func(t *testing.T) { + if !isNotFound(tc.err) { + t.Errorf("isNotFound did not find the 404 through the wrapping: %v", tc.err) + } + }) + } +} + +// go-eth2-client declares Error() on the value receiver, so api.Error and +// *api.Error both satisfy the error interface. It returns the pointer today. +// If that ever changes, a check that matched only the pointer would stop +// recognising any 404 and every missing slot would retry to exhaustion, so +// both forms are accepted. +func TestIsNotFoundAcceptsTheValueFormOfTheError(t *testing.T) { + byValue := api.Error{Method: nethttp.MethodGet, StatusCode: 404} + if !isNotFound(byValue) { + t.Error("isNotFound did not recognise a 404 delivered as a value rather than a pointer") + } + + byValueOther := api.Error{Method: nethttp.MethodGet, StatusCode: 500} + if isNotFound(byValueOther) { + t.Error("isNotFound accepted a 500 delivered as a value") + } +} + +// transportError above is a hand-built stand-in for what net/http produces. +// This makes a request that really fails and checks the stand-in still matches +// it: same error text shape, same answer from isNotFound. Without this the +// other tests could drift into asserting against a fiction. +// +// The request goes to a closed port on the loopback interface, so it needs no +// network and cannot reach anything. +func TestTransportErrorMatchesARealFailedRequest(t *testing.T) { + listener, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Skipf("could not reserve a local port: %s", err) + } + addr := listener.Addr().String() + listener.Close() + + _, realErr := nethttp.Get(fmt.Sprintf("http://%s/eth/v2/beacon/blocks/404", addr)) + if realErr == nil { + t.Skip("the request unexpectedly succeeded; something is listening on the reserved port") + } + joined := errors.Join(errors.New("failed to call GET endpoint"), realErr) + + if !strings.Contains(joined.Error(), "404") { + t.Fatalf("a real transport failure for slot 404 no longer carries the slot, so the bug this guards has changed shape: %v", joined) + } + if isNotFound(joined) { + t.Errorf("isNotFound reported a missing block for a real transport failure: %v", joined) + } + + var urlErr *url.Error + if !errors.As(realErr, &urlErr) { + t.Errorf("net/http no longer returns a *url.Error, so transportError() is no longer faithful: %T", realErr) + } +} diff --git a/pkg/config/defaults.go b/pkg/config/defaults.go index 5f77268f..8a03f867 100644 --- a/pkg/config/defaults.go +++ b/pkg/config/defaults.go @@ -18,6 +18,7 @@ var ( DefaultPrometheusPort int = 9080 DefaultValidatorWindowEpochs int = 100 DefaultValidatorWindowDeleteCadence int = 32 + DefaultValidatorWindowPoolReroll int = 0 DefaultMaxRequestRetries int = 3 DefaultBeaconContractAddress string = "mainnet" ) diff --git a/pkg/config/validator_window.go b/pkg/config/validator_window.go index 35dca2cd..850d4029 100644 --- a/pkg/config/validator_window.go +++ b/pkg/config/validator_window.go @@ -9,6 +9,7 @@ type ValidatorWindowConfig struct { DBUrl string `json:"db-url"` NumEpochs int `json:"num-epochs"` DeleteCadenceEpochs int `json:"delete-cadence-epochs"` + PoolRerollEpochs int `json:"pool-reroll-epochs"` BnEndpoint string `json:"bn-endpoint"` BnApiKey string `json:"bn-api-key"` MaxRequestRetries int `json:"max-request-retries"` @@ -22,6 +23,7 @@ func NewValidatorWindowConfig() *ValidatorWindowConfig { DBUrl: DefaultDBUrl, NumEpochs: DefaultValidatorWindowEpochs, DeleteCadenceEpochs: DefaultValidatorWindowDeleteCadence, + PoolRerollEpochs: DefaultValidatorWindowPoolReroll, BnEndpoint: DefaultBnEndpoint, MaxRequestRetries: DefaultMaxRequestRetries, BnApiKey: DefaultBnApiKey, @@ -46,6 +48,10 @@ func (c *ValidatorWindowConfig) Apply(ctx *cli.Context) { if ctx.IsSet("delete-cadence-epochs") { c.DeleteCadenceEpochs = ctx.Int("delete-cadence-epochs") } + // pool summary reroll window (0 disables the automatic refresh) + if ctx.IsSet("pool-reroll-epochs") { + c.PoolRerollEpochs = ctx.Int("pool-reroll-epochs") + } // cl url if ctx.IsSet("bn-endpoint") { c.BnEndpoint = ctx.String("bn-endpoint") diff --git a/pkg/db/blob_events.go b/pkg/db/blob_events.go index a9d700c8..ddd09cc7 100644 --- a/pkg/db/blob_events.go +++ b/pkg/db/blob_events.go @@ -6,55 +6,60 @@ import ( ) var ( - blobEventsTable = "t_blob_sidecars_events" - insertBlobSideCarsEventsQuery = ` + dataColumnEventsTable = "t_data_column_sidecars_events" + insertDataColumnSidecarsEventsQuery = ` INSERT INTO %s ( f_arrival_timestamp_ms, - f_blob_hash, f_slot, f_block_root, - f_index, - f_kzg_commitment) + f_column_index, + f_kzg_commitments, + f_num_commitments) VALUES` ) -func blobSidecarsEventInput(blobSidecarsEvents []spec.BlobSideCarEventWraper) proto.Input { +func dataColumnSidecarsEventInput(events []spec.DataColumnSidecarEventWrapper) proto.Input { // one object per column var ( f_arrival_timestamp_ms proto.ColUInt64 - f_blob_hash proto.ColStr f_slot proto.ColUInt64 f_block_root proto.ColStr - f_index proto.ColUInt8 - f_kzg_commitment proto.ColStr + f_column_index proto.ColUInt16 + f_kzg_commitments = proto.NewArray[string](new(proto.ColStr)) + f_num_commitments proto.ColUInt16 ) - for _, blobSidecar := range blobSidecarsEvents { + for _, ev := range events { + commitments := make([]string, 0, len(ev.DataColumnSidecarEvent.KZGCommitments)) + for _, c := range ev.DataColumnSidecarEvent.KZGCommitments { + commitments = append(commitments, c.String()) + } - f_arrival_timestamp_ms.Append(uint64(blobSidecar.Timestamp.UnixMilli())) - f_blob_hash.Append(blobSidecar.BlobSidecarEvent.VersionedHash.String()) - f_slot.Append(uint64(blobSidecar.BlobSidecarEvent.Slot)) - f_block_root.Append(blobSidecar.BlobSidecarEvent.BlockRoot.String()) - f_index.Append(uint8(blobSidecar.BlobSidecarEvent.Index)) - f_kzg_commitment.Append(blobSidecar.BlobSidecarEvent.KZGCommitment.String()) + f_arrival_timestamp_ms.Append(uint64(ev.Timestamp.UnixMilli())) + f_slot.Append(uint64(ev.DataColumnSidecarEvent.Slot)) + f_block_root.Append(ev.DataColumnSidecarEvent.BlockRoot.String()) + f_column_index.Append(uint16(ev.DataColumnSidecarEvent.Index)) + f_kzg_commitments.Append(commitments) + // Denormalised so "how many blobs did this block carry" does not have to + // unnest the array on a table that takes ~128 rows per slot. + f_num_commitments.Append(uint16(len(commitments))) } return proto.Input{ - {Name: "f_arrival_timestamp_ms", Data: f_arrival_timestamp_ms}, - {Name: "f_blob_hash", Data: f_blob_hash}, {Name: "f_slot", Data: f_slot}, {Name: "f_block_root", Data: f_block_root}, - {Name: "f_index", Data: f_index}, - {Name: "f_kzg_commitment", Data: f_kzg_commitment}, + {Name: "f_column_index", Data: f_column_index}, + {Name: "f_kzg_commitments", Data: f_kzg_commitments}, + {Name: "f_num_commitments", Data: f_num_commitments}, } } -func (p *DBService) PersistBlobSidecarsEvents(data []spec.BlobSideCarEventWraper) error { - persistObj := PersistableObject[spec.BlobSideCarEventWraper]{ - input: blobSidecarsEventInput, - table: blobEventsTable, - query: insertBlobSideCarsEventsQuery, +func (p *DBService) PersistDataColumnSidecarsEvents(data []spec.DataColumnSidecarEventWrapper) error { + persistObj := PersistableObject[spec.DataColumnSidecarEventWrapper]{ + input: dataColumnSidecarsEventInput, + table: dataColumnEventsTable, + query: insertDataColumnSidecarsEventsQuery, } for _, item := range data { @@ -63,7 +68,7 @@ func (p *DBService) PersistBlobSidecarsEvents(data []spec.BlobSideCarEventWraper err := p.Persist(persistObj.ExportPersist()) if err != nil { - log.Errorf("error persisting blob events: %s", err.Error()) + log.Errorf("error persisting data column events: %s", err.Error()) } return err } diff --git a/pkg/db/epoch_metrics.go b/pkg/db/epoch_metrics.go index ce55b546..ea967d06 100644 --- a/pkg/db/epoch_metrics.go +++ b/pkg/db/epoch_metrics.go @@ -202,64 +202,75 @@ func (p *DBService) RetrieveLastEpoch() (phase0.Epoch, error) { } -// delete metrics that use the state at epoch x -func (s *DBService) DeleteStateMetrics(epoch phase0.Epoch) error { - var err error - - // epochs are written at currentState using current state and nextState - err = s.Delete(DeletableObject{ - query: deleteEpochsQuery, - table: epochsTable, - args: []any{epoch - 1}, - }) // when deleteState -> nextState - - if err != nil { - return err +// DeleteStateMetrics removes rows ahead of ProcessStateTransitionMetrics(epoch) +// rewriting them. Every row it deletes must be one that the same call writes +// back; deleting anything else leaves a hole nothing fills. +// +// ProcessStateTransitionMetrics(E) writes the epoch row for E-1 (ExportToEpoch +// uses CurrentState.Epoch), the proposer duties for E and the validator rewards +// for E (both use NextState.Epoch). It writes nothing for E's own epoch row, +// nor for the rewards of E+1 and E+2: those belong to the processing of E+1 and +// E+2. +// +// The reverse does not hold, and is not required here. That call also writes +// slashings, deposits, consolidations, withdrawal and deposit requests, +// validator last status, block rewards and pool metrics, none of which are +// deleted first. Those are left as they were before this change. +// +// This used to delete those three as well. When the changed epoch sat close to +// the finalized boundary, AdvanceFinalized skipped E+1 and E+2 (they are not +// below finalizedEpoch yet) and nothing ever rewrote them, leaving permanent +// holes: epoch_metrics(E) absent with E-1 and E+1 present, and +// t_validator_rewards_summary empty for E+1 and E+2. Six such holes were live +// on mainnet, all matching that signature exactly (migalabs/goteth#285). +// +// Rows belonging to E+1 and E+2 are deleted and rewritten when those epochs are +// processed, which AdvanceFinalized now guarantees by carrying them over to a +// later invocation if it cannot reach them in this one. +// EpochRowWrittenBy returns the epoch row that processing the given epoch +// writes, and whether there is one at all. +// +// Processing epoch E writes the row for E-1. Processing epoch 0 writes no epoch +// row: there is nothing before genesis. phase0.Epoch is unsigned, so computing +// 0-1 wraps to the maximum uint64 and would address a row that cannot exist - +// harmless today only because nothing matches it, which is not a property worth +// relying on. +func EpochRowWrittenBy(epoch phase0.Epoch) (phase0.Epoch, bool) { + if epoch == 0 { + return 0, false } - err = s.Delete(DeletableObject{ - query: deleteEpochsQuery, - table: epochsTable, - args: []any{epoch}, - }) // when deleteState -> currentState - if err != nil { - return err + return epoch - 1, true +} + +func (s *DBService) DeleteStateMetrics(epoch phase0.Epoch) error { + // The epoch row written by this epoch's processing is the one for epoch-1. + if row, ok := EpochRowWrittenBy(epoch); ok { + if err := s.Delete(DeletableObject{ + query: deleteEpochsQuery, + table: epochsTable, + args: []any{row}, + }); err != nil { + return err + } } - // proposer duties are writter using nextState - err = s.Delete(DeletableObject{ + // Proposer duties are written using nextState, so they belong to epoch. + if err := s.Delete(DeletableObject{ query: deleteProposerDutiesQuery, table: proposerDutiesTable, args: []any{epoch}, - }) - if err != nil { + }); err != nil { return err } - // valRewards are written at nextState using prevState, currentState and nextState - err = s.Delete(DeletableObject{ - query: deleteValidatorRewardsInEpochQuery, - table: valRewardsTable, - args: []any{epoch + 2}, - }) // when deleteState -> prevState - if err != nil { - return err - } - err = s.Delete(DeletableObject{ - query: deleteValidatorRewardsInEpochQuery, - table: valRewardsTable, - args: []any{epoch + 1}, - }) // when deleteState -> currentState - if err != nil { - return err - } - err = s.Delete(DeletableObject{ + // Validator rewards are written at nextState, so they belong to epoch. + if err := s.Delete(DeletableObject{ query: deleteValidatorRewardsInEpochQuery, table: valRewardsTable, args: []any{epoch}, - }) // when deleteState -> nextState - if err != nil { + }); err != nil { return err } - return nil + return nil } diff --git a/pkg/db/epoch_metrics_test.go b/pkg/db/epoch_metrics_test.go new file mode 100644 index 00000000..9465efb4 --- /dev/null +++ b/pkg/db/epoch_metrics_test.go @@ -0,0 +1,48 @@ +package db + +import ( + "testing" + + "github.com/attestantio/go-eth2-client/spec/phase0" +) + +// Processing epoch E writes the epoch row for E-1, which is what +// DeleteStateMetrics clears before the rewrite. Epoch 0 is the exception: +// there is no epoch before genesis. + +func TestProcessingAnEpochWritesThePreviousEpochsRow(t *testing.T) { + row, ok := EpochRowWrittenBy(10) + + if !ok { + t.Fatal("processing epoch 10 should write an epoch row") + } + if row != 9 { + t.Errorf("epoch row = %d, want 9", row) + } +} + +func TestGenesisWritesNoEpochRow(t *testing.T) { + // phase0.Epoch is unsigned, so 0-1 wraps to the maximum uint64 and would + // address a row that cannot exist. Nothing matches it today, which is why + // this never surfaced, but that is not a property to rely on. + row, ok := EpochRowWrittenBy(0) + + if ok { + t.Errorf("processing epoch 0 claimed to write epoch row %d", row) + } +} + +func TestNoEpochEverAddressesTheWrappedRow(t *testing.T) { + // Written through a variable on purpose. The compiler rejects the constant + // form as an overflow, which is exactly why this went unnoticed in the + // original code: there the epoch is a variable, so it wraps silently. + var zero phase0.Epoch + wrapped := zero - 1 + + for _, epoch := range []phase0.Epoch{0, 1, 2, 100, 471766} { + row, ok := EpochRowWrittenBy(epoch) + if ok && row == wrapped { + t.Errorf("epoch %d addresses the wrapped row %d", epoch, row) + } + } +} diff --git a/pkg/db/migrations/000037_add_activation_eligibility_epoch.down.sql b/pkg/db/migrations/000037_add_activation_eligibility_epoch.down.sql new file mode 100644 index 00000000..640e19bd --- /dev/null +++ b/pkg/db/migrations/000037_add_activation_eligibility_epoch.down.sql @@ -0,0 +1,3 @@ +-- Remove f_activation_eligibility_epoch column from t_validator_last_status. +ALTER TABLE t_validator_last_status +DROP COLUMN IF EXISTS f_activation_eligibility_epoch; diff --git a/pkg/db/migrations/000037_add_activation_eligibility_epoch.up.sql b/pkg/db/migrations/000037_add_activation_eligibility_epoch.up.sql new file mode 100644 index 00000000..11cf3171 --- /dev/null +++ b/pkg/db/migrations/000037_add_activation_eligibility_epoch.up.sql @@ -0,0 +1,13 @@ +-- Add f_activation_eligibility_epoch column to t_validator_last_status. +-- Default is FAR_FUTURE_EPOCH (2^64 - 1) so historical rows that pre-date +-- this migration read as "not yet eligible" — which matches the consensus +-- spec semantics for an unset eligibility epoch. goteth rewrites every row +-- on each finalized epoch, so the default is corrected for live validators +-- on the next analyzer pass. +-- +-- IF NOT EXISTS: the column may already be present on databases where the +-- earlier #268 migration was applied before it was reverted in code, this +-- keeps the migration idempotent. ADD COLUMN with a DEFAULT is a metadata-only +-- operation in ClickHouse (no data rewrite). +ALTER TABLE t_validator_last_status +ADD COLUMN IF NOT EXISTS f_activation_eligibility_epoch UInt64 DEFAULT 18446744073709551615 AFTER f_activation_epoch; diff --git a/pkg/db/migrations/000038_data_column_sidecar_events.down.sql b/pkg/db/migrations/000038_data_column_sidecar_events.down.sql new file mode 100644 index 00000000..80941637 --- /dev/null +++ b/pkg/db/migrations/000038_data_column_sidecar_events.down.sql @@ -0,0 +1,2 @@ +RENAME TABLE t_blob_sidecars_events_pre_fulu TO t_blob_sidecars_events; +DROP TABLE IF EXISTS t_data_column_sidecars_events; diff --git a/pkg/db/migrations/000038_data_column_sidecar_events.up.sql b/pkg/db/migrations/000038_data_column_sidecar_events.up.sql new file mode 100644 index 00000000..d6c7b32d --- /dev/null +++ b/pkg/db/migrations/000038_data_column_sidecar_events.up.sql @@ -0,0 +1,31 @@ +-- PeerDAS (Fulu) replaced blob-level p2p propagation with column-level propagation: +-- a node no longer receives whole blobs, it receives DataColumnSidecars. The +-- beacon API's `blob_sidecar` event stopped firing at the Fulu fork, so +-- t_blob_sidecars_events silently stopped filling (last row 2025-12-03) while +-- every other blob table kept working. This table is its replacement: one row per +-- column arrival, which is the finest-grained propagation signal available now +-- (and strictly richer than the old one: it exposes the reconstruction curve of +-- each blob, not just a single arrival timestamp). +-- +-- Note: blob *metadata* still comes from the block itself (t_blob_sidecars) and is +-- unaffected. Only the p2p arrival timing moved here. +CREATE TABLE IF NOT EXISTS t_data_column_sidecars_events ( + f_arrival_timestamp_ms UInt64 CODEC(DoubleDelta, ZSTD(3)), + f_slot UInt64 CODEC(DoubleDelta, ZSTD(3)), + f_block_root String CODEC(ZSTD(3)), + f_column_index UInt16 CODEC(T64, ZSTD(3)), + f_kzg_commitments Array(String) CODEC(ZSTD(3)), + f_num_commitments UInt16 CODEC(T64, ZSTD(3)) + ) + ENGINE = ReplacingMergeTree() + PARTITION BY intDiv(f_slot, 100000) + ORDER BY (f_slot, f_column_index, f_block_root); + +-- The blob_sidecar event no longer exists post-Fulu, so this table can never +-- receive another row. Its historical rows (pre-2025-12-03) are preserved by +-- renaming rather than dropping. +-- +-- Deploy note: any bindeth serving this database must already include bindeth +-- PR #352 (which re-points the blob queries to t_data_column_sidecars_events), +-- otherwise its blob endpoints break on the renamed table. +RENAME TABLE t_blob_sidecars_events TO t_blob_sidecars_events_pre_fulu; diff --git a/pkg/db/pools_summary.go b/pkg/db/pools_summary.go index 1d55da22..8e2aff11 100644 --- a/pkg/db/pools_summary.go +++ b/pkg/db/pools_summary.go @@ -7,13 +7,30 @@ import ( "github.com/attestantio/go-eth2-client/spec/phase0" ) +const ( + // UnknownPoolName groups validators that have no entry (or an empty pool + // name) in t_eth2_pubkeys at aggregation time. Keeping them in a synthetic + // pool instead of dropping them guarantees that the sum across pools + // always matches the network totals in t_epoch_metrics_summary. + UnknownPoolName = "unknown" + + // poolSummaryRefreshBatchEpochs is the number of epochs recomputed per + // INSERT when refreshing a range. Bounds the memory used by the + // aggregation while keeping the refresh fast (a batch takes seconds). + poolSummaryRefreshBatchEpochs = 250 +) + var ( poolsTables = "t_pool_summary" - insertPoolSummary = ` - INSERT INTO %s - SELECT - t_eth2_pubkeys.f_pool_name, f_epoch, + // The missed-blocks condition re-checks that the joined proposer duty row + // really belongs to this validator and epoch: ClickHouse fills the right + // side of a non-matched LEFT JOIN with type defaults (f_val_idx = 0, + // f_proposed = false), which validator index 0 satisfies spuriously and + // gets a fake missed block on every epoch it does not propose. + poolSummarySelect = ` + SELECT + if(t_eth2_pubkeys.f_pool_name = '', '%s', t_eth2_pubkeys.f_pool_name) as f_pool_name, f_epoch, SUM(CASE WHEN (f_reward <= f_max_reward) THEN f_reward ELSE 0 END) as aggregated_rewards, SUM(CASE WHEN (f_reward <= f_max_reward) THEN f_max_reward ELSE 0 END) as aggregated_max_rewards, SUM(f_effective_balance) as aggregated_effective_balance, @@ -25,7 +42,9 @@ var ( COUNT(*) as count_expected_attestations, SUM(CASE WHEN f_attestation_included = TRUE THEN 1 ELSE 0 END) as count_included_attestations, SUM(CASE WHEN t_proposer_duties.f_proposed = TRUE THEN 1 ELSE 0 END) as proposed_blocks_performance, - SUM(CASE WHEN t_proposer_duties.f_proposed = FALSE and t_validator_rewards_summary.f_val_idx = t_proposer_duties.f_val_idx THEN 1 ELSE 0 END) as missed_blocks_performance, + SUM(CASE WHEN t_proposer_duties.f_proposed = FALSE + AND t_validator_rewards_summary.f_val_idx = t_proposer_duties.f_val_idx + AND t_validator_rewards_summary.f_epoch = toUInt64(t_proposer_duties.f_proposer_slot/32) THEN 1 ELSE 0 END) as missed_blocks_performance, count(distinct(t_validator_rewards_summary.f_val_idx)) as number_active_vals, count(CASE WHEN f_withdrawal_prefix = 2 THEN 1 ELSE null END) as number_compounding_vals, AVG(f_inclusion_delay) as avg_inclusion_delay @@ -33,15 +52,31 @@ var ( LEFT JOIN t_eth2_pubkeys final ON t_validator_rewards_summary.f_val_idx = t_eth2_pubkeys.f_val_idx LEFT JOIN t_proposer_duties final - ON t_validator_rewards_summary.f_val_idx = t_proposer_duties.f_val_idx + ON t_validator_rewards_summary.f_val_idx = t_proposer_duties.f_val_idx AND t_validator_rewards_summary.f_epoch = toUInt64(t_proposer_duties.f_proposer_slot/32) - WHERE f_epoch = $1 AND f_status = 1 AND f_pool_name != '' - GROUP BY t_eth2_pubkeys.f_pool_name, f_epoch` + WHERE %s AND f_status = 1 + GROUP BY if(t_eth2_pubkeys.f_pool_name = '', '%s', t_eth2_pubkeys.f_pool_name), f_epoch` + + deletePoolSummaryRangeQuery = ` + DELETE FROM %s + WHERE f_epoch >= $1 AND f_epoch <= $2; + ` + + // Order-independent fingerprint of the validator->pool mapping, used to + // detect pool re-tagging so recent pool summaries can be refreshed. + selectPoolsFingerprintQuery = ` + SELECT concat(toString(count()), '-', toString(sum(cityHash64(f_val_idx, f_pool_name)))) as f_fingerprint + FROM t_eth2_pubkeys FINAL` ) +func insertPoolSummaryQuery(whereClause string) string { + selectStmt := fmt.Sprintf(poolSummarySelect, UnknownPoolName, whereClause, UnknownPoolName) + return fmt.Sprintf("INSERT INTO %s%s", poolsTables, selectStmt) +} + func (p *DBService) InsertPoolSummary(epoch phase0.Epoch) error { - query := fmt.Sprintf(insertPoolSummary, poolsTables) + query := insertPoolSummaryQuery("f_epoch = $1") var err error startTime := time.Now() @@ -56,3 +91,85 @@ func (p *DBService) InsertPoolSummary(epoch phase0.Epoch) error { return err } + +func (p *DBService) insertPoolSummaryRange(fromEpoch phase0.Epoch, toEpoch phase0.Epoch) error { + + query := insertPoolSummaryQuery("f_epoch >= $1 AND f_epoch <= $2") + var err error + + p.highMu.Lock() + err = p.highLevelClient.Exec(p.ctx, query, fromEpoch, toEpoch) + p.highMu.Unlock() + + return err +} + +func (p *DBService) DeletePoolSummaryRange(fromEpoch phase0.Epoch, toEpoch phase0.Epoch) error { + + deleteObj := DeletableObject{ + query: deletePoolSummaryRangeQuery, + table: poolsTables, + args: []any{fromEpoch, toEpoch}, + } + + err := p.Delete(deleteObj) + if err != nil { + log.Errorf("error deleting pool summaries: %s", err.Error()) + } + + return err +} + +// RefreshPoolSummaryRange recomputes t_pool_summary for [fromEpoch, toEpoch] +// from the current contents of t_validator_rewards_summary and +// t_eth2_pubkeys. Existing rows in the range are deleted first: the table is +// a ReplacingMergeTree keyed on (f_epoch, f_pool_name), so re-inserting after +// a pool was renamed or split would leave ghost rows under the old pool name +// and double count its validators. +func (p *DBService) RefreshPoolSummaryRange(fromEpoch phase0.Epoch, toEpoch phase0.Epoch) error { + + if toEpoch < fromEpoch { + return fmt.Errorf("invalid pool summary refresh range: %d-%d", fromEpoch, toEpoch) + } + + startTime := time.Now() + + err := p.DeletePoolSummaryRange(fromEpoch, toEpoch) + if err != nil { + return err + } + + for batchStart := fromEpoch; batchStart <= toEpoch; batchStart += poolSummaryRefreshBatchEpochs { + batchEnd := batchStart + poolSummaryRefreshBatchEpochs - 1 + if batchEnd > toEpoch { + batchEnd = toEpoch + } + err = p.insertPoolSummaryRange(batchStart, batchEnd) + if err != nil { + return fmt.Errorf("refreshing pool summaries %d-%d: %w", batchStart, batchEnd, err) + } + log.Debugf("pool summaries refreshed for epochs %d-%d", batchStart, batchEnd) + } + + log.Infof("pool summaries refreshed for epochs %d-%d, %f seconds", + fromEpoch, toEpoch, time.Since(startTime).Seconds()) + + return nil +} + +// RetrievePoolsFingerprint returns a cheap fingerprint of the current +// validator->pool mapping. It changes whenever t_eth2_pubkeys gains rows or +// any validator is re-tagged, and is used to trigger pool summary refreshes. +func (p *DBService) RetrievePoolsFingerprint() (string, error) { + + var dest []struct { + F_fingerprint string `ch:"f_fingerprint"` + } + + err := p.highSelect(selectPoolsFingerprintQuery, &dest) + + if len(dest) > 0 { + return dest[0].F_fingerprint, err + } + return "", err +} diff --git a/pkg/db/prometheus_metrics.go b/pkg/db/prometheus_metrics.go index b937ca3a..43d19a73 100644 --- a/pkg/db/prometheus_metrics.go +++ b/pkg/db/prometheus_metrics.go @@ -76,7 +76,7 @@ func (r *DBService) initMonitorMetrics() { tablesArr := []string{ blobsTable, - blobEventsTable, + dataColumnEventsTable, blockRewardsTable, blocksTable, epochsTable, diff --git a/pkg/db/service.go b/pkg/db/service.go index a08bf0a7..0ee311ae 100644 --- a/pkg/db/service.go +++ b/pkg/db/service.go @@ -145,7 +145,7 @@ type PersistableObject[ spec.Withdrawal | HeadEvent | spec.AgnosticBlobSidecar | - spec.BlobSideCarEventWraper | + spec.DataColumnSidecarEventWrapper | BlockReward | spec.AgnosticSlashing | spec.BLSToExecutionChange | diff --git a/pkg/db/validator_last_status.go b/pkg/db/validator_last_status.go index 420008f2..02496915 100644 --- a/pkg/db/validator_last_status.go +++ b/pkg/db/validator_last_status.go @@ -17,6 +17,7 @@ var ( f_status, f_slashed, f_activation_epoch, + f_activation_eligibility_epoch, f_withdrawal_epoch, f_exit_epoch, f_public_key, @@ -36,14 +37,15 @@ func valStatusInput(validatorStatuses []spec.ValidatorLastStatus) proto.Input { f_epoch proto.ColUInt64 f_balance_eth proto.ColFloat32 f_effective_balance proto.ColUInt64 - f_status proto.ColUInt8 - f_slashed proto.ColBool - f_activation_epoch proto.ColUInt64 - f_withdrawal_epoch proto.ColUInt64 - f_exit_epoch proto.ColUInt64 - f_public_key proto.ColStr - f_withdrawal_prefix proto.ColUInt8 - f_withdrawal_credentials proto.ColStr + f_status proto.ColUInt8 + f_slashed proto.ColBool + f_activation_epoch proto.ColUInt64 + f_activation_eligibility_epoch proto.ColUInt64 + f_withdrawal_epoch proto.ColUInt64 + f_exit_epoch proto.ColUInt64 + f_public_key proto.ColStr + f_withdrawal_prefix proto.ColUInt8 + f_withdrawal_credentials proto.ColStr ) for _, status := range validatorStatuses { @@ -54,6 +56,7 @@ func valStatusInput(validatorStatuses []spec.ValidatorLastStatus) proto.Input { f_status.Append(uint8(status.CurrentStatus)) f_slashed.Append(status.Slashed) f_activation_epoch.Append(uint64(status.ActivationEpoch)) + f_activation_eligibility_epoch.Append(uint64(status.ActivationEligibilityEpoch)) f_withdrawal_epoch.Append(uint64(status.WithdrawalEpoch)) f_exit_epoch.Append(uint64(status.ExitEpoch)) f_public_key.Append(status.PublicKey.String()) @@ -69,6 +72,7 @@ func valStatusInput(validatorStatuses []spec.ValidatorLastStatus) proto.Input { {Name: "f_status", Data: f_status}, {Name: "f_slashed", Data: f_slashed}, {Name: "f_activation_epoch", Data: f_activation_epoch}, + {Name: "f_activation_eligibility_epoch", Data: f_activation_eligibility_epoch}, {Name: "f_withdrawal_epoch", Data: f_withdrawal_epoch}, {Name: "f_exit_epoch", Data: f_exit_epoch}, {Name: "f_public_key", Data: f_public_key}, diff --git a/pkg/events/blobs.go b/pkg/events/blobs.go index d6a3cc54..9c48e37d 100644 --- a/pkg/events/blobs.go +++ b/pkg/events/blobs.go @@ -8,28 +8,42 @@ import ( "github.com/migalabs/goteth/pkg/spec" ) -func (e *Events) SubscribeToBlobSidecarsEvents() { - // subscribe to head event +// SubscribeToDataColumnSidecarsEvents subscribes to the p2p arrival of data columns. +// +// This replaces the old `blob_sidecar` subscription. Since the Fulu fork (PeerDAS) +// blobs are erasure-coded into columns and gossiped per column, so beacon nodes no +// longer emit `blob_sidecar` at all: the topic is still accepted (HTTP 200) but +// never fires. That is why blob arrival timings silently stopped being recorded at +// the fork while every other blob table kept working. +// +// A subscription failure is logged and skipped rather than crashing the process: +// the analyzer can keep indexing everything else without this data source. Note +// that Events() only returns errors synchronously for client-side conditions; +// node-side rejections surface asynchronously inside go-eth2-client's own +// goroutine, which logs and retries every second. +func (e *Events) SubscribeToDataColumnSidecarsEvents() { err := e.cli.Api.Events(e.ctx, ð2api.EventsOpts{ - Topics: []string{"blob_sidecar"}, - Handler: e.HandleBlobSidecarEvent, - }) // every reorg + Topics: []string{"data_column_sidecar"}, + Handler: e.HandleDataColumnSidecarEvent, + }) if err != nil { - log.Panicf("failed to subscribe to blob_sidecar events: %s", err) + log.Errorf("failed to subscribe to data_column_sidecar events, blob arrival timings will not be recorded: %s", err) + return } - log.Infof("subscribed to blob_sidecar events") + e.SubscribedDataColumns.Store(true) + log.Infof("subscribed to data_column_sidecar events") } -func (e *Events) HandleBlobSidecarEvent(event *apiv1.Event) { +func (e *Events) HandleDataColumnSidecarEvent(event *apiv1.Event) { timestamp := time.Now() if event.Data == nil { return } - data := spec.BlobSideCarEventWraper{ - Timestamp: timestamp, - BlobSidecarEvent: *event.Data.(*apiv1.BlobSidecarEvent), + data := spec.DataColumnSidecarEventWrapper{ + Timestamp: timestamp, + DataColumnSidecarEvent: *event.Data.(*apiv1.DataColumnSidecarEvent), } - e.BlobSidecarChan <- data + e.DataColumnSidecarChan <- data } diff --git a/pkg/events/standard.go b/pkg/events/standard.go index 315e07f4..55b3c0d1 100644 --- a/pkg/events/standard.go +++ b/pkg/events/standard.go @@ -2,6 +2,7 @@ package events import ( "context" + "sync/atomic" apiv1 "github.com/attestantio/go-eth2-client/api/v1" "github.com/migalabs/goteth/pkg/clientapi" @@ -22,10 +23,16 @@ type Events struct { SubscribedHead bool HeadChan chan db.HeadEvent - SubscribedFinalized bool - FinalizedChan chan apiv1.FinalizedCheckpointEvent - ReorgChan chan apiv1.ChainReorgEvent - BlobSidecarChan chan spec.BlobSideCarEventWraper + SubscribedFinalized bool + FinalizedChan chan apiv1.FinalizedCheckpointEvent + ReorgChan chan apiv1.ChainReorgEvent + DataColumnSidecarChan chan spec.DataColumnSidecarEventWrapper + + // SubscribedDataColumns turns true once the data_column_sidecar subscription + // is established; while false, blob arrival timings are not being recorded. + // Pointer so Events stays copyable (atomic values must not be copied); read + // by the prometheus updater goroutine. + SubscribedDataColumns *atomic.Bool } func NewEventsObj(iCtx context.Context, iCli *clientapi.APIClient) Events { @@ -37,6 +44,12 @@ func NewEventsObj(iCtx context.Context, iCli *clientapi.APIClient) Events { SubscribedFinalized: false, FinalizedChan: make(chan apiv1.FinalizedCheckpointEvent), ReorgChan: make(chan apiv1.ChainReorgEvent), - BlobSidecarChan: make(chan spec.BlobSideCarEventWraper), + // Buffered like HeadChan: HandleDataColumnSidecarEvent does a blocking send, so + // a full channel stalls the SSE reader and with it head ingestion. Sized much + // larger than the old blob channel on purpose: PeerDAS emits one event per data + // *column*, so a single block can produce up to 128 events (NUMBER_OF_COLUMNS) + // instead of the <=6 blob events it used to, all arriving in a burst. + DataColumnSidecarChan: make(chan spec.DataColumnSidecarEventWrapper, 1024), + SubscribedDataColumns: new(atomic.Bool), } } diff --git a/pkg/metrics/service.go b/pkg/metrics/service.go index ec1bb394..89fd70bd 100644 --- a/pkg/metrics/service.go +++ b/pkg/metrics/service.go @@ -84,6 +84,7 @@ func (p *PrometheusMetrics) launchMetricsUpdater() { defer p.wg.Done() ticker := time.NewTicker(p.RefreshInterval) + defer ticker.Stop() // lives as long as the routine; stopped for a clean shutdown metricsUpdateLoop: for { diff --git a/pkg/relay/constants.go b/pkg/relay/constants.go index 88ad4a6f..41165322 100644 --- a/pkg/relay/constants.go +++ b/pkg/relay/constants.go @@ -3,23 +3,23 @@ package relay const ( mainnetAestusRelay string = "https://0xa15b52576bcbf1072f4a011c0f99f9fb6c66f3e1ff321f11f461d15e31b1cb359caa092c71bbded0bae5b5ea401aab7e@aestus.live" mainnetAgnosticRelay string = "https://0xa7ab7a996c8584251c8f925da3170bdfd6ebc75d50f5ddc4050a6fdc77f2a3b5fce2cc750d0865e05d7228af97d69561@agnostic-relay.net" - mainnetBloxRouteMaxProfitRelay string = "https://0x8b5d2e73e2a3a55c6c87b8b6eb92e0149a125c852751db1422fa951e42a09b82c142c3ea98d0d9930b056a3bc9896b8f@bloxroute.max-profit.blxrbdn.com" mainnetBloxRouteRegulatedRelay string = "https://0xb0b07cd0abef743db4260b0ed50619cf6ad4d82064cb4fbec9d3ec530f7c5e6793d9f286c4e082c0244ffb9f2658fe88@bloxroute.regulated.blxrbdn.com" mainnetTitanGlobalRelay string = "https://0x8c4ed5e24fe5c6ae21018437bde147693f68cda427cd1122cf20819c30eda7ed74f72dece09bb313f2a1855595ab677d@global.titanrelay.xyz" mainnetTitanRegionalRelay string = "https://0x8c4ed5e24fe5c6ae21018437bde147693f68cda427cd1122cf20819c30eda7ed74f72dece09bb313f2a1855595ab677d@regional.titanrelay.xyz" mainnetFlashbotsRelay string = "https://0xac6e77dfe25ecd6110b8e780608cce0dab71fdd5ebea22a16c0205200f2f8e2e3ad3b71d3499c54ad14d6c21b41a37ae@boost-relay.flashbots.net" mainnetUltraSoundRelay string = "https://0xa1559ace749633b997cb3fdacffb890aeebdb0f5a3b6aaa7eeeaf1a38af0a8fe88b9e4b1f61f236d2e64d95733327a62@relay.ultrasound.money" + mainnetEthgasRelay string = "https://0x88ef3061f598101ca713d556cf757763d9be93d33c3092d3ab6334a36855b6b4a4020528dd533a62d25ea6648251e62e@relay.ethgas.com" ) var mainnetRelayList []string = []string{ mainnetAestusRelay, mainnetAgnosticRelay, - mainnetBloxRouteMaxProfitRelay, mainnetBloxRouteRegulatedRelay, mainnetTitanGlobalRelay, mainnetTitanRegionalRelay, mainnetFlashbotsRelay, mainnetUltraSoundRelay, + mainnetEthgasRelay, } const ( @@ -44,6 +44,7 @@ const ( hoodiUltraSoundRelay string = "https://0xb1559beef7b5ba3127485bbbb090362d9f497ba64e177ee2c8e7db74746306efad687f2cf8574e38d70067d40ef136dc@relay-hoodi.ultrasound.money" hoodiTitanRelay string = "https://0xaa58208899c6105603b74396734a6263cc7d947f444f396a90f7b7d3e65d102aec7e5e5291b27e08d02c50a050825c2f@hoodi.titanrelay.xyz" hoodiAestusRelay string = "https://0x98f0ef62f00780cf8eb06701a7d22725b9437d4768bb19b363e882ae87129945ec206ec2dc16933f31d983f8225772b6@hoodi.aestus.live" + hoodiEthgasRelay string = "https://0xb20c3fe59db9c3655088839ef3d972878d182eb745afd8abb1dd2abf6c14f93cd5934ed4446a5fe1ba039e2bc0cf1011@hoodi-relay.ethgas.com" ) var hoodiRelayList []string = []string{ @@ -52,6 +53,7 @@ var hoodiRelayList []string = []string{ hoodiUltraSoundRelay, hoodiTitanRelay, hoodiAestusRelay, + hoodiEthgasRelay, } const ( diff --git a/pkg/relay/relay_bid_trace.go b/pkg/relay/relay_bid_trace.go index 9b95f765..ff188227 100644 --- a/pkg/relay/relay_bid_trace.go +++ b/pkg/relay/relay_bid_trace.go @@ -23,8 +23,23 @@ const ( // relay for a cooldown period instead of waiting for timeout every time. cbFailureThreshold = 3 cbCooldown = 2 * time.Minute + + // A failed request is retried before the relay's bids for the epoch are + // given up: they are fetched once per epoch and nothing fetches them again. + // The first retry waits relayRetryBackoff, each next one twice as long. + relayRequestAttempts = 3 + relayRetryBackoff = 5 * time.Second ) +// waitBeforeRetry waits d, or less if ctx is done. A variable so the tests can +// record the waits instead of sleeping. +var waitBeforeRetry = func(ctx context.Context, d time.Duration) { + select { + case <-time.After(d): + case <-ctx.Done(): + } +} + var ( log = logrus.WithField( "module", moduleName) @@ -79,6 +94,13 @@ func (r *RelayClient) isOpen() bool { return true } +// failing tells whether the relay's last query failed. +func (r *RelayClient) failing() bool { + r.mu.Lock() + defer r.mu.Unlock() + return r.consecutiveFail > 0 +} + // recordResult updates the circuit breaker after a query. func (r *RelayClient) recordResult(failed bool) { r.mu.Lock() @@ -103,15 +125,35 @@ func (r *RelayClient) GetDeliveredBidsPerSlotRange(slot phase0.Slot, limit int) return nil, fmt.Errorf("circuit breaker open for %s, skipping", r.address) } - bidsDelivered, err := r.client.(relayclient.DeliveredBidTraceProvider).DeliveredBulkBidTrace(r.ctx, slot, limit) - if err != nil || bidsDelivered == nil { - r.recordResult(true) - return bidsDelivered, fmt.Errorf("error obtaining delivered bid trace from %s: %s", r.address, err) + // A relay whose last query failed gets a single attempt: retrying one that + // is down only delays the epoch, and the circuit breaker deals with it. + attempts := relayRequestAttempts + if r.failing() { + attempts = 1 + } + backoff := relayRetryBackoff + var err error + for attempt := 1; ; attempt++ { + // An empty answer (nil, nil) is an answer: the relay delivered nothing. + var bidsDelivered []*v1.BidTrace + bidsDelivered, err = r.client.(relayclient.DeliveredBidTraceProvider).DeliveredBulkBidTrace(r.ctx, slot, limit) + if err == nil { + r.recordResult(false) + return bidsDelivered, nil + } + if attempt == attempts || r.ctx.Err() != nil { + break + } + log.Warnf("retrying %s at slot %d in %s (attempt %d of %d): %s", r.address, slot, backoff, attempt+1, attempts, err) + waitBeforeRetry(r.ctx, backoff) + if r.ctx.Err() != nil { + break + } + backoff *= 2 } - r.recordResult(false) - return bidsDelivered, nil - + r.recordResult(true) + return nil, fmt.Errorf("error obtaining delivered bid trace from %s: %s", r.address, err) } type RelaysMonitor struct { @@ -150,7 +192,7 @@ func (m RelaysMonitor) GetDeliveredBidsPerSlotRange(slot phase0.Slot, limit int) defer wg.Done() singleRelayBidsDelivered, err := rc.GetDeliveredBidsPerSlotRange(slot, limit) - if err != nil || singleRelayBidsDelivered == nil { + if err != nil { log.Errorf("%s", err) return } diff --git a/pkg/relay/relay_retry_test.go b/pkg/relay/relay_retry_test.go new file mode 100644 index 00000000..e55c88cf --- /dev/null +++ b/pkg/relay/relay_retry_test.go @@ -0,0 +1,202 @@ +package relay + +import ( + "context" + "errors" + "strings" + "testing" + "time" + + "github.com/attestantio/go-eth2-client/spec/phase0" + v1 "github.com/attestantio/go-relay-client/api/v1" +) + +// A relay's delivered bids are fetched once per epoch and nothing fetches them +// again, so one failed request used to lose the epoch's bids from that relay. + +// scriptedRelay answers each request with the next error of its script, nil +// meaning a successful answer, and repeats the last one when the script runs out. +type scriptedRelay struct { + script []error + calls int + empty bool // answer successfully with no bids, as the client does for [] +} + +func (s *scriptedRelay) Name() string { return "scripted" } +func (s *scriptedRelay) Address() string { return "https://scripted.relay" } +func (s *scriptedRelay) Pubkey() *phase0.BLSPubKey { return nil } + +func (s *scriptedRelay) DeliveredBidTrace(context.Context, phase0.Slot) (*v1.BidTrace, error) { + return nil, errors.New("not used") +} + +func (s *scriptedRelay) DeliveredBulkBidTrace(ctx context.Context, slot phase0.Slot, limit int) ([]*v1.BidTrace, error) { + err := s.script[min(s.calls, len(s.script)-1)] + s.calls++ + if err != nil || s.empty { + return nil, err + } + return []*v1.BidTrace{{Slot: slot}}, nil +} + +// scriptedClient is a relay client over a scripted relay. The waits between +// attempts are recorded instead of slept; onWait, if set, runs in each. +func scriptedClient(t *testing.T, ctx context.Context, onWait func(), script ...error) (*RelayClient, *scriptedRelay, *[]time.Duration) { + t.Helper() + var waits []time.Duration + wait := waitBeforeRetry + waitBeforeRetry = func(_ context.Context, d time.Duration) { + waits = append(waits, d) + if onWait != nil { + onWait() + } + } + t.Cleanup(func() { waitBeforeRetry = wait }) + relay := &scriptedRelay{script: script} + return &RelayClient{ctx: ctx, client: relay, address: relay.Address()}, relay, &waits +} + +var errRelay = errors.New("context deadline exceeded") + +func TestATransientFailureIsRetried(t *testing.T) { + r, relay, waits := scriptedClient(t, context.Background(), nil, errRelay, errRelay, nil) + + bids, err := r.GetDeliveredBidsPerSlotRange(15373855, 32) + + if err != nil || len(bids) != 1 { + t.Fatalf("bids = %v, err = %v, want the third attempt's answer", bids, err) + } + if relay.calls != 3 { + t.Errorf("requests = %d, want 3", relay.calls) + } + if len(*waits) != 2 || (*waits)[0] != relayRetryBackoff || (*waits)[1] != 2*relayRetryBackoff { + t.Errorf("waits = %v, want %v then twice that", *waits, relayRetryBackoff) + } + if r.failing() { + t.Error("the breaker counts a failure for a request that succeeded on a retry") + } +} + +// A relay that fails every attempt is one failure for the breaker, and the +// error keeps the message operators grep for. +func TestARequestFailingEveryAttemptIsOneFailure(t *testing.T) { + r, relay, _ := scriptedClient(t, context.Background(), nil, errRelay) + + _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32) + + if err == nil || !strings.Contains(err.Error(), "error obtaining delivered bid trace from https://scripted.relay: context deadline exceeded") { + t.Fatalf("err = %v, want the delivered bid trace error", err) + } + if relay.calls != relayRequestAttempts { + t.Errorf("requests = %d, want %d", relay.calls, relayRequestAttempts) + } + if r.consecutiveFail != 1 { + t.Errorf("consecutive failures = %d, want 1", r.consecutiveFail) + } +} + +// The client turns an empty list into no bids and no error: the relay +// delivered nothing up to the cursor. That is an answer, not a failure. +func TestAnEmptyAnswerIsAnAnswer(t *testing.T) { + r, relay, _ := scriptedClient(t, context.Background(), nil, nil) + relay.empty = true + + bids, err := r.GetDeliveredBidsPerSlotRange(15373855, 32) + + if err != nil || bids != nil { + t.Errorf("bids = %v, err = %v, want neither", bids, err) + } + if relay.calls != 1 || r.failing() { + t.Errorf("%d requests, failing %v: want one request and no failure", relay.calls, r.failing()) + } +} + +// A relay whose last request failed gets one attempt per request, so a relay +// that is down does not hold every epoch up for the retries. +func TestARelayAlreadyFailingGetsOneAttempt(t *testing.T) { + r, relay, _ := scriptedClient(t, context.Background(), nil, errRelay) + r.consecutiveFail = 1 + + if _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32); err == nil { + t.Fatal("want an error") + } + if relay.calls != 1 { + t.Errorf("requests = %d, want 1", relay.calls) + } +} + +// The probe after the breaker's cooldown is a request of a relay known to be +// failing: one attempt, and the breaker opens again if it fails. +func TestTheHalfOpenProbeGetsOneAttempt(t *testing.T) { + r, relay, _ := scriptedClient(t, context.Background(), nil, errRelay) + r.consecutiveFail = cbFailureThreshold + r.openUntil = time.Now().Add(-time.Second) + + if _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32); err == nil || strings.Contains(err.Error(), "circuit breaker open") { + t.Fatalf("err = %v, want the probe's own failure", err) + } + if relay.calls != 1 { + t.Errorf("requests = %d, want 1", relay.calls) + } + if !r.isOpen() { + t.Error("a failed probe leaves the breaker closed") + } +} + +// Three failed requests still open the breaker, and an open breaker sends none. +func TestThreeFailedRequestsStillOpenTheBreaker(t *testing.T) { + r, relay, _ := scriptedClient(t, context.Background(), nil, errRelay) + + for i := 0; i < cbFailureThreshold; i++ { + r.GetDeliveredBidsPerSlotRange(15373855, 32) + } + sent := relay.calls + _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32) + + if err == nil || !strings.Contains(err.Error(), "circuit breaker open") { + t.Fatalf("err = %v, want the breaker open", err) + } + if relay.calls != sent { + t.Errorf("an open breaker sent %d requests", relay.calls-sent) + } +} + +// Shutting down stops the retries, whether it comes before the request or +// during the wait for the next attempt. +func TestShuttingDownStopsTheRetries(t *testing.T) { + t.Run("before the request", func(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + r, relay, waits := scriptedClient(t, ctx, nil, errRelay) + if _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32); err == nil { + t.Fatal("want an error") + } + if relay.calls != 1 || len(*waits) != 0 { + t.Errorf("%d requests and %d waits, want one request and no wait", relay.calls, len(*waits)) + } + }) + t.Run("during the wait", func(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + r, relay, _ := scriptedClient(t, ctx, cancel, errRelay) + if _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32); err == nil { + t.Fatal("want an error") + } + if relay.calls != 1 { + t.Errorf("requests = %d, want 1", relay.calls) + } + }) +} + +// A relay that failed before and answers now is healthy again: the next request +// gets its retries back. +func TestAnAnswerAfterAFailureClearsIt(t *testing.T) { + r, _, _ := scriptedClient(t, context.Background(), nil, nil) + r.consecutiveFail = 1 + + if _, err := r.GetDeliveredBidsPerSlotRange(15373855, 32); err != nil { + t.Fatal(err) + } + if r.failing() { + t.Error("the relay still counts as failing after a successful request") + } +} diff --git a/pkg/spec/blob.go b/pkg/spec/blob.go index 79f5ec94..1841dbd9 100644 --- a/pkg/spec/blob.go +++ b/pkg/spec/blob.go @@ -7,9 +7,11 @@ import ( "time" api "github.com/attestantio/go-eth2-client/api/v1" + "github.com/attestantio/go-eth2-client/spec/bellatrix" "github.com/attestantio/go-eth2-client/spec/deneb" "github.com/attestantio/go-eth2-client/spec/phase0" "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/core/types" "github.com/migalabs/goteth/pkg/utils" ) @@ -45,25 +47,108 @@ func NewAgnosticBlobFromAPI(slot phase0.Slot, blob deneb.BlobSidecar) (*Agnostic }, nil } -func (b *AgnosticBlobSidecar) GetTxHash(txs []AgnosticTransaction) { +// AssignTxHashes maps every blob sidecar of a block to the transaction that +// carried it. +// +// A block's blob commitments are the concatenation of each type-3 transaction's +// blob hashes taken in transaction order, so the sidecar holding index i belongs +// to the transaction that owns the i-th entry of that concatenation. +// +// Position is the only dependable key. A versioned hash is derived from nothing +// but the blob's KZG commitment, so two transactions carrying byte-identical +// blobs share one hash and cannot be told apart by it; matching on the hash +// awards every copy to whichever of them is compared last, and leaves the +// others with no blobs at all. +// +// It reads the block's own transaction list rather than the parsed +// AgnosticTransactions, and that is deliberate. Everything needed here - each +// type-3 transaction's hash and the blob hashes it committed - is in the block +// body. AgnosticTransactions are built by matching transactions to EL receipts +// and only include the ones that matched, so a receipt that has not arrived +// drops a blob carrier from the list. Attribution would then see fewer blobs +// committed than sidecars delivered and refuse the whole slot, leaving every +// blob in it with no transaction. Partial receipt fetches happen often enough +// to have their own recovery path (recoverBlockReceipts), so this must not +// depend on them. +// +// Nothing is assigned until the whole block has been checked: the sidecars must +// account for exactly the blobs the transactions committed to, each index must +// appear once, and every hash must agree with the one committed at that +// position. Because the input no longer depends on receipts, a disagreement now +// means the sidecars are genuinely not the ones this block committed to, and +// leaving the mapping untouched is the right answer rather than a symptom of a +// slow EL. +func AssignTxHashes(blobs []*AgnosticBlobSidecar, blockTxs []bellatrix.Transaction) error { - for _, tx := range txs { - if tx.BlobHashes == nil { - continue // this tx does not reference any blobs + // The block's commitments, flattened in transaction order: one entry per + // blob, holding the transaction that carried it and the hash it committed. + type commitment struct { + txHash common.Hash + blobHash string + } + + committed := make([]commitment, 0, len(blobs)) + carriers := 0 + for idx, raw := range blockTxs { + var tx types.Transaction + if err := tx.UnmarshalBinary(raw); err != nil { + return fmt.Errorf("transaction %d could not be decoded: %w", idx, err) + } + if tx.Type() != types.BlobTxType { + continue + } + carriers++ + for _, blobHash := range tx.BlobHashes() { + committed = append(committed, commitment{tx.Hash(), blobHash.String()}) } + } + + if len(committed) != len(blobs) { + return fmt.Errorf("%d blob sidecars but %d blobs committed by %d transactions", + len(blobs), len(committed), carriers) + } - for _, txBlobHash := range tx.BlobHashes { - if txBlobHash.String() == b.BlobHash { - // we found it - b.TxHash = common.Hash(tx.Hash) - } + seen := make([]bool, len(committed)) + for _, blob := range blobs { + // Compared before narrowing, not after. Index is a uint64, and + // converting one at or above 2^63 to int wraps it negative, which slips + // past a "too large" check and then panics indexing seen. + if uint64(blob.Index) >= uint64(len(committed)) { + return fmt.Errorf("blob index %d is past the %d blobs this block committed", + blob.Index, len(committed)) + } + index := int(blob.Index) + if seen[index] { + return fmt.Errorf("two sidecars claim blob index %d", blob.Index) + } + seen[index] = true + + if committed[index].blobHash != blob.BlobHash { + // Both hashes belong in the message. Every other check here reports + // the numbers it compared, and this is the one most likely to need + // reading against the chain: when several blobs in a block share a + // versioned hash, "does not match" alone gives nobody enough to + // tell which sidecar arrived where it should not have. + return fmt.Errorf("blob %d carries hash %s but this block committed %s at that position", + blob.Index, blob.BlobHash, committed[index].blobHash) } } + + for _, blob := range blobs { + blob.TxHash = committed[blob.Index].txHash + } + + return nil } -type BlobSideCarEventWraper struct { - Timestamp time.Time - BlobSidecarEvent api.BlobSidecarEvent +// DataColumnSidecarEventWrapper carries a data-column arrival plus the local time +// we observed it. Since the Fulu fork (PeerDAS) blobs are no longer gossiped whole: +// they are erasure-coded into columns and each node custodies a subset, so +// `data_column_sidecar` replaced the now-dead `blob_sidecar` event as the p2p +// propagation signal. +type DataColumnSidecarEventWrapper struct { + Timestamp time.Time + DataColumnSidecarEvent api.DataColumnSidecarEvent } func KZGCommitmentToVersionedHash(input deneb.KZGCommitment) string { diff --git a/pkg/spec/blob_test.go b/pkg/spec/blob_test.go new file mode 100644 index 00000000..d8a1a601 --- /dev/null +++ b/pkg/spec/blob_test.go @@ -0,0 +1,348 @@ +package spec_test + +import ( + "fmt" + "strings" + "testing" + + "github.com/attestantio/go-eth2-client/spec/bellatrix" + "github.com/attestantio/go-eth2-client/spec/deneb" + "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/core/types" + "github.com/holiman/uint256" + "github.com/migalabs/goteth/pkg/spec" +) + +// blobHash builds a distinguishable versioned hash. Passing the same seed twice +// produces the same hash, which is what happens on chain when two transactions +// carry byte-identical blobs. +func blobHash(seed byte) common.Hash { + var h common.Hash + h[0] = 0x01 + h[31] = seed + return h +} + +// blobTx encodes a type-3 transaction committing the given blob hashes, in the +// form a block's execution payload carries, and returns its hash. +// +// The transaction is unsigned, so the hash is not one that would appear on +// chain - a signature changes it. That does not matter here: what attribution +// needs is that each hash is derived from its own transaction rather than +// chosen by the test, and that two transactions differ. The nonce provides the +// second part, so two transactions committing identical blobs still hash +// differently, which is the situation that produced the bug. +func blobTx(t *testing.T, nonce uint64, blobSeeds ...byte) (bellatrix.Transaction, common.Hash) { + t.Helper() + + hashes := make([]common.Hash, 0, len(blobSeeds)) + for _, seed := range blobSeeds { + hashes = append(hashes, blobHash(seed)) + } + tx := types.NewTx(&types.BlobTx{ + ChainID: uint256.NewInt(1), + Nonce: nonce, + GasTipCap: uint256.NewInt(1), + GasFeeCap: uint256.NewInt(1), + Gas: 21000, + Value: uint256.NewInt(0), + BlobFeeCap: uint256.NewInt(1), + BlobHashes: hashes, + }) + raw, err := tx.MarshalBinary() + if err != nil { + t.Fatalf("encoding blob transaction: %s", err) + } + return bellatrix.Transaction(raw), tx.Hash() +} + +// plainTx encodes a transaction that carries no blobs. +func plainTx(t *testing.T, nonce uint64) bellatrix.Transaction { + t.Helper() + + tx := types.NewTx(&types.DynamicFeeTx{ + ChainID: uint256.NewInt(1).ToBig(), + Nonce: nonce, + GasTipCap: uint256.NewInt(1).ToBig(), + GasFeeCap: uint256.NewInt(1).ToBig(), + Gas: 21000, + Value: uint256.NewInt(0).ToBig(), + }) + raw, err := tx.MarshalBinary() + if err != nil { + t.Fatalf("encoding plain transaction: %s", err) + } + return bellatrix.Transaction(raw) +} + +// sidecars builds the block's sidecar list, indexed in block order. +func sidecars(blobSeeds ...byte) []*spec.AgnosticBlobSidecar { + blobs := make([]*spec.AgnosticBlobSidecar, 0, len(blobSeeds)) + for i, seed := range blobSeeds { + blobs = append(blobs, &spec.AgnosticBlobSidecar{ + Index: deneb.BlobIndex(i), + BlobHash: blobHash(seed).String(), + }) + } + return blobs +} + +func attributed(blobs []*spec.AgnosticBlobSidecar) []string { + got := make([]string, 0, len(blobs)) + for _, b := range blobs { + got = append(got, fmt.Sprintf("%d:%s", b.Index, b.TxHash.String())) + } + return got +} + +// expect pairs each sidecar, in the order they were handed over, with the +// transaction hash it should end up carrying. +func expect(blobs []*spec.AgnosticBlobSidecar, hashes ...common.Hash) []string { + want := make([]string, 0, len(blobs)) + for i, b := range blobs { + want = append(want, fmt.Sprintf("%d:%s", b.Index, hashes[i].String())) + } + return want +} + +// unattributed is the expectation when nothing should be assigned at all. +func unattributed(blobs []*spec.AgnosticBlobSidecar) []string { + want := make([]string, 0, len(blobs)) + for _, b := range blobs { + want = append(want, fmt.Sprintf("%d:%s", b.Index, common.Hash{}.String())) + } + return want +} + +func TestAssignTxHashes(t *testing.T) { + tests := []struct { + name string + build func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) + wantErr bool + }{ + { + // Mainnet slot 14414626. Three consecutive transactions each carried + // the same near-empty blob, so all three shared one versioned hash. + // Matching on that hash collapsed every copy onto the last of them. + name: "transactions carrying identical blobs keep their own", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, h0 := blobTx(t, 0, 1, 2, 3, 4, 5) + t1, h1 := blobTx(t, 1, 9) + t2, h2 := blobTx(t, 2, 9) + t3, h3 := blobTx(t, 3, 9) + t4, h4 := blobTx(t, 4, 6) + t5, h5 := blobTx(t, 5, 7) + + blobs := sidecars(1, 2, 3, 4, 5, 9, 9, 9, 6, 7) + txs := []bellatrix.Transaction{t0, t1, t2, t3, t4, t5} + want := expect(blobs, h0, h0, h0, h0, h0, h1, h2, h3, h4, h5) + return blobs, txs, want + }, + }, + { + // The review case: a blob transaction whose EL receipt has not + // arrived. Attribution reads the block body, so the receipt is + // irrelevant and every blob in the slot is still attributed. + name: "a blob transaction whose receipt never arrived", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, h0 := blobTx(t, 0, 1) + t1, h1 := blobTx(t, 1, 2) + t2, h2 := blobTx(t, 2, 3) + + blobs := sidecars(1, 2, 3) + // All three are in the block. Only one produced a receipt, so + // AgnosticTransactions would have held a single entry. + txs := []bellatrix.Transaction{t0, t1, t2} + return blobs, txs, expect(blobs, h0, h1, h2) + }, + }, + { + name: "one transaction carrying the same blob twice", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + tx, h := blobTx(t, 0, 4, 4) + blobs := sidecars(4, 4) + return blobs, []bellatrix.Transaction{tx}, expect(blobs, h, h) + }, + }, + { + name: "transactions without blobs are ignored", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t1, h1 := blobTx(t, 1, 1) + t3, h3 := blobTx(t, 3, 2) + blobs := sidecars(1, 2) + txs := []bellatrix.Transaction{plainTx(t, 0), t1, plainTx(t, 2), t3} + return blobs, txs, expect(blobs, h1, h3) + }, + }, + { + // Sidecars need not arrive in index order; the index decides, not + // the position in the slice. + name: "sidecars given out of order", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, h0 := blobTx(t, 0, 1, 2) + t1, h1 := blobTx(t, 1, 3) + blobs := []*spec.AgnosticBlobSidecar{ + {Index: 2, BlobHash: blobHash(3).String()}, + {Index: 0, BlobHash: blobHash(1).String()}, + {Index: 1, BlobHash: blobHash(2).String()}, + } + return blobs, []bellatrix.Transaction{t0, t1}, expect(blobs, h1, h0, h0) + }, + }, + { + // More sidecars than the block committed to. Attributing them + // positionally would shift every blob onto the wrong transaction. + name: "more sidecars than the block committed", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, _ := blobTx(t, 0, 1) + blobs := sidecars(1, 2, 3) + return blobs, []bellatrix.Transaction{t0}, unattributed(blobs) + }, + wantErr: true, + }, + { + // The other direction, and the one the index-bound check cannot + // see: every sidecar present is valid and in range, but the block + // committed a blob that never arrived. Attributing the ones that + // did would publish a slot that is quietly short a blob. + name: "fewer sidecars than the block committed", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, _ := blobTx(t, 0, 1, 2, 3) + blobs := sidecars(1, 2) + return blobs, []bellatrix.Transaction{t0}, unattributed(blobs) + }, + wantErr: true, + }, + { + name: "a sidecar claiming an index past the block's blobs", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, _ := blobTx(t, 0, 1) + t1, _ := blobTx(t, 1, 2) + blobs := []*spec.AgnosticBlobSidecar{ + {Index: 0, BlobHash: blobHash(1).String()}, + {Index: 7, BlobHash: blobHash(2).String()}, + } + return blobs, []bellatrix.Transaction{t0, t1}, unattributed(blobs) + }, + wantErr: true, + }, + { + // Index is a uint64 from the beacon API. Narrowing one at or above + // 2^63 to int wraps it negative, which passes a "too large" check + // and then panics on the bounds array, taking block processing with + // it. + name: "a sidecar with an index that wraps when narrowed", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, _ := blobTx(t, 0, 1) + blobs := []*spec.AgnosticBlobSidecar{ + {Index: deneb.BlobIndex(1 << 63), BlobHash: blobHash(1).String()}, + } + return blobs, []bellatrix.Transaction{t0}, unattributed(blobs) + }, + wantErr: true, + }, + { + name: "two sidecars claiming the same index", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, _ := blobTx(t, 0, 1) + t1, _ := blobTx(t, 1, 1) + blobs := []*spec.AgnosticBlobSidecar{ + {Index: 0, BlobHash: blobHash(1).String()}, + {Index: 0, BlobHash: blobHash(1).String()}, + } + return blobs, []bellatrix.Transaction{t0, t1}, unattributed(blobs) + }, + wantErr: true, + }, + { + name: "sidecars that the transactions did not commit to", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + t0, _ := blobTx(t, 0, 1) + t1, _ := blobTx(t, 1, 2) + blobs := sidecars(1, 8) + return blobs, []bellatrix.Transaction{t0, t1}, unattributed(blobs) + }, + wantErr: true, + }, + { + // A payload entry that is not a valid transaction is a decoding + // failure, not a mismatch, and must not be silently skipped. + name: "an undecodable transaction", + build: func(t *testing.T) ([]*spec.AgnosticBlobSidecar, []bellatrix.Transaction, []string) { + blobs := sidecars(1) + return blobs, []bellatrix.Transaction{{0xff, 0xff, 0xff}}, unattributed(blobs) + }, + wantErr: true, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + blobs, txs, want := test.build(t) + + err := spec.AssignTxHashes(blobs, txs) + + if test.wantErr && err == nil { + t.Fatal("expected an error, got none") + } + if !test.wantErr && err != nil { + t.Fatalf("unexpected error: %s", err) + } + + got := attributed(blobs) + for i := range want { + if got[i] != want[i] { + t.Errorf("blob %d: got %s, want %s", i, got[i], want[i]) + } + } + }) + } +} + +func TestAssignTxHashesCountsOnlyBlobCarriersInItsError(t *testing.T) { + // The error is the only thing anyone sees when a slot goes unattributed, so + // the transaction count in it has to mean "transactions that committed + // blobs", not "transactions in the block". Counting plain transactions here + // would send whoever reads the log looking in the wrong place. + t1, _ := blobTx(t, 1, 1) + txs := []bellatrix.Transaction{plainTx(t, 0), t1, plainTx(t, 2), plainTx(t, 3)} + + err := spec.AssignTxHashes(sidecars(1, 2), txs) + if err == nil { + t.Fatal("expected a mismatch error, got none") + } + if !strings.Contains(err.Error(), "by 1 transactions") { + t.Errorf("error should report 1 blob-carrying transaction, got: %s", err) + } +} + +func TestAssignTxHashesReportsBothHashesOnMismatch(t *testing.T) { + // The error is all anyone gets when a slot goes unattributed. Naming only + // the index leaves them unable to tell which sidecar landed where it should + // not have, which matters most in exactly the case this function exists + // for: several blobs in one block sharing a versioned hash. + tx, _ := blobTx(t, 0, 1) + arrived, committed := blobHash(8).String(), blobHash(1).String() + + err := spec.AssignTxHashes( + []*spec.AgnosticBlobSidecar{{Index: 0, BlobHash: arrived}}, + []bellatrix.Transaction{tx}, + ) + if err == nil { + t.Fatal("expected a hash mismatch error, got none") + } + msg := err.Error() + gotAt, wantAt := strings.Index(msg, arrived), strings.Index(msg, committed) + if gotAt < 0 { + t.Errorf("error omits the hash that arrived (%s): %s", arrived, msg) + } + if wantAt < 0 { + t.Errorf("error omits the hash the block committed (%s): %s", committed, msg) + } + // Naming both but the wrong way round is worse than naming neither: it + // reads plausibly and sends the reader looking for the wrong sidecar. The + // hash that arrived is described first, the one the block committed second. + if gotAt >= 0 && wantAt >= 0 && gotAt > wantAt { + t.Errorf("the hashes are the wrong way round; the arrived hash should come first: %s", msg) + } +} diff --git a/pkg/spec/deposit_counters_test.go b/pkg/spec/deposit_counters_test.go new file mode 100644 index 00000000..e4cd51c6 --- /dev/null +++ b/pkg/spec/deposit_counters_test.go @@ -0,0 +1,50 @@ +package spec + +import "testing" + +// The deposit counters on a state are accumulated while it is NextState and +// read one epoch later, while it is CurrentState. Anything that replaces or +// resets the object in between leaves them at zero, and the epoch row is then +// written with no deposits while t_deposits holds the rows +// (migalabs/goteth#287). + +func TestRefreshBlocksClearsTheDepositAccumulationFlag(t *testing.T) { + state := &AgnosticState{ + DepositsNum: 4, + TotalDepositsAmount: 128_000_000_000, + PendingDepositsProcessed: true, + } + + state.RefreshBlocks(nil) + + if state.DepositsNum != 0 { + t.Fatalf("RefreshBlocks left DepositsNum at %d; the fixture assumes it resets", + state.DepositsNum) + } + if state.PendingDepositsProcessed { + t.Error("the counters were reset but the state still claims they were accumulated, " + + "so nothing would recompute them and the epoch row would report zero deposits") + } +} + +// A freshly downloaded state has never been accumulated, which is what marks it +// for recomputation rather than being taken at face value. +func TestAFreshStateIsNotMarkedAccumulated(t *testing.T) { + if (&AgnosticState{}).PendingDepositsProcessed { + t.Error("a new state claims its deposit counters were accumulated") + } +} + +// Zero deposits is a legitimate outcome, and must stay distinguishable from +// "never counted": most epochs genuinely have none. +func TestZeroDepositsIsDistinctFromNeverCounted(t *testing.T) { + counted := &AgnosticState{DepositsNum: 0, PendingDepositsProcessed: true} + never := &AgnosticState{DepositsNum: 0} + + if !counted.PendingDepositsProcessed { + t.Error("an epoch with genuinely no deposits should not be recomputed") + } + if never.PendingDepositsProcessed { + t.Error("a state that was never counted must be recomputed") + } +} diff --git a/pkg/spec/metrics/consolidation_recompute_test.go b/pkg/spec/metrics/consolidation_recompute_test.go new file mode 100644 index 00000000..95d1ab06 --- /dev/null +++ b/pkg/spec/metrics/consolidation_recompute_test.go @@ -0,0 +1,251 @@ +package metrics + +import ( + "testing" + + "github.com/attestantio/go-eth2-client/spec/electra" + "github.com/attestantio/go-eth2-client/spec/phase0" + "github.com/migalabs/goteth/pkg/spec" +) + +// The consolidation counters have the same shape as the deposit ones fixed in +// migalabs/goteth#287: ConsolidationsProcessed is appended to and +// ConsolidationsProcessedAmount accumulated with +=, both while the state is +// NextState, and both read from CurrentState an epoch later by standard.go. A +// state re-downloaded in between reports zero while t_consolidations holds the +// rows; a state reprocessed against a retained object reports double. + +const consolidatedBalance = phase0.Gwei(32_000_000_000) + +// eth1Credentials returns a 0x01 withdrawal credential. The prefix byte is read +// unconditionally by processExcessActiveBalanceRestructuring, and keeping both +// states on the same prefix means no switch-to-compounding is detected. +func eth1Credentials() []byte { + credentials := make([]byte, 32) + credentials[0] = spec.Eth1AddressWithdrawalPrefix + return credentials +} + +// stateWithOnePendingConsolidation builds the smallest state that processes a +// single consolidation: the source is unslashed and already withdrawable, so +// neither the skip nor the break branch is taken. +func stateWithOnePendingConsolidation() *spec.AgnosticState { + return &spec.AgnosticState{ + Epoch: 10, + Validators: []*phase0.Validator{ + {EffectiveBalance: consolidatedBalance, WithdrawableEpoch: 5, WithdrawalCredentials: eth1Credentials()}, + {EffectiveBalance: consolidatedBalance, WithdrawableEpoch: phase0.Epoch(spec.FarFutureEpoch), WithdrawalCredentials: eth1Credentials()}, + }, + Balances: []phase0.Gwei{consolidatedBalance, consolidatedBalance}, + PendingConsolidations: []*electra.PendingConsolidation{{SourceIndex: 0, TargetIndex: 1}}, + ConsolidationsProcessed: make([]spec.ConsolidationProcessed, 0), + ConsolidatedAmounts: make(map[phase0.ValidatorIndex]phase0.Gwei), + } +} + +// The fix rests on this: a state that lost its counters can have them derived +// again from the state alone, reaching the numbers the original run reached. +func TestRecomputingAReplacedStateReproducesTheConsolidationCounters(t *testing.T) { + p := &ElectraMetrics{} + + accumulated := stateWithOnePendingConsolidation() + p.processPendingConsolidationsFor(accumulated) + + // The same state as it comes back from the beacon node, counters at zero. + redownloaded := stateWithOnePendingConsolidation() + p.processPendingConsolidationsFor(redownloaded) + + if len(accumulated.ConsolidationsProcessed) == 0 { + t.Fatal("the fixture processed no consolidations, so it cannot show anything") + } + if len(redownloaded.ConsolidationsProcessed) != len(accumulated.ConsolidationsProcessed) { + t.Errorf("recomputed %d consolidations, the original run reached %d", + len(redownloaded.ConsolidationsProcessed), len(accumulated.ConsolidationsProcessed)) + } + if redownloaded.ConsolidationsProcessedAmount != accumulated.ConsolidationsProcessedAmount { + t.Errorf("recomputed %d gwei, the original run reached %d", + redownloaded.ConsolidationsProcessedAmount, accumulated.ConsolidationsProcessedAmount) + } +} + +func TestProcessingMarksTheStateConsolidated(t *testing.T) { + p := &ElectraMetrics{} + state := stateWithOnePendingConsolidation() + + p.processPendingConsolidationsFor(state) + + if !state.PendingConsolidationsProcessed { + t.Error("the state was processed but not marked, so it would be recomputed again") + } +} + +// An epoch with an empty queue must still be marked, otherwise every epoch +// without consolidations, which is most of them, is recomputed on every pass. +func TestAnEmptyConsolidationQueueStillMarksTheState(t *testing.T) { + p := &ElectraMetrics{} + state := &spec.AgnosticState{Epoch: 10, ConsolidatedAmounts: make(map[phase0.ValidatorIndex]phase0.Gwei)} + + p.processPendingConsolidationsFor(state) + + if !state.PendingConsolidationsProcessed { + t.Error("a state with no pending consolidations was left unmarked") + } + if len(state.ConsolidationsProcessed) != 0 { + t.Errorf("an empty queue produced %d consolidations", len(state.ConsolidationsProcessed)) + } +} + +// Why the flag has to gate the call: the counters accumulate with += and +// append, so a second run on the same object doubles them. This pins the +// hazard the flag exists to prevent. +func TestRunningConsolidationsTwiceLeavesTheCountersUnchanged(t *testing.T) { + p := &ElectraMetrics{} + state := stateWithOnePendingConsolidation() + + p.processPendingConsolidationsFor(state) + num, amount := len(state.ConsolidationsProcessed), state.ConsolidationsProcessedAmount + + p.processPendingConsolidationsFor(state) + + if len(state.ConsolidationsProcessed) != num { + t.Errorf("ConsolidationsProcessed went from %d to %d entries on a second run", + num, len(state.ConsolidationsProcessed)) + } + if state.ConsolidationsProcessedAmount != amount { + t.Errorf("ConsolidationsProcessedAmount went from %d to %d on a second run", + amount, state.ConsolidationsProcessedAmount) + } +} + +func TestPerValidatorConsolidatedAmountsDoNotDoubleOnASecondRun(t *testing.T) { + // ConsolidatedAmounts is accumulated per validator with += as well. It is + // rebuilt from scratch by processConsolidationsForRewardCalculation on the + // PreProcessBundle path, but this function is what populates it on the + // NextState path, so it needs its own assertion. + p := &ElectraMetrics{} + state := stateWithOnePendingConsolidation() + + p.processPendingConsolidationsFor(state) + before := make(map[phase0.ValidatorIndex]phase0.Gwei, len(state.ConsolidatedAmounts)) + for idx, amount := range state.ConsolidatedAmounts { + before[idx] = amount + } + if len(before) == 0 { + t.Fatal("no per-validator amounts were recorded; the fixture no longer exercises this") + } + + p.processPendingConsolidationsFor(state) + + for idx, amount := range before { + if state.ConsolidatedAmounts[idx] != amount { + t.Errorf("validator %d went from %d to %d on a second run", idx, amount, state.ConsolidatedAmounts[idx]) + } + } +} + +func TestTheNextStateConsolidationPathIsGuardedToo(t *testing.T) { + // processPendingConsolidations runs on every ProcessStateTransitionMetrics + // call, so an epoch reprocessed against a state still held in cache - a + // dependency pass in AdvanceFinalized, a carried reprocess - went through + // this path a second time and doubled the counters. + state := stateWithOnePendingConsolidation() + p := &ElectraMetrics{} + p.baseMetrics.NextState = state + + p.processPendingConsolidations() + amount := state.ConsolidationsProcessedAmount + + p.processPendingConsolidations() + + if state.ConsolidationsProcessedAmount != amount { + t.Errorf("reprocessing through the NextState path doubled %d to %d", amount, state.ConsolidationsProcessedAmount) + } +} + +func TestRefreshingAStateAllowsConsolidationsToBeCountedAgain(t *testing.T) { + // Idempotence must not become "counted once, ever". RefreshBlocks zeroes + // the counters, so it clears the flag, and the next pass has to refill them + // or the epoch row reports no consolidations. + p := &ElectraMetrics{} + state := stateWithOnePendingConsolidation() + + p.processPendingConsolidationsFor(state) + amount := state.ConsolidationsProcessedAmount + if amount == 0 { + t.Fatal("fixture processed no consolidations") + } + + state.RefreshBlocks(nil) + if state.PendingConsolidationsProcessed { + t.Fatal("RefreshBlocks left the state marked as already accumulated") + } + + p.processPendingConsolidationsFor(state) + if state.ConsolidationsProcessedAmount != amount { + t.Errorf("after a refresh the counters came back as %d, want %d", state.ConsolidationsProcessedAmount, amount) + } +} + +func TestARefreshClearsTheConsolidationEntries(t *testing.T) { + // RefreshBlocks promises to reset the accumulators. It zeroed the deposit + // counters but left ConsolidationsProcessed and ConsolidationsProcessedAmount + // populated, so a recompute after a refresh appended a second set of rows on + // top of the first. + p := &ElectraMetrics{} + state := stateWithOnePendingConsolidation() + + p.processPendingConsolidationsFor(state) + num, amount := len(state.ConsolidationsProcessed), state.ConsolidationsProcessedAmount + if num == 0 { + t.Fatal("fixture processed no consolidations") + } + + state.RefreshBlocks(nil) + p.processPendingConsolidationsFor(state) + + if len(state.ConsolidationsProcessed) != num { + t.Errorf("after a refresh and recompute there are %d entries, want %d", len(state.ConsolidationsProcessed), num) + } + if state.ConsolidationsProcessedAmount != amount { + t.Errorf("after a refresh and recompute the amount is %d, want %d", state.ConsolidationsProcessedAmount, amount) + } +} + +// The tests above pin the function's own behaviour. This one pins the wiring: +// that PreProcessBundle recomputes against CurrentState, which is the object +// standard.go reads the epoch row from. Without that call site the function is +// correct and the epoch row is still written with zeros. +func TestPreProcessBundleFillsAReDownloadedCurrentState(t *testing.T) { + // CurrentState as it comes back from the beacon node after a reorg: the + // pending queue is there, the counters accumulated an epoch earlier are not. + currentState := stateWithOnePendingConsolidation() + currentState.StateRoot = phase0.Root{0x01} // not empty, or the bundle is a no-op + currentState.Blocks = nil // short-circuits ProcessAttestations + currentState.DepositedAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) + currentState.ConsolidatedOutAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) + + nextState := stateWithOnePendingConsolidation() + nextState.Epoch = currentState.Epoch + 1 + nextState.ConsolidatedOutAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) + nextState.DepositedAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) + + p := &ElectraMetrics{} + p.baseMetrics.CurrentState = currentState + p.baseMetrics.NextState = nextState + // PrevState carries an empty state root, so the block-reward tail of the + // bundle, which needs a far larger fixture, does not run. It still has to be + // non-nil: EmptyStateRoot has a value receiver. + p.baseMetrics.PrevState = &spec.AgnosticState{} + + if err := p.PreProcessBundle(); err != nil { + t.Fatalf("PreProcessBundle: %v", err) + } + + if currentState.ConsolidationsProcessedAmount == 0 { + t.Error("CurrentState came out of the bundle with no consolidated amount; " + + "the epoch row would be written as zero while t_consolidations holds the rows") + } + if len(currentState.ConsolidationsProcessed) == 0 { + t.Error("CurrentState came out of the bundle with no consolidation entries") + } +} diff --git a/pkg/spec/metrics/deposit_recompute_test.go b/pkg/spec/metrics/deposit_recompute_test.go new file mode 100644 index 00000000..50468e7c --- /dev/null +++ b/pkg/spec/metrics/deposit_recompute_test.go @@ -0,0 +1,211 @@ +package metrics + +import ( + "testing" + + "github.com/attestantio/go-eth2-client/spec/electra" + "github.com/attestantio/go-eth2-client/spec/phase0" + "github.com/migalabs/goteth/pkg/spec" +) + +// The deposit counters are accumulated while a state is NextState and read an +// epoch later, while it is CurrentState. A state that was re-downloaded or +// refreshed in between carries zeros, and the epoch row is then written with no +// deposits while t_deposits holds the rows (migalabs/goteth#287). + +const depositAmount = phase0.Gwei(32_000_000_000) + +// stateWithOnePendingDeposit builds the smallest state that processes a single +// deposit: the queue is finalized, the Eth1 bridge check is satisfied, and the +// balance available for processing covers the amount. +func stateWithOnePendingDeposit() *spec.AgnosticState { + var pubkey phase0.BLSPubKey + pubkey[0] = 0x01 + + return &spec.AgnosticState{ + Epoch: 10, + Validators: []*phase0.Validator{{PublicKey: pubkey, ExitEpoch: phase0.Epoch(spec.FarFutureEpoch), WithdrawableEpoch: phase0.Epoch(spec.FarFutureEpoch)}}, + PendingDeposits: []*electra.PendingDeposit{{Pubkey: pubkey, Amount: depositAmount, Slot: 0}}, + DepositBalanceToConsume: depositAmount * 4, + Eth1DepositIndex: 1, + DepositRequestsStartIndex: 0, + DepositedAmounts: make(map[phase0.ValidatorIndex]phase0.Gwei), + } +} + +// The fix rests on this: a state that lost its counters can have them derived +// again from the state alone, reaching the numbers the original run reached. +func TestRecomputingAReplacedStateReproducesTheCounters(t *testing.T) { + p := &ElectraMetrics{} + + accumulated := stateWithOnePendingDeposit() + p.processPendingDepositsFor(accumulated) + + // The same state as it comes back from the beacon node, counters at zero. + redownloaded := stateWithOnePendingDeposit() + p.processPendingDepositsFor(redownloaded) + + if accumulated.DepositsNum == 0 { + t.Fatal("the fixture processed no deposits, so it cannot show anything") + } + if redownloaded.DepositsNum != accumulated.DepositsNum { + t.Errorf("recomputed %d deposits, the original run reached %d", + redownloaded.DepositsNum, accumulated.DepositsNum) + } + if redownloaded.TotalDepositsAmount != accumulated.TotalDepositsAmount { + t.Errorf("recomputed %d gwei, the original run reached %d", + redownloaded.TotalDepositsAmount, accumulated.TotalDepositsAmount) + } +} + +func TestProcessingMarksTheStateAccumulated(t *testing.T) { + p := &ElectraMetrics{} + state := stateWithOnePendingDeposit() + + p.processPendingDepositsFor(state) + + if !state.PendingDepositsProcessed { + t.Error("the state was processed but not marked, so it would be recomputed again") + } +} + +// An epoch with an empty queue must still be marked, otherwise every epoch +// without deposits, which is most of them, is recomputed on every pass. +func TestAnEmptyQueueStillMarksTheState(t *testing.T) { + p := &ElectraMetrics{} + state := &spec.AgnosticState{Epoch: 10, DepositedAmounts: make(map[phase0.ValidatorIndex]phase0.Gwei)} + + p.processPendingDepositsFor(state) + + if !state.PendingDepositsProcessed { + t.Error("a state with no pending deposits was left unmarked") + } + if state.DepositsNum != 0 { + t.Errorf("an empty queue produced %d deposits", state.DepositsNum) + } +} + +// Why PendingDepositsProcessed has to gate the call: the counters accumulate +// with +=, so a second run on the same object doubles them. This pins the +// hazard the flag exists to prevent. +func TestRunningTwiceOnOneStateLeavesTheCountersUnchanged(t *testing.T) { + // The counters accumulate with +=, so a second pass over the same state + // object would double them. The same object legitimately reaches this + // function twice - once as NextState during its own epoch, once as + // CurrentState an epoch later - so idempotence is what makes the second + // call safe rather than a guard at one call site. + p := &ElectraMetrics{} + state := stateWithOnePendingDeposit() + + p.processPendingDepositsFor(state) + num, amount, deposits := state.DepositsNum, state.TotalDepositsAmount, len(state.DepositsProcessed) + + p.processPendingDepositsFor(state) + + if state.DepositsNum != num { + t.Errorf("DepositsNum went from %d to %d on a second run", num, state.DepositsNum) + } + if state.TotalDepositsAmount != amount { + t.Errorf("TotalDepositsAmount went from %d to %d on a second run", amount, state.TotalDepositsAmount) + } + if len(state.DepositsProcessed) != deposits { + t.Errorf("DepositsProcessed went from %d to %d entries on a second run", deposits, len(state.DepositsProcessed)) + } +} + +func TestPerValidatorAmountsDoNotDoubleOnASecondRun(t *testing.T) { + // DepositedAmounts is accumulated per validator with += as well, and it + // feeds the per-validator deposit rows rather than the epoch counters, so + // it needs its own assertion. + p := &ElectraMetrics{} + state := stateWithOnePendingDeposit() + + p.processPendingDepositsFor(state) + before := make(map[phase0.ValidatorIndex]phase0.Gwei, len(state.DepositedAmounts)) + for idx, amount := range state.DepositedAmounts { + before[idx] = amount + } + if len(before) == 0 { + t.Fatal("no per-validator amounts were recorded; the fixture no longer exercises this") + } + + p.processPendingDepositsFor(state) + + for idx, amount := range before { + if state.DepositedAmounts[idx] != amount { + t.Errorf("validator %d went from %d to %d on a second run", idx, amount, state.DepositedAmounts[idx]) + } + } +} + +func TestTheNextStatePathIsGuardedToo(t *testing.T) { + // The failure the guard-at-one-call-site version missed: processPendingDeposits + // runs unconditionally on every ProcessStateTransitionMetrics call, so an + // epoch reprocessed against a state still held in cache - a dependency pass + // in AdvanceFinalized, a carried reprocess, a refresh that failed - went + // through this path a second time and doubled the counters. + state := stateWithOnePendingDeposit() + p := &ElectraMetrics{} + p.baseMetrics.NextState = state + + p.processPendingDeposits() + num := state.DepositsNum + + p.processPendingDeposits() + + if state.DepositsNum != num { + t.Errorf("reprocessing through the NextState path doubled %d to %d", num, state.DepositsNum) + } +} + +func TestRefreshingAStateAllowsItToBeCountedAgain(t *testing.T) { + // Idempotence must not become "counted once, ever". RefreshBlocks zeroes + // the counters, so it clears the flag, and the next pass has to refill them + // or the epoch row reports no deposits (#287 in the other direction). + p := &ElectraMetrics{} + state := stateWithOnePendingDeposit() + + p.processPendingDepositsFor(state) + num := state.DepositsNum + if num == 0 { + t.Fatal("fixture processed no deposits") + } + + state.RefreshBlocks(nil) + if state.PendingDepositsProcessed { + t.Fatal("RefreshBlocks left the state marked as already accumulated") + } + + p.processPendingDepositsFor(state) + if state.DepositsNum != num { + t.Errorf("after a refresh the counters came back as %d, want %d", state.DepositsNum, num) + } +} + +func TestARefreshResetsThePerValidatorAmountsToo(t *testing.T) { + // RefreshBlocks promises to reset the accumulators so that recalculating + // does not double-count. DepositedAmounts accumulates with += and was left + // populated, so the scalar counters came back correct while the + // per-validator amounts came back doubled. + p := &ElectraMetrics{} + state := stateWithOnePendingDeposit() + + p.processPendingDepositsFor(state) + want := make(map[phase0.ValidatorIndex]phase0.Gwei, len(state.DepositedAmounts)) + for idx, amount := range state.DepositedAmounts { + want[idx] = amount + } + if len(want) == 0 { + t.Fatal("no per-validator amounts were recorded; the fixture no longer exercises this") + } + + state.RefreshBlocks(nil) + p.processPendingDepositsFor(state) + + for idx, amount := range want { + if state.DepositedAmounts[idx] != amount { + t.Errorf("validator %d: %d after a refresh and recompute, want %d", + idx, state.DepositedAmounts[idx], amount) + } + } +} diff --git a/pkg/spec/metrics/state_electra.go b/pkg/spec/metrics/state_electra.go index e6df3ab6..7fb52b6f 100644 --- a/pkg/spec/metrics/state_electra.go +++ b/pkg/spec/metrics/state_electra.go @@ -52,6 +52,31 @@ func (p *ElectraMetrics) PreProcessBundle() error { return err } p.processPendingDeposits() + + // The epoch row for CurrentState.Epoch reads its deposit counters from + // CurrentState, but they were accumulated an epoch earlier, while that + // object was NextState. Reorg handling deletes and re-downloads states + // (AdvanceFinalized, ensureDependencyStates) and RefreshBlocks zeroes + // these counters outright, so the object serving as CurrentState here is + // not always the one that was accumulated. When it is not, the counters + // read as exactly zero while t_deposits holds the rows. + // + // Recompute from the state itself, which is deterministic and costs + // nothing on the common path where the object survived (#287): the + // function returns immediately for a state that has already been + // through it. + p.processPendingDepositsFor(p.baseMetrics.CurrentState) + + // The consolidation counters have the same lifecycle and the same + // failure: ConsolidationsProcessedNum and ConsolidationsProcessedAmount + // are read from CurrentState in standard.go but accumulated an epoch + // earlier against NextState, so a re-downloaded object reports zero + // while t_consolidations holds the rows. This runs before the + // ConsolidatedAmounts maps are cleared below, so only the epoch-row + // counters survive it; the per-validator reward maps are rebuilt by + // processConsolidationsForRewardCalculation as before. + p.processPendingConsolidationsFor(p.baseMetrics.CurrentState) + // FIX: Clear state maps before processing (state objects are reused between iterations) p.baseMetrics.CurrentState.ConsolidatedAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) p.baseMetrics.CurrentState.ConsolidatedOutAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) @@ -60,7 +85,7 @@ func (p *ElectraMetrics) PreProcessBundle() error { p.processExcessActiveBalanceRestructuring(p.baseMetrics.CurrentState, p.baseMetrics.NextState) p.processConsolidationsForRewardCalculation(p.baseMetrics.CurrentState, p.baseMetrics.NextState) p.processDepositsForRewardCalculation(p.baseMetrics.CurrentState, p.baseMetrics.NextState) - p.processPendingConsolidations(p.baseMetrics.NextState) + p.processPendingConsolidations() if !p.baseMetrics.PrevState.EmptyStateRoot() { // block rewards p.ProcessSlashings() @@ -607,7 +632,19 @@ func (p ElectraMetrics) getParticipationFlags(attestation electra.Attestation, i } // // https://github.com/ethereum/consensus-specs/blob/dev/specs/electra/beacon-chain.md#new-process_pending_consolidations -func (p ElectraMetrics) processPendingConsolidations(s *spec.AgnosticState) { +func (p *ElectraMetrics) processPendingConsolidations() { + p.processPendingConsolidationsFor(p.baseMetrics.NextState) +} + +// processPendingConsolidationsFor walks a state's pending consolidation queue, +// accumulating the counters the epoch row reads. It is safe to call twice on +// the same state: the counters accumulate with += and append, so the flag makes +// the second call a no-op rather than a doubling. +func (p *ElectraMetrics) processPendingConsolidationsFor(s *spec.AgnosticState) { + if s.PendingConsolidationsProcessed { + return + } + nextEpoch := s.Epoch + 1 for index, pendingConsolidation := range s.PendingConsolidations { @@ -636,6 +673,8 @@ func (p ElectraMetrics) processPendingConsolidations(s *spec.AgnosticState) { s.ConsolidationsProcessed = append(s.ConsolidationsProcessed, *consolidationProcessed) s.ConsolidationsProcessedAmount += sourceEffectiveBalance } + + s.PendingConsolidationsProcessed = true } // processConsolidationsForRewardCalculation replays the spec's process_pending_consolidations @@ -862,8 +901,30 @@ func (p *ElectraMetrics) ProcessSlashings() { // https://github.com/ethereum/consensus-specs/blob/dev/specs/electra/beacon-chain.md#new-process_pending_deposits func (p *ElectraMetrics) processPendingDeposits() { - nextEpoch := p.baseMetrics.NextState.Epoch + 1 - state := p.baseMetrics.NextState + p.processPendingDepositsFor(p.baseMetrics.NextState) +} + +// processPendingDepositsFor walks a state's pending deposit queue, accumulating +// its deposit counters and rebuilding its list of processed deposits. What it +// derives depends only on the state passed in, so running it on a state that +// was re-downloaded reproduces the numbers the original accumulation reached. +// +// It is idempotent, and that is load-bearing rather than a nicety. The counters +// are accumulated with +=, not assigned, so a second run would double them, and +// the same state object legitimately reaches this function twice: once as +// NextState during its own epoch, and again as CurrentState an epoch later. +// Reprocessing adds more ways in - a dependency-triggered pass in +// AdvanceFinalized, a carried reprocess, a state retained in cache rather than +// re-downloaded. Guarding at one call site only protects that call site, so the +// guard lives here, where every path meets. +// +// RefreshBlocks clears the flag, because it zeroes the counters this sets. +func (p *ElectraMetrics) processPendingDepositsFor(state *spec.AgnosticState) { + if state.PendingDepositsProcessed { + return + } + + nextEpoch := state.Epoch + 1 availableForProcessing := state.DepositBalanceToConsume + phase0.Gwei(getActivationExitChurnLimit(state)) processedAmount := phase0.Gwei(0) nextDepositIndex := uint64(0) @@ -935,4 +996,5 @@ func (p *ElectraMetrics) processPendingDeposits() { state.TotalDepositsAmount += deposit.Amount } state.DepositsProcessed = processedDeposits + state.PendingDepositsProcessed = true } diff --git a/pkg/spec/state.go b/pkg/spec/state.go index c427e3ae..e49903a9 100644 --- a/pkg/spec/state.go +++ b/pkg/spec/state.go @@ -42,13 +42,19 @@ type AgnosticState struct { Deposits []phase0.Gwei // one per validator index DepositsNum uint64 // number of deposits TotalDepositsAmount phase0.Gwei // total amount of deposits - CurrentJustifiedCheckpoint phase0.Checkpoint // the latest justified checkpoint - CurrentFinalizedCheckpoint phase0.Checkpoint // the latest finalized checkpoint - LatestBlockHeader *phase0.BeaconBlockHeader - SyncCommitteeParticipation uint64 // Tracks sync committee participation - NewProposerSlashings int // number of new proposer slashings - NewAttesterSlashings int // number of new attester slashings - Slashings []AgnosticSlashing + // PendingDepositsProcessed records whether the two counters above were + // accumulated for this state object. They are filled while the state is + // NextState and read one epoch later while it is CurrentState, so a state + // that was re-downloaded or refreshed in between carries zeros that nothing + // else recomputes (migalabs/goteth#287). + PendingDepositsProcessed bool + CurrentJustifiedCheckpoint phase0.Checkpoint // the latest justified checkpoint + CurrentFinalizedCheckpoint phase0.Checkpoint // the latest finalized checkpoint + LatestBlockHeader *phase0.BeaconBlockHeader + SyncCommitteeParticipation uint64 // Tracks sync committee participation + NewProposerSlashings int // number of new proposer slashings + NewAttesterSlashings int // number of new attester slashings + Slashings []AgnosticSlashing // Electra ConsolidationRequests []ConsolidationRequest WithdrawalRequests []WithdrawalRequest @@ -56,16 +62,21 @@ type AgnosticState struct { PendingConsolidations []*electra.PendingConsolidation PendingPartialWithdrawals []*electra.PendingPartialWithdrawal ConsolidationsProcessed []ConsolidationProcessed - ConsolidationsProcessedAmount phase0.Gwei // total amount of Gwei consolidated - NewExitingValidators []phase0.ValidatorIndex // list of validators that are exiting due to consolidation/withdrawal requests, used for tracking errors of a validator trying to consolidate/withdraw twice on same epoch. - ConsolidatedAmounts map[phase0.ValidatorIndex]phase0.Gwei // map of validator index to consolidated amount (target receives) - ConsolidatedOutAmounts map[phase0.ValidatorIndex]phase0.Gwei // map of validator index to outgoing consolidated amount (source sends) - PendingDeposits []*electra.PendingDeposit - DepositsProcessed []Deposit - DepositedAmounts map[phase0.ValidatorIndex]phase0.Gwei // map of validator index to deposited amount (used for Electra Fork) - DepositBalanceToConsume phase0.Gwei // balance to consume for deposits, used for Electra Fork - Eth1DepositIndex uint64 // index of the next deposit request to be processed, used for Electra Fork - DepositRequestsStartIndex uint64 // index of the next deposit request to be processed, used for Electra Fork + ConsolidationsProcessedAmount phase0.Gwei // total amount of Gwei consolidated + // PendingConsolidationsProcessed records whether ConsolidationsProcessed and + // ConsolidationsProcessedAmount were accumulated for this state object. They + // have the same lifecycle as the deposit counters above: filled while the + // state is NextState, read an epoch later while it is CurrentState. + PendingConsolidationsProcessed bool + NewExitingValidators []phase0.ValidatorIndex // list of validators that are exiting due to consolidation/withdrawal requests, used for tracking errors of a validator trying to consolidate/withdraw twice on same epoch. + ConsolidatedAmounts map[phase0.ValidatorIndex]phase0.Gwei // map of validator index to consolidated amount (target receives) + ConsolidatedOutAmounts map[phase0.ValidatorIndex]phase0.Gwei // map of validator index to outgoing consolidated amount (source sends) + PendingDeposits []*electra.PendingDeposit + DepositsProcessed []Deposit + DepositedAmounts map[phase0.ValidatorIndex]phase0.Gwei // map of validator index to deposited amount (used for Electra Fork) + DepositBalanceToConsume phase0.Gwei // balance to consume for deposits, used for Electra Fork + Eth1DepositIndex uint64 // index of the next deposit request to be processed, used for Electra Fork + DepositRequestsStartIndex uint64 // index of the next deposit request to be processed, used for Electra Fork } func GetCustomState(bstate spec.VersionedBeaconState, duties EpochDuties) (AgnosticState, error) { @@ -140,6 +151,25 @@ func (p *AgnosticState) RefreshBlocks(blockList []*AgnosticBlock) { p.TotalWithdrawalsAmount = 0 p.DepositsNum = 0 p.TotalDepositsAmount = 0 + // Reset the flag with the counters it describes. Leaving it set would let a + // refreshed state claim numbers it no longer has, and nothing would + // recompute them. + p.PendingDepositsProcessed = false + // DepositedAmounts accumulates per validator with +=, so it is one of the + // accumulators this function promises to reset. Zeroing DepositsNum while + // leaving this populated meant the next pass added a second time and the + // per-validator amounts doubled, even though the scalar counters looked + // right. + p.DepositedAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) + // The consolidation counters have the same shape as the deposit ones: a + // slice appended to and a total accumulated with +=, both read from + // CurrentState by the epoch row. They were left populated here, so a + // refreshed state kept the old entries and the next pass added to them. + p.ConsolidationsProcessed = make([]ConsolidationProcessed, 0) + p.ConsolidationsProcessedAmount = 0 + p.PendingConsolidationsProcessed = false + p.ConsolidatedAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) + p.ConsolidatedOutAmounts = make(map[phase0.ValidatorIndex]phase0.Gwei) p.NumAttestations = 0 p.SyncCommitteeParticipation = 0 p.AddBlocks(blockList) diff --git a/pkg/spec/validator_last_status.go b/pkg/spec/validator_last_status.go index e4e3a202..13bee5db 100644 --- a/pkg/spec/validator_last_status.go +++ b/pkg/spec/validator_last_status.go @@ -7,17 +7,18 @@ import ( ) type ValidatorLastStatus struct { - ValIdx phase0.ValidatorIndex - Epoch phase0.Epoch - CurrentBalance phase0.Gwei - EffectiveBalance phase0.Gwei - CurrentStatus ValidatorStatus - Slashed bool - ActivationEpoch phase0.Epoch - WithdrawalEpoch phase0.Epoch - ExitEpoch phase0.Epoch - PublicKey phase0.BLSPubKey - WithdrawalCredentials []byte + ValIdx phase0.ValidatorIndex + Epoch phase0.Epoch + CurrentBalance phase0.Gwei + EffectiveBalance phase0.Gwei + CurrentStatus ValidatorStatus + Slashed bool + ActivationEpoch phase0.Epoch + ActivationEligibilityEpoch phase0.Epoch + WithdrawalEpoch phase0.Epoch + ExitEpoch phase0.Epoch + PublicKey phase0.BLSPubKey + WithdrawalCredentials []byte } func (f ValidatorLastStatus) ToArray() []interface{} { @@ -29,6 +30,7 @@ func (f ValidatorLastStatus) ToArray() []interface{} { resultArgs = append(resultArgs, f.CurrentStatus) resultArgs = append(resultArgs, f.Slashed) resultArgs = append(resultArgs, f.ActivationEpoch) + resultArgs = append(resultArgs, f.ActivationEligibilityEpoch) resultArgs = append(resultArgs, f.WithdrawalEpoch) resultArgs = append(resultArgs, f.ExitEpoch) resultArgs = append(resultArgs, f.PublicKey.String()) diff --git a/pkg/utils/book.go b/pkg/utils/book.go index ba96c75c..016ea4a7 100644 --- a/pkg/utils/book.go +++ b/pkg/utils/book.go @@ -8,14 +8,21 @@ import ( ) var ( - emptyKey = "" structName = "routinebook" CheckPageInterval = 1 * time.Second ) +// RoutineBook is a counting semaphore that also records what is holding each +// slot, so callers can ask whether a given key is still being worked on. +// +// pages counts holders rather than marking presence. Acquire is not a per-key +// lock: two goroutines can acquire the same key, and each takes its own token. +// While a page was a bare marker the second acquire overwrote the first and +// only one FreePage found a key to delete, so one token was never returned and +// the pool shrank by one every time it happened (migalabs/goteth#292). type RoutineBook struct { sync.Mutex - pages map[string]string + pages map[string]int freeSpaceChan chan struct{} size int64 bookTag string @@ -24,8 +31,8 @@ type RoutineBook struct { func NewRoutineBook(size int, tag string) *RoutineBook { r := &RoutineBook{ - pages: make(map[string]string, size), // contains a list of keys identifying routines - freeSpaceChan: make(chan struct{}, size), // indicates the free position in the array + pages: make(map[string]int, size), // holders per key, see the type comment + freeSpaceChan: make(chan struct{}, size), // indicates the free position in the array size: int64(size), bookTag: tag, } @@ -50,23 +57,36 @@ func (r *RoutineBook) Acquire(key string) { case <-ticker.C: log.WithField("bookTag", r.bookTag).Warnf("Waiting for too long to acquire page %s...", key) case <-r.freeSpaceChan: - r.Set(key, "active") + r.hold(key) return } } } +// FreePage releases one holder of key and returns its token. +// +// The token goes back for every held acquire, not once per key: releasing only +// once would strand the tokens of any other holder of the same key. A key with +// no holders returns nothing, which keeps the channel from being filled past +// its capacity - a send that blocked there would never complete. func (r *RoutineBook) FreePage(key string) { r.Lock() - defer r.Unlock() - _, ok := r.pages[key] - // If the key exists - if ok { + holders, ok := r.pages[key] + if !ok || holders <= 0 { + r.Unlock() + return + } + if holders == 1 { delete(r.pages, key) - r.freeSpaceChan <- struct{}{} + } else { + r.pages[key] = holders - 1 } + r.Unlock() + // Outside the lock: a send here can only block if the channel is full, + // and blocking while holding the mutex would stop every other caller. + r.freeSpaceChan <- struct{}{} } func (r *RoutineBook) CheckPageActive(key string) bool { @@ -77,30 +97,54 @@ func (r *RoutineBook) CheckPageActive(key string) bool { } -func (r *RoutineBook) WaitUntilInactive(key string) bool { +// WaitUntilInactive blocks until nothing holds key. +// +// The ticker is stopped on the way out. It was not, and an unstopped ticker is +// never collected, so every call left a runtime timer behind - once per block +// processed and once per slot of every reorg walk. +// +// The wait is unbounded, which is deliberate: the caller is about to replace +// something the holder is still reading, and giving up would defeat the point. +// It warns while it waits, the way Acquire does, so a barrier that never clears +// is visible rather than silent. +// +// It returned a bool that no caller read and that could only ever be true: the +// old loop ranged over a ticker channel, which is never closed, so the trailing +// `return false` was unreachable. +func (r *RoutineBook) WaitUntilInactive(key string) { ticker := time.NewTicker(CheckPageInterval) + defer ticker.Stop() - for range ticker.C { + warn := time.NewTicker(AcquireWaitIntervalLog) + defer warn.Stop() - _, ok := r.get(key) + // Checked before the first tick. The loop used to wait a whole interval + // before looking, so a key nobody held still cost that second - once per + // block processed, since ProcessBlock waits on its own slot key. + if _, ok := r.get(key); !ok { + return + } - if !ok { - return true + for { + select { + case <-warn.C: + log.WithField("bookTag", r.bookTag).Warnf("Still waiting for page %s to become inactive...", key) + case <-ticker.C: + if _, ok := r.get(key); !ok { + return + } } } - - return false - } -func (r *RoutineBook) Set(key string, value string) { +// hold records one more holder of key. The caller has already taken a token. +func (r *RoutineBook) hold(key string) { r.Lock() defer r.Unlock() - r.pages[key] = value // book page - + r.pages[key]++ } -func (r *RoutineBook) get(key string) (string, bool) { +func (r *RoutineBook) get(key string) (int, bool) { r.Lock() defer r.Unlock() @@ -110,24 +154,25 @@ func (r *RoutineBook) get(key string) (string, bool) { } +// ActivePages is the number of holders across all keys, which is what the +// shutdown checks mean by "anything still running". Two holders of one key +// count twice, because two routines are running. func (r *RoutineBook) ActivePages() int { r.Lock() defer r.Unlock() result := 0 - for _, item := range r.pages { - if item != emptyKey { - result += 1 - } + for _, holders := range r.pages { + result += holders } return result } +// NumFreePages counts the tokens still available. It reads the channel rather +// than subtracting the number of keys: a key can have several holders, so the +// key count stopped matching the tokens in use once pages began counting. func (r *RoutineBook) NumFreePages() int { - - r.Lock() - defer r.Unlock() - return int(r.size) - len(r.pages) + return len(r.freeSpaceChan) } func (r *RoutineBook) GetKeys() []string { diff --git a/pkg/utils/book_test.go b/pkg/utils/book_test.go new file mode 100644 index 00000000..6a9b3ad8 --- /dev/null +++ b/pkg/utils/book_test.go @@ -0,0 +1,206 @@ +package utils + +import ( + "sync" + "testing" + "time" +) + +// Acquire looks like a per-key lock but is a counting semaphore that records +// what holds each slot. Two goroutines can acquire the same key, and each takes +// its own token. While a page was a bare marker the second acquire overwrote +// the first, so only one FreePage found a key to delete and one token was never +// returned: the pool shrank by one every time, until nothing could acquire at +// all (migalabs/goteth#292). + +func TestAcquiringOneKeyTwiceReturnsBothTokens(t *testing.T) { + book := NewRoutineBook(4, "test") + + book.Acquire("epoch=471766") + book.Acquire("epoch=471766") + if free := book.NumFreePages(); free != 2 { + t.Fatalf("two acquires left %d of 4 tokens free, want 2", free) + } + + book.FreePage("epoch=471766") + book.FreePage("epoch=471766") + + if free := book.NumFreePages(); free != 4 { + t.Errorf("after releasing both holders %d of 4 tokens are free, want 4; "+ + "the missing one is gone for the life of the process", free) + } +} + +// The consequence, stated as the pool sees it: repeat the leak and the book +// runs out of slots even though nothing is holding any. +func TestRepeatedDuplicateAcquiresDoNotExhaustThePool(t *testing.T) { + book := NewRoutineBook(2, "test") + + for i := 0; i < 10; i++ { + book.Acquire("epoch=100") + book.Acquire("epoch=100") + book.FreePage("epoch=100") + book.FreePage("epoch=100") + } + + if free := book.NumFreePages(); free != 2 { + t.Errorf("after 10 paired acquire/free rounds %d of 2 tokens are free; "+ + "the pool is exhausted and the next Acquire blocks forever", free) + } + if active := book.ActivePages(); active != 0 { + t.Errorf("book reports %d active holders with none outstanding", active) + } +} + +// A key stays active while any holder is still working, or a reorg would +// replace a state out from under a processor that is still reading it. +func TestAKeyStaysActiveUntilTheLastHolderReleasesIt(t *testing.T) { + book := NewRoutineBook(4, "test") + + book.Acquire("epoch=10") + book.Acquire("epoch=10") + + book.FreePage("epoch=10") + if !book.CheckPageActive("epoch=10") { + t.Error("the key went inactive while a second holder was still working") + } + + book.FreePage("epoch=10") + if book.CheckPageActive("epoch=10") { + t.Error("the key stayed active after its last holder released it") + } +} + +// Freeing a key nobody holds must not push a token into the channel: the pool +// would grow past its size, and once the channel is full that send blocks +// forever. +func TestFreeingAKeyNobodyHoldsDoesNotInventTokens(t *testing.T) { + book := NewRoutineBook(2, "test") + + done := make(chan struct{}) + go func() { + defer close(done) + book.FreePage("never-acquired") + book.FreePage("never-acquired") + book.FreePage("never-acquired") + }() + + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("FreePage blocked on a full channel; the pool was over-filled") + } + + if free := book.NumFreePages(); free != 2 { + t.Errorf("pool holds %d tokens, want 2", free) + } +} + +func TestActivePagesCountsHoldersNotKeys(t *testing.T) { + // The shutdown check asks "is anything still running", so two routines on + // one key must count twice. + book := NewRoutineBook(4, "test") + + book.Acquire("epoch=10") + book.Acquire("epoch=10") + book.Acquire("epoch=11") + + if active := book.ActivePages(); active != 3 { + t.Errorf("ActivePages reported %d, want 3; a shutdown check would think "+ + "fewer routines were running than there are", active) + } +} + +func TestConcurrentAcquireAndFreeKeepsTheAccountingExact(t *testing.T) { + book := NewRoutineBook(8, "test") + + var wg sync.WaitGroup + for i := 0; i < 50; i++ { + wg.Add(1) + go func() { + defer wg.Done() + book.Acquire("epoch=1") + book.FreePage("epoch=1") + }() + } + wg.Wait() + + if free := book.NumFreePages(); free != 8 { + t.Errorf("after 50 paired acquire/free rounds %d of 8 tokens are free", free) + } + if active := book.ActivePages(); active != 0 { + t.Errorf("%d holders still recorded with none outstanding", active) + } +} + +// WaitUntilInactive is what stops a reorg replacing a state a processor is +// still reading. It has to return once the last holder releases the key, and +// not before. +func TestWaitUntilInactiveReturnsWhenTheLastHolderReleases(t *testing.T) { + previous := CheckPageInterval + CheckPageInterval = time.Millisecond + defer func() { CheckPageInterval = previous }() + + book := NewRoutineBook(4, "test") + book.Acquire("epoch=10") + book.Acquire("epoch=10") + + returned := make(chan struct{}) + go func() { + defer close(returned) + book.WaitUntilInactive("epoch=10") + }() + + book.FreePage("epoch=10") + select { + case <-returned: + t.Fatal("the wait returned while a second holder was still working; " + + "the caller would replace the state underneath it") + case <-time.After(50 * time.Millisecond): + } + + book.FreePage("epoch=10") + select { + case <-returned: + case <-time.After(5 * time.Second): + t.Fatal("the wait never returned after the last holder released the key") + } +} + +func TestWaitUntilInactiveReturnsImmediatelyForAnUnheldKey(t *testing.T) { + previous := CheckPageInterval + CheckPageInterval = time.Millisecond + defer func() { CheckPageInterval = previous }() + + book := NewRoutineBook(4, "test") + + returned := make(chan struct{}) + go func() { + defer close(returned) + book.WaitUntilInactive("nobody-holds-this") + }() + + select { + case <-returned: + case <-time.After(5 * time.Second): + t.Fatal("waiting on a key nobody holds never returned") + } +} + +// The unheld case has to be free. ProcessBlock waits on its own slot key for +// every block, so a wasted interval there is a wasted interval per block. +func TestWaitUntilInactiveDoesNotPayAnIntervalForAnUnheldKey(t *testing.T) { + previous := CheckPageInterval + CheckPageInterval = 2 * time.Second + defer func() { CheckPageInterval = previous }() + + book := NewRoutineBook(4, "test") + + start := time.Now() + book.WaitUntilInactive("nobody-holds-this") + + if elapsed := time.Since(start); elapsed > time.Second { + t.Errorf("waiting on an unheld key took %s; it should not wait for a tick "+ + "before looking", elapsed) + } +} diff --git a/pkg/utils/constants.go b/pkg/utils/constants.go index d20a9a7f..fa09b67b 100644 --- a/pkg/utils/constants.go +++ b/pkg/utils/constants.go @@ -3,7 +3,7 @@ package utils import "time" const ( - Version = "v3.8.2" + Version = "v3.9.0" CliName = "GotEth" RoutineFlushTimeout = time.Duration(1 * time.Second) AcquireWaitIntervalLog = 1 * time.Minute diff --git a/pkg/utils/ticker_lifecycle_test.go b/pkg/utils/ticker_lifecycle_test.go new file mode 100644 index 00000000..45c81bba --- /dev/null +++ b/pkg/utils/ticker_lifecycle_test.go @@ -0,0 +1,164 @@ +package utils + +import ( + "go/ast" + "go/parser" + "go/token" + "os" + "path/filepath" + "strings" + "testing" +) + +// A time.Ticker that is never stopped is never collected: it goes on waking the +// runtime at its interval for the life of the process. That is harmless for a +// ticker created once per long-running routine and a leak for one created +// inside a loop. +// +// goteth had four of the second kind, all in retry or rate-limit paths, so they +// accumulated exactly when the node was already under stress (issue #295). A +// one-shot wait wants time.Sleep; a real ticker wants Stop. +// +// This walks the repository because the rule is about every package, and +// because a convention nobody can see is one that gets broken again. +func TestEveryTickerIsStopped(t *testing.T) { + root, err := filepath.Abs(filepath.Join("..", "..")) + if err != nil { + t.Fatal(err) + } + + checked := 0 + err = filepath.Walk(root, func(path string, info os.FileInfo, err error) error { + if err != nil { + return err + } + if info.IsDir() { + // Vendored and generated trees are not ours to police. + switch info.Name() { + case ".git", "vendor", "go-relay-client": + return filepath.SkipDir + } + return nil + } + if !strings.HasSuffix(path, ".go") || strings.HasSuffix(path, "_test.go") { + return nil + } + + fset := token.NewFileSet() + file, err := parser.ParseFile(fset, path, nil, 0) + if err != nil { + return err + } + rel, _ := filepath.Rel(root, path) + + ast.Inspect(file, func(n ast.Node) bool { + fn, ok := n.(*ast.FuncDecl) + if !ok || fn.Body == nil { + return true + } + named, unnamed := tickersIn(fn) + for name, pos := range named { + checked++ + if !stopsTicker(fn, name) { + t.Errorf("%s:%d: ticker %q is never stopped. If it is a one-shot "+ + "wait use time.Sleep; if it is a real ticker add defer %s.Stop(). "+ + "An unstopped ticker keeps firing for the life of the process.", + rel, fset.Position(pos).Line, name, name) + } + } + // A ticker nobody keeps cannot be stopped by anybody. <-time.NewTicker(d).C + // reads as a one-shot wait and leaks exactly like the assigned version, + // which is why it is named rather than merely uncounted. + for _, pos := range unnamed { + checked++ + t.Errorf("%s:%d: time.NewTicker result is not held, so it can never be "+ + "stopped. For a one-shot wait use time.Sleep.", + rel, fset.Position(pos).Line) + } + return true + }) + return nil + }) + if err != nil { + t.Fatal(err) + } + + // If the walk stops finding tickers, this test has quietly stopped testing + // anything - a rename of the package or a move of the tree would do it. + if checked == 0 { + t.Fatal("found no time.NewTicker calls at all; this test is no longer looking " + + "at the right tree") + } + t.Logf("checked %d tickers", checked) +} + +// tickersIn returns the variables in fn assigned from time.NewTicker, and the +// positions of any NewTicker call whose result is not bound to a variable at +// all. The second group needs no Stop check: nothing holds them, so nothing can +// stop them. +func tickersIn(fn *ast.FuncDecl) (map[string]token.Pos, []token.Pos) { + named := map[string]token.Pos{} + bound := map[token.Pos]bool{} + + ast.Inspect(fn.Body, func(n ast.Node) bool { + assign, ok := n.(*ast.AssignStmt) + if !ok || len(assign.Lhs) != 1 || len(assign.Rhs) != 1 { + return true + } + if !isCallTo(assign.Rhs[0], "time", "NewTicker") { + return true + } + bound[assign.Rhs[0].Pos()] = true + if name, ok := assign.Lhs[0].(*ast.Ident); ok { + named[name.Name] = assign.Pos() + } + return true + }) + + var unnamed []token.Pos + ast.Inspect(fn.Body, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok || !isCallTo(call, "time", "NewTicker") || bound[call.Pos()] { + return true + } + unnamed = append(unnamed, call.Pos()) + return true + }) + return named, unnamed +} + +// stopsTicker reports whether fn calls name.Stop() anywhere, deferred or not. +func stopsTicker(fn *ast.FuncDecl, name string) bool { + stopped := false + ast.Inspect(fn.Body, func(n ast.Node) bool { + if isCallTo(n, name, "Stop") { + stopped = true + } + return !stopped + }) + return stopped +} + +func isCallTo(n ast.Node, receiver, method string) bool { + var fun ast.Expr + switch v := n.(type) { + case *ast.CallExpr: + fun = v.Fun + case *ast.DeferStmt: + fun = v.Call.Fun + case *ast.ExprStmt: + call, ok := v.X.(*ast.CallExpr) + if !ok { + return false + } + fun = call.Fun + default: + return false + } + sel, ok := fun.(*ast.SelectorExpr) + if !ok || sel.Sel.Name != method { + return false + } + ident, ok := sel.X.(*ast.Ident) + return ok && ident.Name == receiver +} diff --git a/pkg/validator_window/window.go b/pkg/validator_window/window.go index 49c79893..384ffcc8 100644 --- a/pkg/validator_window/window.go +++ b/pkg/validator_window/window.go @@ -2,6 +2,8 @@ package validatorwindow import ( "context" + "strconv" + "strings" "sync" "time" @@ -22,15 +24,17 @@ var ( ) type ValidatorWindowRunner struct { - ctx context.Context - dbClient *db.DBService // client to communicate with psql - eventsObj events.Events // object to receive signals from beacon node (needed to trigger the deletes) - stop bool // used to know if the tool should stop - windowEpochSize int // number of epochs of data to maintain in the database - deleteCadenceEpochs int // only emit DELETE once the boundary has advanced by this many epochs - lastDeletedBoundary phase0.Epoch // last boundary we successfully sent a DELETE for - deleteFiredOnce bool // becomes true after the first DELETE so the cadence check kicks in - routineSyncGroup sync.WaitGroup // to check if the routine is running + ctx context.Context + dbClient *db.DBService // client to communicate with psql + eventsObj events.Events // object to receive signals from beacon node (needed to trigger the deletes) + stop bool // used to know if the tool should stop + windowEpochSize int // number of epochs of data to maintain in the database + deleteCadenceEpochs int // only emit DELETE once the boundary has advanced by this many epochs + lastDeletedBoundary phase0.Epoch // last boundary we successfully sent a DELETE for + deleteFiredOnce bool // becomes true after the first DELETE so the cadence check kicks in + poolRerollEpochs int // refresh t_pool_summary for the last N epochs when the pool mapping changes (0 disables) + lastPoolsFingerprint string // last observed fingerprint of t_eth2_pubkeys + routineSyncGroup sync.WaitGroup // to check if the routine is running } func NewValidatorWindow( @@ -73,6 +77,7 @@ func NewValidatorWindow( eventsObj: events.NewEventsObj(pCtx, cli), windowEpochSize: iConfig.NumEpochs, deleteCadenceEpochs: cadence, + poolRerollEpochs: iConfig.PoolRerollEpochs, routineSyncGroup: sync.WaitGroup{}, }, nil } @@ -82,6 +87,7 @@ func (s *ValidatorWindowRunner) Run() { s.eventsObj.SubscribeToFinalizedCheckpointEvents() // every new finalized checkpoint, trigger deletes s.eventsObj.SubscribeToHeadEvents() // for monitorization ticker := time.NewTicker(utils.RoutineFlushTimeout) + defer ticker.Stop() // lives as long as the routine; stopped for a clean shutdown s.routineSyncGroup.Add(1) defer s.routineSyncGroup.Done() @@ -97,42 +103,12 @@ func (s *ValidatorWindowRunner) Run() { return } - if dbHeadEpoch < phase0.Epoch(s.windowEpochSize) { - log.Infof("database head epoch: %d is less than window epoch size: %d", dbHeadEpoch, s.windowEpochSize) - continue - } - windowLowerEpochBoundary := dbHeadEpoch - phase0.Epoch(s.windowEpochSize) - - // Each DELETE FROM t_validator_rewards_summary becomes a ClickHouse - // mutation that rewrites every part holding in-window epochs. On - // networks with ~1M validators that mutation takes minutes per fire; - // firing on every finalized checkpoint (~6:24 min) saturates the - // merge thread and stalls the head. Only emit the DELETE once the - // boundary has advanced by deleteCadenceEpochs since the last fire. - if s.deleteFiredOnce { - if windowLowerEpochBoundary <= s.lastDeletedBoundary { - log.Debugf("skipping delete: boundary %d not advanced past last fire %d", - windowLowerEpochBoundary, s.lastDeletedBoundary) - continue - } - advanced := windowLowerEpochBoundary - s.lastDeletedBoundary - if advanced < phase0.Epoch(s.deleteCadenceEpochs) { - log.Debugf("skipping delete: boundary advanced %d/%d epochs since last fire (boundary=%d)", - advanced, s.deleteCadenceEpochs, windowLowerEpochBoundary) - continue - } - } - - log.Infof("database head epoch: %d", dbHeadEpoch) - log.Infof("deleting validator rewards from %d epoch backwards", windowLowerEpochBoundary) - err = s.dbClient.DeleteValidatorRewardsUntil(windowLowerEpochBoundary) - if err != nil { - log.Errorf("could not delete the validators: %s", err) + if !s.runRetention(dbHeadEpoch) { s.EndProcesses() return } - s.lastDeletedBoundary = windowLowerEpochBoundary - s.deleteFiredOnce = true + + s.maybeRerollPoolSummaries(dbHeadEpoch) case <-ticker.C: if s.stop { return @@ -141,6 +117,142 @@ func (s *ValidatorWindowRunner) Run() { } } +// runRetention applies the sliding-window delete on the rewards table. +// Returns false on a fatal error that should stop the runner. +func (s *ValidatorWindowRunner) runRetention(dbHeadEpoch phase0.Epoch) bool { + + if dbHeadEpoch < phase0.Epoch(s.windowEpochSize) { + log.Infof("database head epoch: %d is less than window epoch size: %d", dbHeadEpoch, s.windowEpochSize) + return true + } + windowLowerEpochBoundary := dbHeadEpoch - phase0.Epoch(s.windowEpochSize) + + // Each DELETE FROM t_validator_rewards_summary becomes a ClickHouse + // mutation that rewrites every part holding in-window epochs. On + // networks with ~1M validators that mutation takes minutes per fire; + // firing on every finalized checkpoint (~6:24 min) saturates the + // merge thread and stalls the head. Only emit the DELETE once the + // boundary has advanced by deleteCadenceEpochs since the last fire. + if s.deleteFiredOnce { + if windowLowerEpochBoundary <= s.lastDeletedBoundary { + log.Debugf("skipping delete: boundary %d not advanced past last fire %d", + windowLowerEpochBoundary, s.lastDeletedBoundary) + return true + } + advanced := windowLowerEpochBoundary - s.lastDeletedBoundary + if advanced < phase0.Epoch(s.deleteCadenceEpochs) { + log.Debugf("skipping delete: boundary advanced %d/%d epochs since last fire (boundary=%d)", + advanced, s.deleteCadenceEpochs, windowLowerEpochBoundary) + return true + } + } + + log.Infof("database head epoch: %d", dbHeadEpoch) + log.Infof("deleting validator rewards from %d epoch backwards", windowLowerEpochBoundary) + err := s.dbClient.DeleteValidatorRewardsUntil(windowLowerEpochBoundary) + if err != nil { + log.Errorf("could not delete the validators: %s", err) + return false + } + s.lastDeletedBoundary = windowLowerEpochBoundary + s.deleteFiredOnce = true + return true +} + +// maybeRerollPoolSummaries refreshes t_pool_summary for the trailing +// poolRerollEpochs epochs whenever the validator->pool mapping changes, so +// late-tagged validators and pool renames propagate into recent history +// instead of freezing the tagging snapshot taken at ingestion time. +func (s *ValidatorWindowRunner) maybeRerollPoolSummaries(dbHeadEpoch phase0.Epoch) { + + if s.poolRerollEpochs <= 0 { + return + } + + fingerprint, err := s.dbClient.RetrievePoolsFingerprint() + if err != nil { + log.Errorf("could not retrieve pools fingerprint: %s", err) + return + } + if fingerprint == "" { + return + } + // Sync scripts commonly refresh t_eth2_pubkeys with TRUNCATE + INSERT, + // so a checkpoint landing mid-sync would observe an empty or partial + // mapping and reroll recent history with most validators as 'unknown'. + // Skip (without recording the fingerprint) until the mapping recovers. + newCount := fingerprintRowCount(fingerprint) + if newCount == 0 { + log.Warnf("pool mapping is empty, skipping pool summary reroll (pubkeys sync in progress?)") + return + } + if s.lastPoolsFingerprint != "" { + lastCount := fingerprintRowCount(s.lastPoolsFingerprint) + if lastCount > 0 && newCount < lastCount/2 { + log.Warnf("pool mapping shrank from %d to %d entries, skipping pool summary reroll until it recovers (pubkeys sync in progress?)", + lastCount, newCount) + return + } + } + if s.lastPoolsFingerprint == "" { + // first observation after startup: record without refreshing so a + // restart alone does not trigger a reroll + s.lastPoolsFingerprint = fingerprint + return + } + if fingerprint == s.lastPoolsFingerprint { + return + } + + // leave a margin below the database head: the analyzer may still be + // writing the most recent epochs + const headMarginEpochs = 3 + if dbHeadEpoch <= headMarginEpochs { + return + } + toEpoch := dbHeadEpoch - headMarginEpochs + + fromEpoch := phase0.Epoch(0) + if toEpoch > phase0.Epoch(s.poolRerollEpochs) { + fromEpoch = toEpoch - phase0.Epoch(s.poolRerollEpochs) + 1 + } + // never refresh below the rewards retention window: those epochs have no + // source rows anymore, so delete+reinsert there would wipe their summaries + if dbHeadEpoch > phase0.Epoch(s.windowEpochSize) { + rewardsFloor := dbHeadEpoch - phase0.Epoch(s.windowEpochSize) + 1 + if fromEpoch < rewardsFloor { + fromEpoch = rewardsFloor + } + } + if toEpoch < fromEpoch { + return + } + + log.Infof("pool mapping changed, refreshing pool summaries for epochs %d-%d", fromEpoch, toEpoch) + err = s.dbClient.RefreshPoolSummaryRange(fromEpoch, toEpoch) + if err != nil { + // keep the old fingerprint so the refresh is retried on the next + // finalized checkpoint + log.Errorf("could not refresh pool summaries: %s", err) + return + } + s.lastPoolsFingerprint = fingerprint +} + +// fingerprintRowCount extracts the row count from a pools fingerprint, +// which is formatted as "-". +func fingerprintRowCount(fingerprint string) uint64 { + parts := strings.SplitN(fingerprint, "-", 2) + if len(parts) < 1 { + return 0 + } + count, err := strconv.ParseUint(parts[0], 10, 64) + if err != nil { + return 0 + } + return count +} + func (s *ValidatorWindowRunner) Close() { s.stop = true s.routineSyncGroup.Wait()