Parachain Node stop collating - Parachain network stalled for few days

[crystalin]

cc @bkchr

Moonbeam node, starting collation every 6s (not 12s because the network is stall but that is irrelevant to the issue) from 2022-12-06 20:31:12.099 to 2022-12-06 20:31:54.033 and then stops while still important new relay blocks:

params:

     --validator \
     --port 30333 \
     --rpc-port 9933 \
     --ws-port 9944 \
     --execution wasm \
     --wasm-execution compiled \
     --log=parachain::collator-protocol=trace,debug,libp2p=info,multi=info,netlink=info,peer=info,sync=info \
     --pruning=256 \
     --keep-blocks=1000 \
     --state-cache-size 0 \
     --db-cache 16000 \
     --base-path /var/lib/alphanet-data \
     --chain alphanet \
     --pool-limit 1 \
     -- \
     --pruning=1 \
     --keep-blocks=1 \
     --sync=fast-unsafe \
     --port 30334 \
     --rpc-port 9934 \
     --ws-port 9945 \
     --execution wasm

logs:
node-starting.log

[crystalin]

I added a case where the "Starting collation" resumed later:

restart-collation.log

[crystalin]

Another exemple with cumulus tracing:
Stopped at 21:41:18 and resumed at 21:41:54
restart-collation-trace.log

[crystalin]

Per Basti request, more logs:
Missing creation from 21:53:54 -> 21:54:54 (1 minute, which is also the period of the validation core rotation)
restart-collation-generation-trace.log

[bkchr]

Looks like the core is occupied all the time, making it impossible to produce a block.

[crystalin]

Logs from a validator assigned to para 1000:
polka-13.log

[bkchr]

Yeah I see a lot of:

2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(d49d9cb4e7afd080ff62c7a5deb55571b5f069525d9c03f31c3e15a964152d49 (5GsUq42N...)) relay_parent=0x6fcbe4fd7805a83e5ecd55f9ac13283c3b2864e16ae2413851dfdd6f920393c5 group_index=GroupIndex(9) session_index=13421 chunk_index=ValidatorIndex(16) candidate_hash=0x051092126b3c0dabd85909bc54b842c93496aca3c764eeaa8b75dff98b2e7c2d err=NotConnected traceID=6732179419757691168023312528502702793
2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(048277b772cf8479df897bdf01f5e430e121d235c62d3e52e5c0e70d5b54eb3e (5CAcogaP...)) relay_parent=0x4f6f052ef389ba663d5be7bacc62678745478fca33b6373a30042323f9cf2ecc group_index=GroupIndex(19) session_index=13421 chunk_index=ValidatorIndex(16) candidate_hash=0x655218c9ea8e1b0ca3980924ceb55a1943986a7df00c6e9fabefb432baec0da2 err=NotConnected traceID=134678298691958799537670216691351902745
2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(80b12af78701229f58e609c0666aad8656ebf8f9b6e7bb8849fe84c5852ef251 (5EySchJG...)) relay_parent=0x4f6f052ef389ba663d5be7bacc62678745478fca33b6373a30042323f9cf2ecc group_index=GroupIndex(1) session_index=13421 chunk_index=ValidatorIndex(16) candidate_hash=0xfb75c86893a258d181bb518dfdc73dcca6b5d3941a4ea6b0e7e0e56fa9f01962 err=NotConnected traceID=334247790441802652608452993464461114828
2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(9a544e50191b8af555ced5838bf071131b510f2e7cc3343be1891d19c80ed801 (5FZ4Gw1J...)) relay_parent=0x44bb7e4ae10c77db096f24cbba1472a9e40aee208bbc1827c7835ea14b8e293f group_index=GroupIndex(10) session_index=13421 chunk_index=ValidatorIndex(16) candidate_hash=0xbdacfa9a3468a33fddde51b4b13b72d4cc7693e3e3a0f3363d689809ffcb7319 err=NotConnected traceID=252122249082774750165059510947651744468
2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(6ccbc516b7e1f13a3756cb5ed2e6861bbc9a15e697f42bb192c945180e657612 (5EXMZVUf...)) relay_parent=0x44bb7e4ae10c77db096f24cbba1472a9e40aee208bbc1827c7835ea14b8e293f group_index=GroupIndex(11) session_index=13421 chunk_index=ValidatorIndex(16) candidate_hash=0x5360a46f3bbf77891e8a028525a45cef2e94cab1d4912363b96be6216cf755ea err=NotConnected traceID=110827719276559483762667640835392429295
2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk origin=Public(d27b0ec2982bb7e41d6706e7a50a673375ed050633e5d2bb4f2d4ef798cfd301 (5GpgU8zE...)) relay_parent=0x44bb7e4ae10c77db096f24cbba1472a9e40aee208bbc1827c7835ea14b8e293f group_index=GroupIndex(13) session_index=13421 chunk_index=ValidatorIndex(16) candidate_hash=0xb8d7d6ab1488248fe6564db6e7b3c8d1d48bba41828f71d730ae5dd257b012ba err=NotConnected traceID=245698649039034766718676824724792920273
2022-12-06 22:26:42.223 DEBUG tokio-runtime-worker parachain::availability-distribution: Some network error occurred when fetching erasure chunk

Which seems to support my "suspicion" that we fail to distribute the chunks of a POV and thus we see the timeout when rotate the validators. As there is only one backing validator, this makes it impossible to fetch the chunk from somewhere else.

@crystalin can you please also add -lpeerset=trace,sub-libp2p=trace (and keep the old targets as well!)

[crystalin]

@bkchr I can't reproduce it anymore on the same network (our Alphanet) as the nodes are now producing blocks correctly.
I'm planning to create a new network and test if I can have the same scenario reproduce the same behavior on it

[crystalin]

Additional information:

This issue was only reproducable on our Alphanet Network and not locally nor other smaller networks:

• Runtime: Westend 9340
• Client: 0.9.29 - 0.9.33
• 21 validators
• 15 parachains => 100+ collators
• 1 validator / core

Runtime upgrade used to introduced a small stall, but this usually recovered quickly. With recent version (I think since 0.9.29), it introduce a "permanent" stall, until we change the "validator per core" to 2

Reproduction

We have been able to reproduce it with another parachain, which is currently stalled, on the same relay (polkadot.js

• Parachain 888

Logs using 1 validator, restricted to 1 core rotation before and after the 888 assigment: https://drive.google.com/file/d/1b_31w13zeW5_3OnPrks8zV0w6GKrHgOM/view?usp=share_link
./polkadot --validator --port 30312 --rpc-port 9955 --ws-port 9966 --chain westend-raw-specs.json --base-path ./ -linfo,netlink=info,wasm=info,parachain=trace,peerset=trace,sub-libp2p=trace --in-peers 5 --out-peers 5 --db-cache 8000

[bkchr]

I looked at these logs for way too long! The problem (as always) there are certain information missing. I created the following pr to add some missing info that may help to debug this: paritytech/polkadot#6455

Could you use this to build a new validator binary @crystalin?

[crystalin]

Thank you @bkchr. I know it is exhausting to troubleshoot those issue and I really appreciate your effort.
I'm going to prepare the binary for your changes and will update this ticket too.

[crystalin]

Unfortunately the parachain is producing blocks now so I need to find another parachain I can use to trigger the issue. i'll update you once I can

[hub-il]

I believe I am having the same issue on statemint. Is there a way I can confirm? I came into sync and then now after every few hours the node continues to run but I stop getting new blocks. If I restart the node then it starts up again for a bit.

[crystalin]

I believe this is a different issue. In this ticket we are talking about a full network not producing block, not just a single node