Subsystem (av-store) stalled while major syncing

[mchaffee]

Posting this log as an FYI...

We had a node crash with the following error. The server came back up via systemd, and there have been no issues since.

Jan 31 13:27:42 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:42 ✨ Imported #16434322 (0x38c9…8e04)
Jan 31 13:27:44 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:44 💤 Idle (40 peers), best: #16434322 (0x38c9…8e04), finalized #16434319 (0xef3e…f2b0),>
Jan 31 13:27:48 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:48 ✨ Imported #16434323 (0x128b…93d7)
Jan 31 13:27:49 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:49 💤 Idle (40 peers), best: #16434323 (0x128b…93d7), finalized #16434320 (0x3cc2…dbb9),>
Jan 31 13:27:54 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:54 💤 Idle (40 peers), best: #16434323 (0x128b…93d7), finalized #16434321 (0x5e4b…323d),>
Jan 31 13:27:55 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:55 ✨ Imported #16434324 (0xba48…bbca)
Jan 31 13:27:55 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:55 Advanced session window for approvals update=Advanced { prev_window_start: 27835, pre>
Jan 31 13:27:59 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:27:59 💤 Idle (40 peers), best: #16434324 (0xba48…bbca), finalized #16434322 (0x38c9…8e04),>
Jan 31 13:28:00 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:00 ✨ Imported #16434325 (0xe07b…b367)
Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 💤 Idle (40 peers), best: #16434325 (0xe07b…b367), finalized #16434322 (0x38c9…8e04),>
Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 ♻️  Reorg on #16434325,0xe07b…b367 to #16434324,0x6e4d…69ec, common ancestor #16434323>
Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 ✨ Imported #16434324 (0x6e4d…69ec)
Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 GRANDPA voter error: safety invariant has been violated: SelectChain returned a final>
Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 Essential task `grandpa-voter` failed. Shutting down service.
Jan 31 13:28:05 GS-Prod-VA2-VM19 polkadot[646170]: Error:
Jan 31 13:28:05 GS-Prod-VA2-VM19 polkadot[646170]:    0: Other: Essential task failed.
Jan 31 13:28:05 GS-Prod-VA2-VM19 polkadot[646170]: Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Jan 31 13:28:05 GS-Prod-VA2-VM19 polkadot[646170]: Run with RUST_BACKTRACE=full to include source snippets.
Jan 31 13:28:05 GS-Prod-VA2-VM19 systemd[1]: polkadot.service: Main process exited, code=exited, status=1/FAILURE
Jan 31 13:28:05 GS-Prod-VA2-VM19 systemd[1]: polkadot.service: Failed with result 'exit-code'.
Jan 31 13:28:05 GS-Prod-VA2-VM19 systemd[1]: polkadot.service: Consumed 2w 2d 22h 47min 18.325s CPU time.
Jan 31 13:29:05 GS-Prod-VA2-VM19 systemd[1]: polkadot.service: Scheduled restart job, restart counter is at 1.
Jan 31 13:29:05 GS-Prod-VA2-VM19 systemd[1]: Stopped Kusama Node.
Jan 31 13:29:05 GS-Prod-VA2-VM19 systemd[1]: polkadot.service: Consumed 2w 2d 22h 47min 18.325s CPU time.
Jan 31 13:29:05 GS-Prod-VA2-VM19 systemd[1]: Started Kusama Node.
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 ----------------------------
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 This chain is not in any way
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05       endorsed by the
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05      KUSAMA FOUNDATION
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 ----------------------------
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 Parity Polkadot
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 ✌️  version 0.9.37-645723987cf
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 ❤️  by Parity Technologies <admin@parity.io>, 2017-2023
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 📋 Chain specification: Kusama
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 🏷  Node name: 🍀LuckyFriday-KSM-09🍀
Jan 31 13:29:05 GS-Prod-VA2-VM19 polkadot[706190]: 2023-01-31 13:29:05 👤 Role: AUTHORITY

[dolphintwo]

2023-02-01 09:12:54 ⚙️  Syncing 20.6 bps, target=#16442460 (100 peers), best: #10908405 (0x663e…8c6d), finalized #10908160 (0x63cc…9b87), ⬇ 1.1MiB/s ⬆ 2.5MiB/s
2023-02-01 09:12:59 ⚙️  Syncing 22.4 bps, target=#16442460 (100 peers), best: #10908517 (0x1444…ccd6), finalized #10908160 (0x63cc…9b87), ⬇ 948.2kiB/s ⬆ 3.8MiB/s
2023-02-01 09:13:04 ⚙️  Syncing 21.9 bps, target=#16442460 (100 peers), best: #10908627 (0x8ac6…84ac), finalized #10908160 (0x63cc…9b87), ⬇ 1.0MiB/s ⬆ 1.6MiB/s
2023-02-01 09:13:09 ⚙️  Syncing 16.4 bps, target=#16442460 (100 peers), best: #10908709 (0x9a8a…9796), finalized #10908672 (0xaa84…5473), ⬇ 1.2MiB/s ⬆ 639.5kiB/s
2023-02-01 09:13:14 ⚙️  Syncing 23.6 bps, target=#16442460 (100 peers), best: #10908827 (0x6319…a354), finalized #10908672 (0xaa84…5473), ⬇ 865.0kiB/s ⬆ 713.3kiB/s
2023-02-01 09:13:15 Overseer exited with error err=Generated(SubsystemStalled("availability-store-subsystem"))
2023-02-01 09:13:15 Essential task `overseer` failed. Shutting down service.
2023-02-01 09:13:15 subsystem exited with error subsystem="statement-distribution-subsystem" err=FromOrigin { origin: "statement-distribution", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
2023-02-01 09:13:15 subsystem exited with error subsystem="chain-api-subsystem" err=FromOrigin { origin: "chain-api", source: Generated(Context("Signal channel is terminated and empty.")) }
2023-02-01 09:13:15 err=Subsystem(Generated(Context("Signal channel is terminated and empty.")))
2023-02-01 09:13:15 subsystem exited with error subsystem="candidate-validation-subsystem" err=FromOrigin { origin: "candidate-validation", source: Generated(Context("Signal channel is terminated and empty.")) }
2023-02-01 09:13:15 subsystem exited with error subsystem="pvf-checker-subsystem" err=FromOrigin { origin: "pvf-checker", source: Generated(Context("Signal channel is terminated and empty.")) }
2023-02-01 09:13:15 subsystem exited with error subsystem="availability-distribution-subsystem" err=FromOrigin { origin: "availability-distribution", source: IncomingMessageChannel(Generated(Context("Signal channel is terminated and empty."))) }
2023-02-01 09:13:15 Unable to author block in slot. No best block header: Request for leaves from chain selection got canceled
2023-02-01 09:13:15 subsystem exited with error subsystem="approval-voting-subsystem" err=FromOrigin { origin: "approval-voting", source: Generated(Context("Signal channel is terminated and empty.")) }
2023-02-01 09:13:15 subsystem exited with error subsystem="dispute-coordinator-subsystem" err=FromOrigin { origin: "dispute-coordinator", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
2023-02-01 09:13:15 subsystem exited with error subsystem="bitfield-signing-subsystem" err=FromOrigin { origin: "bitfield-signing", source: Generated(Context("Signal channel is terminated and empty.")) }
2023-02-01 09:13:15 subsystem exited with error subsystem="runtime-api-subsystem" err=Generated(Context("Signal channel is terminated and empty."))
2023-02-01 09:14:15 Detected running(potentially stalled) tasks on shutdown:
2023-02-01 09:14:15 Task "candidate-backing-subsystem" (Group: candidate-backing) was still running after waiting 60 seconds to finish.
2023-02-01 09:14:15 Task "availability-store-subsystem" (Group: availability-store) was still running after waiting 60 seconds to finish.
Error:
   0: Other: Essential task failed.
Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
kusama.service: Main process exited, code=exited, status=1/FAILURE
kusama.service: Failed with result 'exit-code'.
kusama.service: Scheduled restart job, restart counter is at 13.
Stopped Kusama Node Daemon.
Started Kusama Node Daemon.
2023-02-01 09:14:20 ----------------------------
2023-02-01 09:14:20 This chain is not in any way
2023-02-01 09:14:20       endorsed by the
2023-02-01 09:14:20      KUSAMA FOUNDATION
2023-02-01 09:14:20 ----------------------------
2023-02-01 09:14:20 Parity Polkadot
2023-02-01 09:14:20 ✌️  version 0.9.37-645723987cf
2023-02-01 09:14:20 ❤️  by Parity Technologies <admin@parity.io>, 2017-2023
2023-02-01 09:14:20 📋 Chain specification: Kusama

[bkchr]

Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 GRANDPA voter error: safety invariant has been violated: SelectChain returned a final>
Jan 31 13:28:04 GS-Prod-VA2-VM19 polkadot[646170]: 2023-01-31 13:28:04 Essential task grandpa-voter failed. Shutting down service.

This is a duplicate of: paritytech/substrate#13254

[bkchr]

2023-02-01 09:14:15 Detected running(potentially stalled) tasks on shutdown:
2023-02-01 09:14:15 Task "candidate-backing-subsystem" (Group: candidate-backing) was still running after waiting 60 seconds to finish.
2023-02-01 09:14:15 Task "availability-store-subsystem" (Group: availability-store) was still running after waiting 60 seconds to finish.

This is "interesting", ty for the report.

[sandreim]

Thanks, this is indeed interesting, looks like av store gets stuck for some reason: 2023-02-01 09:13:15 Overseer exited with error err=Generated(SubsystemStalled("availability-store-subsystem"))

One possible cause could be the pruning that is one big storage prefix iteration: https://github.com/paritytech/polkadot/blob/master/node/core/av-store/src/lib.rs#L1219.

@dolphintwo can you share a heatmap view for these histogram metrics: polkadot_parachain_av_store_pruning and polkadot_parachain_av_store_process_block_finalized ?

[sandreim]

FWIW I also seen this recently on some Versi tests.

[dolphintwo]

@sandreim Is this heatmap okey? my node is still keep restarting

[sandreim]

Not really, I am using this query for my testnet (you would need to change the labels to match on your nodes and polkadot chain): sum(increase(polkadot_parachain_av_store_pruning_bucket{chain="$chain", pod=~".*validator.*"}[$__rate_interval])) by (le) to get this heatmap:

Would be good to see the values before the issue started as well.

[ordian]

2023-02-01 09:12:54 ⚙️  Syncing 20.6 bps, target=#16442460 (100 peers), best: #10908405 (0x663e…8c6d), finalized #10908160 (0x63cc…9b87), ⬇ 1.1MiB/s ⬆ 2.5MiB/s
2023-02-01 09:12:59 ⚙️  Syncing 22.4 bps, target=#16442460 (100 peers), best: #10908517 (0x1444…ccd6), finalized #10908160 (0x63cc…9b87), ⬇ 948.2kiB/s ⬆ 3.8MiB/s
2023-02-01 09:13:04 ⚙️  Syncing 21.9 bps, target=#16442460 (100 peers), best: #10908627 (0x8ac6…84ac), finalized #10908160 (0x63cc…9b87), ⬇ 1.0MiB/s ⬆ 1.6MiB/s
2023-02-01 09:13:09 ⚙️  Syncing 16.4 bps, target=#16442460 (100 peers), best: #10908709 (0x9a8a…9796), finalized #10908672 (0xaa84…5473), ⬇ 1.2MiB/s ⬆ 639.5kiB/s
2023-02-01 09:13:14 ⚙️  Syncing 23.6 bps, target=#16442460 (100 peers), best: #10908827 (0x6319…a354), finalized #10908672 (0xaa84…5473), ⬇ 865.0kiB/s ⬆ 713.3kiB/s
2023-02-01 09:13:15 Overseer exited with error err=Generated(SubsystemStalled("availability-store-subsystem"))

The node here is clearly in major sync. In theory it shouldn't receive block import and finality notifications, but looks like it did.

The slowness is either in processing new leaf (and going many blocks to the latest known finalized head) or pruning on finality. For pruning, we could limit the amount of pruned keys, similar to

polkadot/node/core/dispute-coordinator/src/db/v1.rs

Line 74 in 81d2650

fn add_vote_cleanup_tx(

[bkchr]

The node here is clearly in major sync. In theory it shouldn't receive block import and finality notifications, but looks like it did.

Block import notifications are not being sent when doing a major sync. However, finality notification send per justification we import, aka once per era.

[dolphintwo]

Interesting, when I remove "--validator" and start again, I don't seem to encounter this problem again.

[ordian]

@dolphintwo could you reproduce the problem with 0.9.36? I suspect that #6452 that got into 0.9.37 release fixed one problem and created another one. #6691 might revert the side-effects of that PR.