Reading Sync test logs — the tip-tracking report, line by line

The Sync test category (tip-tracking + sync-from-scratch) all drives one Python state machine, so every Sync workflow shares the report format, thresholds and metric block described here.

Driver: erigon-qa/test_system/qa-tests/tip-tracking/run_and_check_tip_tracking.py. Shared by qa-tip-tracking*, qa-constrained-tip-tracking, qa-sync-from-scratch*, qa-sync-with-externalcl, qa-sync-test-bisection-tool and the pre-test stabilisation steps. The report block opens with *** Tip tracking completed on every Sync workflow, sync-from-scratch included.

Test phases

The driver is a state machine; the log announces every transition.

Two timers bound the run:

• TRACKING_TIME_SECONDS — how long the node must hold the tip once reached (typically 7200 = 2 h). Expiry → normal completion + analysis.
• TOTAL_TIME_SECONDS — hard deadline for the whole run. Expiry while still LOOKING_FOR_CHAIN_TIP → abort (Deadline reached). Expiry while already TRACKING_CHAIN_TIP → the run completes normally with a shorter window.

*** In sync / *** Out of sync bracket each in-sync interval; the count of these pairs tells you whether the node lost the tip once or flapped constantly.

What "in sync" means

SyncSentinel polls http://localhost:8545 every block_time seconds using EnhancedBlockTimestampPolicy: in sync ⇔ now - latest_block.timestamp <= 2 × block_time.

The policy also cross-checks eth_syncing. A mismatch logs Node in false sync condition / Node in false out-of-sync condition — a warning, not a failure, but worth reporting: it can indicate a bug in eth_syncing itself.

The report block

*** Tip tracking completed opens it. Then, in order:

subdir-size-increments_mb (per datadir sub-directory) is in the JSON only — it is what localises a size regression to chaindata, snapshots, etc.

The metric block

Scraped from Erigon's Prometheus endpoint (:6061/debug/metrics/prometheus) every block_time seconds while tracking. Not thresholded (except exec_steps_in_db) but decisive when explaining a sync-time failure.

Percentage of time 'block_consumer_delay_hist_bucket-post_execution' was under threshold 4s: 95.14%
Percentage of time 'block_consumer_delay_hist_bucket-pre_execution'  was under threshold 4s: 95.14%
Initial/Final/Rate of metric 'chain_tip_mgas_per_sec': ...
Metric 'exec_mgas_sec': min 6.96, max 77.16, mean 45.84
Metric 'exec_txns':     min 262.9, max 1230.7, mean 583.8
Initial/Final/Rate of metric 'exec_blocks': ...

• block_consumer_delay_hist_bucket — how long a block waits before/after execution. Thresholds are chain-dependent: [4] s for the 12 s chains, [1, 2] for gnosis/chiado, [0.5, 1, 2] for bor-mainnet/amoy. A drop here is the usual cause of a sync-time failure. A companion ...-threshold-Ns-warning measure is set when a sampling window missed the bucket exactly at the threshold — treat those percentages as approximate.
• exec_mgas_sec / exec_txns — raw execution throughput (gauge: min/max/mean).
• exec_blocks — counter; its rate is blocks/s from the metrics side, a cross-check on *** Blocks per second.
• chain_tip_mgas_per_sec — nan is normal when the node was never processing at the tip.

Plots of all of these ship in the metric-plots* artifact (metrics-<chain>-plots_<metric>_*.png) — usually faster to read than the numbers.

Failure messages, verbatim

*** Test failed: total sync time below threshold (75%), final value: <P>%
      → outcome FAILURE, reason "in sync less than 75% of the time"

*** Test failed: exec_steps_in_db exceeded threshold (300), final value: <V>
      → outcome FAILURE, reason "exec_steps_in_db exceeded threshold of 300"

*** Aborting test: Deadline reached
      → outcome "Unexpected error", reason "Deadline reached"

*** Aborting test: Erigon process terminated unexpectedly: <reason>
*** Aborting test: Erigon in ERROR: Errored line: <the [EROR] line>
*** Aborting test: Erigon aborted: Segmentation fault: <line>
*** Aborting test: SyncSentinel error: <description>
*** Aborting test: LoadTool error: <description>
*** Aborting test: Consensus client startup failure: <description>
      → outcome "Unexpected error", reason as shown

Only the first two threshold breaches are reported: sync-time is checked first, so an exec_steps_in_db breach in the same run is recorded as a measure but not as the failure reason.

Errors logged by Erigon after the test has ended (STOPPING / STOPPED / ENDED) are deliberately ignored — Ignoring error: ... in the log. Don't report those as the cause.

On abort the driver calls dump_coroutine_stacks() → SIGUSR1 to Erigon, so the goroutine dump lands at the tail of the log.

Node types

The workflow's last positional arg selects the prune mode, which changes what is normal for datadir growth and download time: