Description
When snap sync stops making progress there is nothing at Info level, and nothing
in the default metric set, that says so. A node whose every snap request fails
is indistinguishable from one that is working slowly.
Three separate paths lose the signal:
- A timeout produces no response object at all.
SnapSyncFeed.HandleResponse
falls into its final else, logs _logger.Trace($"SNAP - timeout {peer}") and
returns LesserQuality. It never reaches SnapProvider, so it never touches
Metrics.SnapRangeResult either. Trace is off in production, so a node in this
state produces no output at all.
- A response carrying an unusable range does reach
Metrics.SnapRangeResult,
but that metric is [DetailedMetric] and therefore off unless detailed metrics
are enabled.
- Meanwhile
ProgressTracker keeps printing Snap State Ranges (Phase 1): ( 0.00 %)
on its normal cadence, which reads as "working".
The two internal mechanisms that do act on failure are also silent above Debug:
_logger.Trace($"SNAP - peer to be punished:{peer}") and the pivot-update path's
_logger.Debug(...).
Actual behavior
Measured on an OP mainnet node (2.0.0-rc, OP L2, op-node v1.19.0):
|
|
time in StateNodes |
83,011 s (23 h) |
nethermind_snap_synced_accounts |
0 |
nethermind_snap_state_synced |
0 |
nethermind_state_synced |
0 |
| snap peers |
24 (all Reth), at the chain head |
| pivot distance from head |
44 blocks |
| account-range partitions with more accounts to the right |
8 |
| account requests in flight |
1, continuously |
| log lines explaining any of this |
0 |
The peer set is not stale and the pivot is not stale, so neither of the existing
"blame the peer" and "move the pivot" heuristics applies — and neither says
anything an operator can see. The only visible output for those 23 hours was the
unchanging 0.00 % progress line.
Expected behavior
A sustained run of snap requests that produce no usable range should be reported
at Warn, once a stall is actually established rather than on each failure, saying
how many requests it covers, how long it has run, and why the most recent one was
unusable. Timeouts should also be countable in the default metric set, since
"nobody is answering" and "someone is answering with bad data" call for different
operator actions and are currently indistinguishable.
Additional context
Not a 2.0.0-rc regression: the Trace-only timeout line and the
[DetailedMetric] attribute on SnapRangeResult are both present on master
(a238575539).
Related: #13155 (unbounded requeue of an empty storage range) and #13200 (forced
pivot chasing the head) were both found by reading logs that did exist. This is
the case where they do not.
Desktop
- Operating System: Linux x64
- Version: 2.0.0-rc; present on master
a238575539
- Installation Method: Docker
Description
When snap sync stops making progress there is nothing at Info level, and nothing
in the default metric set, that says so. A node whose every snap request fails
is indistinguishable from one that is working slowly.
Three separate paths lose the signal:
SnapSyncFeed.HandleResponsefalls into its final
else, logs_logger.Trace($"SNAP - timeout {peer}")andreturns
LesserQuality. It never reachesSnapProvider, so it never touchesMetrics.SnapRangeResulteither. Trace is off in production, so a node in thisstate produces no output at all.
Metrics.SnapRangeResult,but that metric is
[DetailedMetric]and therefore off unless detailed metricsare enabled.
ProgressTrackerkeeps printingSnap State Ranges (Phase 1): ( 0.00 %)on its normal cadence, which reads as "working".
The two internal mechanisms that do act on failure are also silent above Debug:
_logger.Trace($"SNAP - peer to be punished:{peer}")and the pivot-update path's_logger.Debug(...).Actual behavior
Measured on an OP mainnet node (
2.0.0-rc, OP L2, op-node v1.19.0):StateNodesnethermind_snap_synced_accountsnethermind_snap_state_syncednethermind_state_syncedThe peer set is not stale and the pivot is not stale, so neither of the existing
"blame the peer" and "move the pivot" heuristics applies — and neither says
anything an operator can see. The only visible output for those 23 hours was the
unchanging
0.00 %progress line.Expected behavior
A sustained run of snap requests that produce no usable range should be reported
at Warn, once a stall is actually established rather than on each failure, saying
how many requests it covers, how long it has run, and why the most recent one was
unusable. Timeouts should also be countable in the default metric set, since
"nobody is answering" and "someone is answering with bad data" call for different
operator actions and are currently indistinguishable.
Additional context
Not a
2.0.0-rcregression: the Trace-only timeout line and the[DetailedMetric]attribute onSnapRangeResultare both present onmaster(
a238575539).Related: #13155 (unbounded requeue of an empty storage range) and #13200 (forced
pivot chasing the head) were both found by reading logs that did exist. This is
the case where they do not.
Desktop
a238575539