Disputes Causing Unresponsivenss

[wpank]

Many had logs similar to this with some parachain subsystems failing, but the node doesn't crash.

[dbpatty]

when I restarted my node first time I had this log (it wasn't responde):
Dec 09 00:38:54 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.997 ERROR tokio-runtime-worker sc_service::task_manager: Essential task overseer failed. Shutting down service.
Dec 09 00:38:54 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.997 WARN tokio-runtime-worker slots: Unable to author block in slot. No best block header: Request for leaves from chain selection got canceled
Dec 09 00:38:54 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.997 INFO tokio-runtime-worker parachain::dispute-coordinator: New dispute initiated for candidate. candidate_hash=0xe1e677e00a3a3411c4bad16559c4753c47cd51043159b1f4399caea155bfb91b session=26550 traceID=300272958686085533188489404059870328124
Dec 09 00:38:54 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.997 INFO tokio-runtime-worker parachain::dispute-coordinator: Dispute on candidate concluded with 'valid' result candidate_hash=0xe1e677e00a3a3411c4bad16559c4753c47cd51043159b1f4399caea155bfb91b session=26550 traceID=300272958686085533188489404059870328124
Dec 09 00:38:54 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.998 ERROR tokio-runtime-worker polkadot_overseer: subsystem exited with error subsystem="statement-distribution-subsystem" err=FromOrigin { origin: "statement-distribution", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
Dec 09 00:38:55 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.999 WARN tokio-runtime-worker parachain::dispute-coordinator: Fetch for approval votes got cancelled, only expected during shutdown!
Dec 09 00:38:55 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.999 INFO tokio-runtime-worker parachain::dispute-coordinator: New dispute initiated for candidate. candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
Dec 09 00:38:55 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:54.999 INFO tokio-runtime-worker parachain::dispute-coordinator: Dispute on candidate concluded with 'valid' result candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
Dec 09 00:38:55 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:55.014 ERROR tokio-runtime-worker polkadot_overseer: subsystem exited with error subsystem="runtime-api-subsystem" err=Generated(Context("Signal channel is terminated and empty."))
Dec 09 00:38:55 Ubuntu-2004-focal-64-minimal polkadot[4186922]: 2022-12-09 00:38:55.031 ERROR tokio-runtime-worker polkadot_overseer: subsystem exited with error subsystem="dispute-coordinator-subsystem" err=FromOrigin { origin: "dispute-coordinator", source: ChainApiSenderDropped }

[tugytur]

logs from our validators

First I had thousands of these

2022-12-09 00:34:18 error=AuthorityFlooding(Public(82d52cc7b29907658987ceb5ca8774cadac4f2f2dff14b5fd7257929ea8f9931

and shortly after:

2022-12-09 00:39:33 💤 Idle (40 peers), best: #15675155 (0x6365…21c0), finalized #15675123 (0x1032…cc38), ⬇ 3.2MiB/s ⬆ 947.1kiB/s
2022-12-09 00:39:36 ✨ Imported #15675156 (0x2050…cc1b)
2022-12-09 00:39:38 💤 Idle (40 peers), best: #15675156 (0x2050…cc1b), finalized #15675123 (0x1032…cc38), ⬇ 596.6kiB/s ⬆ 335.7kiB/s
2022-12-09 00:39:39 ♻️  Reorg on #15675156,0x2050…cc1b to #15675151,0xdbda…58bf, common ancestor #15675150,0x85f8…bcf9
2022-12-09 00:39:39 ✨ Imported #15675151 (0xdbda…58bf)
2022-12-09 00:39:42 Subsystem dispute-coordinator-subsystem appears unresponsive. origin=polkadot_service::relay_chain_selection::SelectRelayChainInner<sc_client_db::Backend<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32, sp_runtime::traits::BlakeTwo256>, sp_runtime::OpaqueExtrinsic>>, polkadot_overseer::Handle>
2022-12-09 00:39:42 Call to `DetermineUndisputedChain` failed error=DetermineUndisputedChainCanceled(Canceled)
2022-12-09 00:39:42 err=ContextChannelClosed
2022-12-09 00:39:42 subsystem exited with error subsystem="pvf-checker-subsystem" err=FromOrigin { origin: "pvf-checker", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-09 00:39:42 subsystem exited with error subsystem="candidate-validation-subsystem" err=FromOrigin { origin: "candidate-validation", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-09 00:39:42 subsystem exited with error subsystem="bitfield-signing-subsystem" err=FromOrigin { origin: "bitfield-signing", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-09 00:39:42 err=Subsystem(Generated(Context("Signal channel is terminated and empty.")))
2022-12-09 00:39:42 subsystem exited with error subsystem="chain-api-subsystem" err=FromOrigin { origin: "chain-api", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-09 00:39:42 subsystem exited with error subsystem="availability-distribution-subsystem" err=FromOrigin { origin: "availability-distribution", source: IncomingMessageChannel(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-09 00:39:42 subsystem exited with error subsystem="availability-recovery-subsystem" err=FromOrigin { origin: "availability-recovery", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-09 00:39:42 Failed to receive a message from Overseer, exiting err=Generated(Context("Signal channel is terminated and empty."))
2022-12-09 00:39:42 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-09 00:39:42 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-09 00:39:42 error receiving message from subsystem context: Generated(Context("Signal channel is terminated and empty.")) err=Generated(Context("Signal channel is terminated and empty."))
2022-12-09 00:39:42 Fetch for approval votes got cancelled, only expected during shutdown!
2022-12-09 00:39:42 subsystem exited with error subsystem="approval-voting-subsystem" err=FromOrigin { origin: "approval-voting", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-09 00:39:42 Essential task `overseer` failed. Shutting down service.
2022-12-09 00:39:42 Unable to author block in slot. No best block header: Request for leaves from chain selection got canceled
2022-12-09 00:39:42 New dispute initiated for candidate. candidate_hash=0x76f50ee7b0b011c8476ff06137758119f14621ed56fc8eddeddcab972075d418 session=26550 traceID=158121318543083314337622651639539532057
2022-12-09 00:39:42 Dispute on candidate concluded with 'valid' result candidate_hash=0x76f50ee7b0b011c8476ff06137758119f14621ed56fc8eddeddcab972075d418 session=26550 traceID=158121318543083314337622651639539532057
2022-12-09 00:39:42 Fetch for approval votes got cancelled, only expected during shutdown!
2022-12-09 00:39:42 New dispute initiated for candidate. candidate_hash=0xb135a789e5406bed8b799a8edc1f7ded19c6d443c35c0cab94190cb4802e1e6c session=26550 traceID=235551945075044477828146618989736328685
2022-12-09 00:39:42 Dispute on candidate concluded with 'valid' result candidate_hash=0xb135a789e5406bed8b799a8edc1f7ded19c6d443c35c0cab94190cb4802e1e6c session=26550 traceID=235551945075044477828146618989736328685
2022-12-09 00:39:42 Fetch for approval votes got cancelled, only expected during shutdown!
2022-12-09 00:39:42 New dispute initiated for candidate. candidate_hash=0xe1e677e00a3a3411c4bad16559c4753c47cd51043159b1f4399caea155bfb91b session=26550 traceID=300272958686085533188489404059870328124
2022-12-09 00:39:42 Dispute on candidate concluded with 'valid' result candidate_hash=0xe1e677e00a3a3411c4bad16559c4753c47cd51043159b1f4399caea155bfb91b session=26550 traceID=300272958686085533188489404059870328124
2022-12-09 00:39:42 Fetch for approval votes got cancelled, only expected during shutdown!
2022-12-09 00:39:42 New dispute initiated for candidate. candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
2022-12-09 00:39:42 Dispute on candidate concluded with 'valid' result candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
2022-12-09 00:39:42 subsystem exited with error subsystem="statement-distribution-subsystem" err=FromOrigin { origin: "statement-distribution", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-09 00:39:42 subsystem exited with error subsystem="runtime-api-subsystem" err=Generated(Context("Signal channel is terminated and empty."))
2022-12-09 00:39:42 subsystem exited with error subsystem="dispute-coordinator-subsystem" err=FromOrigin { origin: "dispute-coordinator", source: ChainApiSenderDropped }
2022-12-09 00:39:42 GRANDPA voter error: safety invariant has been violated: `voter_commands_rx` was closed.
2022-12-09 00:39:42 Essential task `grandpa-voter` failed. Shutting down service

another validator:

2022-12-08 23:40:23 💤 Idle (40 peers), best: #15675153 (0x594b…c937), finalized #15675123 (0x1032…cc38), ⬇ 358.1kiB/s ⬆ 280.6kiB/s
2022-12-08 23:40:24 Subsystem dispute-coordinator-subsystem appears unresponsive. origin=polkadot_service::relay_chain_selection::SelectRelayChainInner<sc_client_db::Backend<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32, sp_runtime::traits::BlakeTwo256>, sp_runtime::OpaqueExtrinsic>>, polkadot_overseer::Handle>
2022-12-08 23:40:24 Call to `DetermineUndisputedChain` failed error=DetermineUndisputedChainCanceled(Canceled)
2022-12-08 23:40:24 err=ContextChannelClosed
2022-12-08 23:40:24 Unable to author block in slot. No best block header: Request for leaves from chain selection got canceled
2022-12-08 23:40:24 err=Subsystem(Generated(Context("Signal channel is terminated and empty.")))
2022-12-08 23:40:24 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-08 23:40:24 subsystem exited with error subsystem="pvf-checker-subsystem" err=FromOrigin { origin: "pvf-checker", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-08 23:40:24 subsystem exited with error subsystem="availability-recovery-subsystem" err=FromOrigin { origin: "availability-recovery", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-08 23:40:24 subsystem exited with error subsystem="availability-distribution-subsystem" err=FromOrigin { origin: "availability-distribution", source: IncomingMessageChannel(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-08 23:40:24 subsystem exited with error subsystem="approval-voting-subsystem" err=FromOrigin { origin: "approval-voting", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-08 23:40:24 subsystem exited with error subsystem="chain-api-subsystem" err=FromOrigin { origin: "chain-api", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-08 23:40:24 Fetch for approval votes got cancelled, only expected during shutdown!
2022-12-08 23:40:24 subsystem exited with error subsystem="statement-distribution-subsystem" err=FromOrigin { origin: "statement-distribution", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-08 23:40:24 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
2022-12-08 23:40:24 subsystem exited with error subsystem="bitfield-signing-subsystem" err=FromOrigin { origin: "bitfield-signing", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-08 23:40:24 Essential task `overseer` failed. Shutting down service.
2022-12-08 23:40:24 subsystem exited with error subsystem="candidate-validation-subsystem" err=FromOrigin { origin: "candidate-validation", source: Generated(Context("Signal channel is terminated and empty.")) }
2022-12-08 23:40:24 error receiving message from subsystem context: Generated(Context("Signal channel is terminated and empty.")) err=Generated(Context("Signal channel is terminated and empty."))
2022-12-08 23:40:24 Failed to receive a message from Overseer, exiting err=Generated(Context("Signal channel is terminated and empty."))
2022-12-08 23:40:24 subsystem exited with error subsystem="runtime-api-subsystem" err=Generated(Context("Signal channel is terminated and empty."))
2022-12-08 23:40:24 New dispute initiated for candidate. candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
2022-12-08 23:40:24 Dispute on candidate concluded with 'valid' result candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
2022-12-08 23:40:24 subsystem exited with error subsystem="dispute-coordinator-subsystem" err=FromOrigin { origin: "dispute-coordinator", source: ChainApiSenderDropped }

I only posted these two because the rest seem to be identical

[rphmeier]

Thanks for the logs, folks.

The working hypothesis is that the dispute-coordinator got overloaded, and is becoming unresponsive. We have a few corroborations of this theory, now, from a few different places. If anyone has more logs which contain the phrase "appears unresponsive", please post them here. And if by any chance there are folks running with parachain=debug, it would be fantastic to have a few logs showing the dispute coordinator's actions leading up to the stall.

It is interesting to note in both @tugytur's examples, that the dispute coordinator was considered unresponsive and then afterwards issued a log "Fetch for approval votes cancelled" followed by "New dispute initiated for candidate". This might indicate the code branch where the dispute coordinator is stalling.

[CertHum-Jim]

Node never crashed, tons of disputes and what's above as others.

Dec 09 00:00:10 auto polkadot[54988]: 2022-12-09 00:00:10 New dispute initiated for candidate. candidate_hash=0xe8aba53daecc372155274bffe2fe9dee09a2872924e2a38faa25d6acb6556a8f session=26550 traceID=309272129269509726855056992512346332654
Dec 09 00:00:10 auto polkadot[54988]: 2022-12-09 00:00:10 Dispute on candidate concluded with 'valid' result candidate_hash=0xe8aba53daecc372155274bffe2fe9dee09a2872924e2a38faa25d6acb6556a8f session=26550 traceID=309272129269509726855056992512346332654
Dec 09 00:00:11 auto polkadot[54988]: 2022-12-09 00:00:11 💤 Idle (200 peers), best: #15675243 (0x2639…8290), finalized #15675181 (0xebdb…b046), ⬇ 600.7kiB/s ⬆ 819.9kiB/s
Dec 09 00:00:12 auto polkadot[54988]: 2022-12-09 00:00:12 ✨ Imported #15675244 (0x5542…83aa)
Dec 09 00:00:16 auto polkadot[54988]: 2022-12-09 00:00:16 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 1.6MiB/s ⬆ 1.1MiB/s
Dec 09 00:00:21 auto polkadot[54988]: 2022-12-09 00:00:21 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 1009.4kiB/s ⬆ 734.4kiB/s
Dec 09 00:00:22 auto polkadot[54988]: 2022-12-09 00:00:22 Creating inherent data providers took more time than we had left for the slot.
Dec 09 00:00:26 auto polkadot[54988]: 2022-12-09 00:00:26 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 635.9kiB/s ⬆ 242.5kiB/s
Dec 09 00:00:30 auto polkadot[54988]: 2022-12-09 00:00:30 New dispute initiated for candidate. candidate_hash=0xeb0649c6b038d048e84c0e6ae1a8f75234139793deb28c87b0d9918a8c75ae78 session=26550 traceID=312401229148221728666033565104784078674
Dec 09 00:00:31 auto polkadot[54988]: 2022-12-09 00:00:31 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 1.1MiB/s ⬆ 7.1MiB/s
Dec 09 00:00:36 auto polkadot[54988]: 2022-12-09 00:00:36 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 815.3kiB/s ⬆ 734.8kiB/s
Dec 09 00:00:41 auto polkadot[54988]: 2022-12-09 00:00:41 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 1.2MiB/s ⬆ 1.6MiB/s
Dec 09 00:00:46 auto polkadot[54988]: 2022-12-09 00:00:46 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 873.0kiB/s ⬆ 775.8kiB/s
Dec 09 00:00:50 auto polkadot[54988]: 2022-12-09 00:00:50 Dispute on candidate concluded with 'valid' result candidate_hash=0xeb0649c6b038d048e84c0e6ae1a8f75234139793deb28c87b0d9918a8c75ae78 session=26550 traceID=312401229148221728666033565104784078674
Dec 09 00:00:51 auto polkadot[54988]: 2022-12-09 00:00:51 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 1.6MiB/s ⬆ 1.8MiB/s
Dec 09 00:00:56 auto polkadot[54988]: 2022-12-09 00:00:56 💤 Idle (200 peers), best: #15675244 (0x5542…83aa), finalized #15675181 (0xebdb…b046), ⬇ 1.6MiB/s ⬆ 782.7kiB/s
Dec 09 00:01:00 auto polkadot[54988]: 2022-12-09 00:01:00 New dispute initiated for candidate. candidate_hash=0x2cd649044dca4e9ea15c8c3cd9166c42f070ad94e49ae85954f058a16d2ee8b1 session=26550 traceID=59598664299151388191875610784774384706
Dec 09 00:01:00 auto polkadot[54988]: 2022-12-09 00:01:00 Dispute on candidate concluded with 'valid' result candidate_hash=0x2cd649044dca4e9ea15c8c3cd9166c42f070ad94e49ae85954f058a16d2ee8b1 session=26550 traceID=59598664299151388191875610784774384706
Dec 09 00:01:00 auto polkadot[54988]: 2022-12-09 00:01:00 New dispute initiated for candidate. candidate_hash=0x099b526589c28af01cfed1bca487222464723152a71fecddb18ce0a61ce4f9a9 session=26550 traceID=12769529177403688586641415157907399204
Dec 09 00:01:00 auto polkadot[54988]: 2022-12-09 00:01:00 Dispute on candidate concluded with 'valid' result candidate_hash=0x099b526589c28af01cfed1bca487222464723152a71fecddb18ce0a61ce4f9a9 session=26550 traceID=12769529177403688586641415157907399204
Dec 09 00:01:00 auto polkadot[54988]: 2022-12-09 00:01:00 New dispute initiated for candidate. candidate_hash=0x6eccee7c701aa440a12b6e5e008df32a975d21809df8f384c52d0884acc1633d session=26550 traceID=147279145167954200553586695736319144746

[rphmeier]

Thanks @CertHum-Jim - hiding to reduce noise.

Please do not post logs unless your node specifically has gone down or has initiated a dispute, to avoid noise, but if in doubt please post and we will hide if not useful.

[senseless]

I have posted logs below. I had 2 of 5 active set validators seize up and fail to continue working or exit out with a failure. Log set below are for the 2 nodes that went offline.

https://gist.githubusercontent.com/senseless/69b5391408055620cf1c385d214752f3/raw/7f4ad237a44664608d0d8d0d7b283220b9914a4e/Validator:%2520CibcGcwnThunMNYrStEWHYdr5WDuy8QnMgT3Vr39JeWCcQs

https://gist.githubusercontent.com/senseless/69b5391408055620cf1c385d214752f3/raw/7f4ad237a44664608d0d8d0d7b283220b9914a4e/Validator:%2520F8FswEGD1quEyNciuR9KwsragUmqnk7mFLqmAdRdnY9Sdwx

[rphmeier]

@senseless Thanks. The nodes here didn't go down, but did seize up and failed to sync at a reasonable rate. Presumably related to the "Flooding" logs.

[paradox-tt]

Posting from one node,

-- Logs begin at Fri 2022-12-02 11:29:36 UTC, end at Fri 2022-12-09 03:18:18 UTC. --

Dec 08 23:39:13 ns3219400 polkadot[364299]: 2022-12-08 23:39:13 dropping (Stream e9a274e4/23838) because buffer is full
Dec 08 23:39:13 ns3219400 polkadot[364299]: 2022-12-08 23:39:13 dropping (Stream e9a274e4/23840) because buffer is full
Dec 08 23:39:13 ns3219400 polkadot[364299]: 2022-12-08 23:39:13 dropping (Stream e9a274e4/23842) because buffer is full
Dec 08 23:39:13 ns3219400 polkadot[364299]: 2022-12-08 23:39:13 dropping (Stream e9a274e4/23844) because buffer is full
Dec 08 23:39:13 ns3219400 polkadot[364299]: 2022-12-08 23:39:13 dropping (Stream e9a274e4/23846) because buffer is full
Dec 08 23:39:13 ns3219400 polkadot[364299]: 2022-12-08 23:39:13 dropping (Stream e9a274e4/23848) because buffer is full
Dec 08 23:39:17 ns3219400 polkadot[364299]: 2022-12-08 23:39:17 💤 Idle (40 peers), best: #15675154 (0x799a…afb4), finalized #15675123 (0x1032…cc38), ⬇ 2.1MiB/s ⬆ 718.4kiB/s
Dec 08 23:39:19 ns3219400 polkadot[364299]: 2022-12-08 23:39:19 Creating inherent data providers took more time than we had left for the slot.
Dec 08 23:39:22 ns3219400 polkadot[364299]: 2022-12-08 23:39:22 💤 Idle (40 peers), best: #15675154 (0x799a…afb4), finalized #15675123 (0x1032…cc38), ⬇ 702.0kiB/s ⬆ 270.7kiB/s
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 Call to `DetermineUndisputedChain` failed error=DetermineUndisputedChainCanceled(Canceled)
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 Subsystem dispute-coordinator-subsystem appears unresponsive. origin=polkadot_service::relay_chain_selection::SelectRelayChainInner<sc_client_db::Backend<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32, sp_runtime::traits::BlakeTwo256>, sp_runtime::OpaqueExtrinsic>>, polkadot_overseer::Handle>
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 err=ContextChannelClosed
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 Failed to receive a message from Overseer, exiting err=Generated(Context("Signal channel is terminated and empty."))
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="pvf-checker-subsystem" err=FromOrigin { origin: "pvf-checker", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="approval-voting-subsystem" err=FromOrigin { origin: "approval-voting", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="candidate-validation-subsystem" err=FromOrigin { origin: "candidate-validation", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 error receiving message from subsystem context: Generated(Context("Signal channel is terminated and empty.")) err=Generated(Context("Signal channel is terminated and empty."))
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 Essential task `overseer` failed. Shutting down service.
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 Unable to author block in slot. No best block header: Request for leaves from chain selection got canceled
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 err=Subsystem(Generated(Context("Signal channel is terminated and empty.")))
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="statement-distribution-subsystem" err=FromOrigin { origin: "statement-distribution", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="bitfield-signing-subsystem" err=FromOrigin { origin: "bitfield-signing", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 GRANDPA voter error: safety invariant has been violated: `voter_commands_rx` was closed.
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 Essential task `grandpa-voter` failed. Shutting down service.
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="availability-recovery-subsystem" err=FromOrigin { origin: "availability-recovery", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="runtime-api-subsystem" err=Generated(Context("Signal channel is terminated and empty."))
Dec 08 23:39:26 ns3219400 polkadot[364299]: 2022-12-08 23:39:26 subsystem exited with error subsystem="availability-distribution-subsystem" err=FromOrigin { origin: "availability-distribution", source: IncomingMessageChannel(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:49:43 ns3219400 systemd[1]: Stopping Kusama Node...

I invoked the stop manually when the error was detected.

I should have logs from two other nodes, shall I post as well?

[tdimitrov]

I should have logs from two other nodes, shall I post as well?

Yes, please.

[senseless]

@senseless Thanks. The nodes here didn't go down, but did seize up and failed to sync at a reasonable rate. Presumably related to the "Flooding" logs.

When they seized they failed to output any additional logs in the log file until I restarted the node.

[rphmeier]

Were those the absolute last logs in the log file? If so, something must have been cut off...

[rphmeier]

@paradox-tt, to confirm, the node outputting those logs did not actually shut down but just hung for 10 minutes until stopped manually?

[senseless]

Were those the absolute last logs in the log file? If so, something must have been cut off...

Yes, the last line was the last line in the log file.

[paradox-tt]

To reduce on noise I used ... to replace a few lines of "dropping (Stream aaae890a/9699) because buffer is full".

This node hung to the point that it did not produce a block or heartbeat in the session and was slashed. I was able to restart and re-declare the intent for the next session.

Timing:

Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="dispute-coordinator-subsystem" err=FromOrigin { origin: "dispute-coordinator", source: ChainApiSenderDropped }
Dec 09 00:45:15 ns3219400 systemd[1]: Stopping Kusama Node...

-- Logs begin at Fri 2022-12-02 11:29:36 UTC, end at Fri 2022-12-09 03:23:59 UTC. --
...
Dec 08 23:39:37 ns3219400 polkadot[527355]: 2022-12-08 23:39:37 💤 Idle (40 peers), best: #15675156 (0x2050…cc1b), finalized #15675123 (0x1032…cc38), ⬇ 1.2MiB/s ⬆ 763.1kiB/s
Dec 08 23:39:39 ns3219400 polkadot[527355]: 2022-12-08 23:39:39 ♻�  Reorg on #15675156,0x2050…cc1b to #15675151,0xdbda…58bf, common ancestor #15675150,0x85f8…bcf9
Dec 08 23:39:39 ns3219400 polkadot[527355]: 2022-12-08 23:39:39 ✨ Imported #15675151 (0xdbda…58bf)
Dec 08 23:39:42 ns3219400 polkadot[527355]: 2022-12-08 23:39:42 💤 Idle (40 peers), best: #15675151 (0xdbda…58bf), finalized #15675123 (0x1032…cc38), ⬇ 359.8kiB/s ⬆ 216.8kiB/s
Dec 08 23:39:47 ns3219400 polkadot[527355]: 2022-12-08 23:39:47 💤 Idle (40 peers), best: #15675151 (0xdbda…58bf), finalized #15675123 (0x1032…cc38), ⬇ 618.7kiB/s ⬆ 485.4kiB/s
Dec 08 23:39:50 ns3219400 polkadot[527355]: 2022-12-08 23:39:50 ✨ Imported #15675152 (0xa37a…ec14)
Dec 08 23:39:50 ns3219400 polkadot[527355]: 2022-12-08 23:39:50 dropping (Stream 1df5effb/11727) because buffer is full
Dec 08 23:39:50 ns3219400 polkadot[527355]: 2022-12-08 23:39:50 dropping (Stream 1df5effb/11729) because buffer is full
Dec 08 23:39:51 ns3219400 polkadot[527355]: 2022-12-08 23:39:51 dropping (Stream 044350ef/4833) because buffer is full
Dec 08 23:39:51 ns3219400 polkadot[527355]: 2022-12-08 23:39:51 dropping (Stream 044350ef/4835) because buffer is full
Dec 08 23:39:51 ns3219400 polkadot[527355]: 2022-12-08 23:39:51 dropping (Stream 044350ef/4837) because buffer is full
Dec 08 23:39:51 ns3219400 polkadot[527355]: 2022-12-08 23:39:51 dropping (Stream fb8e0f0c/6483) because buffer is full
Dec 08 23:39:51 ns3219400 polkadot[527355]: 2022-12-08 23:39:51 dropping (Stream fb8e0f0c/6485) because buffer is full
Dec 08 23:39:51 ns3219400 polkadot[527355]: 2022-12-08 23:39:51 dropping (Stream fb8e0f0c/6487) because buffer is full
...
Dec 08 23:39:52 ns3219400 polkadot[527355]: 2022-12-08 23:39:52 dropping (Stream aaae890a/10097) because buffer is full
Dec 08 23:39:52 ns3219400 polkadot[527355]: 2022-12-08 23:39:52 dropping (Stream 0771cf3d/15771) because buffer is full
Dec 08 23:39:52 ns3219400 polkadot[527355]: 2022-12-08 23:39:52 💤 Idle (40 peers), best: #15675152 (0xa37a…ec14), finalized #15675123 (0x1032…cc38), ⬇ 2.7MiB/s ⬆ 1013.4kiB/s
Dec 08 23:39:53 ns3219400 polkadot[527355]: 2022-12-08 23:39:53 dropping (Stream 2d1fa8d5/11258) because buffer is full
Dec 08 23:39:53 ns3219400 polkadot[527355]: 2022-12-08 23:39:53 dropping (Stream 2d1fa8d5/11260) because buffer is full
...
Dec 08 23:39:53 ns3219400 polkadot[527355]: 2022-12-08 23:39:53 dropping (Stream eb168d87/2984) because buffer is full
Dec 08 23:39:53 ns3219400 polkadot[527355]: 2022-12-08 23:39:53 dropping (Stream eb168d87/2986) because buffer is full
...
Dec 08 23:40:07 ns3219400 polkadot[527355]: 2022-12-08 23:40:07 dropping (Stream 8b88c072/3419) because buffer is full
Dec 08 23:40:07 ns3219400 polkadot[527355]: 2022-12-08 23:40:07 dropping (Stream 8b88c072/3421) because buffer is full
Dec 08 23:40:07 ns3219400 polkadot[527355]: 2022-12-08 23:40:07 💤 Idle (40 peers), best: #15675153 (0x594b…c937), finalized #15675123 (0x1032…cc38), ⬇ 2.3MiB/s ⬆ 978.8kiB/s
Dec 08 23:40:08 ns3219400 polkadot[527355]: 2022-12-08 23:40:08 dropping (Stream 0771cf3d/16009) because buffer is full
Dec 08 23:40:08 ns3219400 polkadot[527355]: 2022-12-08 23:40:08 dropping (Stream 0771cf3d/16011) because buffer is full
...
Dec 08 23:40:08 ns3219400 polkadot[527355]: 2022-12-08 23:40:08 dropping (Stream e3affccc/20524) because buffer is full
Dec 08 23:40:08 ns3219400 polkadot[527355]: 2022-12-08 23:40:08 dropping (Stream e3affccc/20526) because buffer is full
Dec 08 23:40:08 ns3219400 polkadot[527355]: 2022-12-08 23:40:08 dropping (Stream e3affccc/20528) because buffer is full
Dec 08 23:40:08 ns3219400 polkadot[527355]: 2022-12-08 23:40:08 dropping (Stream e3affccc/20530) because buffer is full
Dec 08 23:40:12 ns3219400 polkadot[527355]: 2022-12-08 23:40:12 💤 Idle (40 peers), best: #15675153 (0x594b…c937), finalized #15675123 (0x1032…cc38), ⬇ 944.4kiB/s ⬆ 346.2kiB/s
Dec 08 23:40:17 ns3219400 polkadot[527355]: 2022-12-08 23:40:17 💤 Idle (40 peers), best: #15675153 (0x594b…c937), finalized #15675123 (0x1032…cc38), ⬇ 383.1kiB/s ⬆ 299.2kiB/s
Dec 08 23:40:20 ns3219400 polkadot[527355]: 2022-12-08 23:40:20 dropping (Stream 68611826/9015) because buffer is full
Dec 08 23:40:20 ns3219400 polkadot[527355]: 2022-12-08 23:40:20 dropping (Stream 68611826/9017) because buffer is full
Dec 08 23:40:20 ns3219400 polkadot[527355]: 2022-12-08 23:40:20 dropping (Stream 68611826/9019) because buffer is full
Dec 08 23:40:20 ns3219400 polkadot[527355]: 2022-12-08 23:40:20 dropping (Stream 68611826/9035) because buffer is full
Dec 08 23:40:22 ns3219400 polkadot[527355]: 2022-12-08 23:40:22 💤 Idle (40 peers), best: #15675153 (0x594b…c937), finalized #15675123 (0x1032…cc38), ⬇ 286.7kiB/s ⬆ 240.8kiB/s
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Call to `DetermineUndisputedChain` failed error=DetermineUndisputedChainCanceled(Canceled)
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Subsystem dispute-coordinator-subsystem appears unresponsive. origin=polkadot_service::relay_chain_selection::SelectRelayChainInner<sc_client_db::Backend<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32, sp_runtime::traits::BlakeTwo256>, sp_runtime::OpaqueExtrinsic>>, polkadot_overseer::Handle>
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 err=ContextChannelClosed
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="bitfield-signing-subsystem" err=FromOrigin { origin: "bitfield-signing", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="availability-distribution-subsystem" err=FromOrigin { origin: "availability-distribution", source: IncomingMessageChannel(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="availability-recovery-subsystem" err=FromOrigin { origin: "availability-recovery", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Failed to receive a message from Overseer, exiting err=Generated(Context("Signal channel is terminated and empty."))
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="network-bridge-subsystem" err=FromOrigin { origin: "network-bridge", source: SubsystemError(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 error receiving message from subsystem context: Generated(Context("Signal channel is terminated and empty.")) err=Generated(Context("Signal channel is terminated and empty."))
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="approval-voting-subsystem" err=FromOrigin { origin: "approval-voting", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Fetch for approval votes got cancelled, only expected during shutdown!
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Essential task `overseer` failed. Shutting down service.
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 New dispute initiated for candidate. candidate_hash=0xe1e677e00a3a3411c4bad16559c4753c47cd51043159b1f4399caea155bfb91b session=26550 traceID=300272958686085533188489404059870328124
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Dispute on candidate concluded with 'valid' result candidate_hash=0xe1e677e00a3a3411c4bad16559c4753c47cd51043159b1f4399caea155bfb91b session=26550 traceID=300272958686085533188489404059870328124
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Unable to author block in slot. No best block header: Request for leaves from chain selection got canceled
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Fetch for approval votes got cancelled, only expected during shutdown!
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 New dispute initiated for candidate. candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Dispute on candidate concluded with 'valid' result candidate_hash=0xfcd08ae3f48e2eb589415d6cecffe6e65cfd8a7fb587323deae45faf8552ac67 session=26550 traceID=336048269717378469227419513318138701542
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="runtime-api-subsystem" err=Generated(Context("Signal channel is terminated and empty."))
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="statement-distribution-subsystem" err=FromOrigin { origin: "statement-distribution", source: SubsystemReceive(Generated(Context("Signal channel is terminated and empty."))) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 GRANDPA voter error: safety invariant has been violated: `voter_commands_rx` was closed.
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 Essential task `grandpa-voter` failed. Shutting down service.
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="candidate-validation-subsystem" err=FromOrigin { origin: "candidate-validation", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 err=Subsystem(Generated(Context("Signal channel is terminated and empty.")))
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="chain-api-subsystem" err=FromOrigin { origin: "chain-api", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="pvf-checker-subsystem" err=FromOrigin { origin: "pvf-checker", source: Generated(Context("Signal channel is terminated and empty.")) }
Dec 08 23:40:24 ns3219400 polkadot[527355]: 2022-12-08 23:40:24 subsystem exited with error subsystem="dispute-coordinator-subsystem" err=FromOrigin { origin: "dispute-coordinator", source: ChainApiSenderDropped }

[paradox-tt]

@paradox-tt, to confirm, the node outputting those logs did not actually shut down but just hung for 10 minutes until stopped manually?

That is correct.