[Alphanet] Parachain Collation Wasn't Advertised to Any Validator

[albertov19]

A team is onboarding a parachain (ID 900) with node ID --Alice.

They were able to produce only 1 block, and since that block, we just see:

2024-02-19 18:39:10 [Relaychain] Collation wasn't advertised to any validator. candidate_hash=0x39651a0176615fc0a04f9a5828bde938b85a4276e4fac1cb69f0e21310b04ac1 

The node was more or less run with the following command:

docker run -it -v $(pwd):/specs \
--name=trappist-alice \
paritytech/trappist:v1.5.0b-westend trappist-node \
--chain=/specs/alphanet_trappist_raw.json \
--validator --alice \
--blocks-pruning archive --state-pruning archive \
-- \
--chain=/specs/westend-alphanet-raw-specs.json \
--sync fast \
--state-pruning 50 --blocks-pruning 50

The full logs are attached

Logs.txt

[crystalin]

Looking at the logs:

1. Relay block is received

00:02:42.113  INFO substrate: [Relaychain] ✨ Imported #14301341 (0x07da…dd46)

2. Collator block (aka "candidate") is produced (within reasonable time (< 1000ms) after the relay block is imported)

00:02:42.125  INFO aura::cumulus: [Parachain] 🔖 Pre-sealed block for proposal at 1. Hash now 
00:02:42.127  INFO substrate: [Parachain] ✨ Imported #1 (0xc104…44b7)
00:02:42.128 DEBUG parachain::collation-generation: [Relaychain] candidate is generated candidate_hash=0xb1f034827efcb2a9cefc721387ca22aacc96eac9c7d8e18c14d378fde0b3d06a pov_hash=0x42b92969a268fe1219f1447554522dd349db3456d8e3ef884cb5d38650df7eb9 relay_parent=0x07da7a5812f7578a9c578ff53619fdaba1a75a04f57f102d396951dcb036dd46 para_id=900 traceID=236520571524239589133728087165677216426

3. Candidate is properly advertised to the validator in charge:

00:02:42.129 DEBUG parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=1 failed_to_resolve=0
00:02:42.129 DEBUG parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=1 removed=0
00:02:42.467 DEBUG parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWKNim53CCELvPizuwCNdB8Xh4anYvAbpEWbeqTFv3CdAs") role=Authority
00:02:42.488 DEBUG parachain::collator-protocol: [Relaychain] Advertising collation. relay_parent=0x07da7a5812f7578a9c578ff53619fdaba1a75a04f57f102d396951dcb036dd46 candidate_hash=0xb1f034827efcb2a9cefc721387ca22aacc96eac9c7d8e18c14d378fde0b3d06a peer_id=12D3KooWKNim53CCELvPizuwCNdB8Xh4anYvAbpEWbeqTFv3CdAs traceID=236520571524239589133728087165677216426

4. Candidate is not processed in time (6s between each relay block, which triggers a "view changed"):

00:02:44.556 DEBUG parachain::collator-protocol: [Relaychain] Removing relay parent because our view changed. relay_parent=0x76de7533df34b30a1c9b9445eefcd34bc59ba7c1abd891d19161cf3116850427
00:02:44.556  WARN parachain::collator-protocol: [Relaychain] Collation wasn't advertised to any validator. candidate_hash=0xfd7e936c230ac263dd96d0a000f9b82cb9700ba50de3c1bb84d1bac7709fc759 pov_hash=0x9e869583199dce1427a882562599fd6db31485d836676a546726a9f489ebb151 traceID=336951902419457375045194551757144438828

This indicates it is probably failing somewhere in the validator. I'll gather some of the validators logs on Alphanet and reply

[crystalin]

Looking at validator logs, we can see they have trouble executing the block through pvf:

2024-02-20 11:03:41.504 ERROR tokio-runtime-worker runtime: panicked at /home/builder/cargo/git/checkouts/polkadot-sdk-cff69157b985ed76/af5beb7/substrate/primitives/state-machine/src/ext.rs:300:48: Externalities not allowed to fail within runtime: DefaultError
2024-02-20 11:03:41.507  WARN tokio-runtime-worker parachain::pvf: execution worker concluded, error occurred: InvalidCandidate(WorkerReportedError("execute: execute error: AbortedDueToTrap(MessageWithBacktrace { message: \"wasm trap: wasm `unreachable` instruction executed\", backtrace: Some(Backtrace { backtrace_string: \"error while executing at wasm backtrace:\\n    0: 0xbfdb3 - <unknown>!rust_begin_unwind\\n    1: 0xe4d5 - <unknown>!core::panicking::panic_fmt::h7a368385936888dc\\n    2: 0xf1a0 - <unknown>!core::result::unwrap_failed::hbe79a418fab461ff\\n    3: 0x315447 - <unknown>!<sp_state_machine::ext::Ext<H,B> as sp_externalities::Externalities>::next_storage_key::h44090e8d4dadfd41\\n    4: 0x729917 - <unknown>!<wasm function 9290>\\n    5: 0x1de39 - <unknown>!environmental::local_key::LocalKey<T>::with::had71a56877431907\\n    6: 0x2accd - <unknown>!cumulus_pallet_parachain_system::validate_block::implementation::host_storage_next_key::h9c7abace271d41d9\\n    7: 0x721409 - <unknown>!<wasm function 8318>\\n    8: 0x5f719b - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14,TupleElement15,TupleElement16,TupleElement17,TupleElement18,TupleElement19,TupleElement20,TupleElement21,TupleElement22,TupleElement23,TupleElement24,TupleElement25,TupleElement26,TupleElement27,TupleElement28,TupleElement29,TupleElement30,TupleElement31,TupleElement32) as frame_support::traits::hooks::BeforeAllRuntimeMigrations>::before_all_runtime_migrations::hca7d458f1c319734\\n    9: 0x62cd81 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block::h1d8d606276b1ba7c\\n   10: 0x62c010 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COn RuntimeUpgrade>::execute_block::hfd08d2b96b662cd6\\n   11: 0x477798 - <unknown>!<cumulus_pallet_aura_ext::BlockExecutor<T,I> as frame_support::traits::misc::ExecuteBlock<Block>>::execute_block::he9e9eb4b6f9b3ff1\\n   12: 0x61d876 - <unknown>!environmental::local_key::LocalKey<T>::with::h7f63e91cfdc26e89\\n   13: 0x30d20f - <unknown>!cumulus_pallet_parachain_system::validate_block::implementation::validate_block::hc7eac773e5fb8368\\n   14: 0x6745af - <unknown>!validate_block\\n   15: 0x72dd9b - <unknown>!<wasm function 9804>\" }) })")) artifact_id=ArtifactId { code_hash: 0x0e965d85ef4d284e4e6a2363ee89175edc31a73cc122fbaaa1f82f84a899c9bb, executor_params_hash: 0x03170a2e7597b7b7e3d84c05391d139a62b157e78786d8c082f29dcf4c111314 } worker=Worker(1v1) worker_rip=false
2024-02-20 11:03:41.507  INFO tokio-runtime-worker parachain::candidate-validation: Failed to validate candidate para_id=Id(900) error=InvalidCandidate(WorkerReportedError("execute: execute error: AbortedDueToTrap(MessageWithBacktrace { message: \"wasm trap: wasm `unreachable` instruction executed\", backtrace: Some(Backtrace { backtrace_string: \"error while executing at wasm backtrace:\\n    0: 0xbfdb3 - <unknown>!rust_begin_unwind\\n    1: 0xe4d5 - <unknown>!core::panicking::panic_fmt::h7a368385936888dc\\n    2: 0xf1a0 - <unknown>!core::result::unwrap_failed::hbe79a418fab461ff\\n    3: 0x315447 - <unknown>!<sp_state_machine::ext::Ext<H,B> as sp_externalities::Externalities>::next_storage_key::h44090e8d4dadfd41\\n    4: 0x729917 - <unknown>!<wasm function 9290>\\n    5: 0x1de39 - <unknown>!environmental::local_key::LocalKey<T>::with::had71a56877431907\\n    6: 0x2accd - <unknown>!cumulus_pallet_parachain_system::validate_block::implementation::host_storage_next_key::h9c7abace271d41d9\\n    7: 0x721409 - <unknown>!<wasm function 8318>\\n    8: 0x5f719b - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14,TupleElement15,TupleElement16,TupleElement17,TupleElement18,TupleElement19,TupleElement20,TupleElement21,TupleElement22,TupleElement23,TupleElement24,TupleElement25,TupleElement26,TupleElement27,TupleElement28,TupleElement29,TupleElement30,TupleElement31,TupleElement32) as frame_support::traits::hooks::BeforeAllRuntimeMigrations>::before_all_runtime_migrations::hca7d458f1c319734\\n    9: 0x62cd81 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block::h1d8d606276b1ba7c\\n   10: 0x62c010 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::execute_block::hfd08d2b96b662cd6\\n   11: 0x477798 - <unknown>!<cumulus_pallet_aura_ext::BlockExecutor<T,I> as frame_support::traits::misc::ExecuteBlock<Block>>::execute_block::he9e9eb4b6f9b3ff1\\n   12: 0x61d876 - <unknown>!environmental::local_key::LocalKey<T>::with::h7f63e91cfdc26e89\\n   13: 0x30d20f - <unknown>!cumulus_pallet_parachain_system::validate_block::implementation::validate_block::hc7eac773e5fb8368\\n   14: 0x6745af - <unknown>!validate_block\\n   15: 0x72dd9b - <unknown>!<wasm function 9804>\" }) })"))
2024-02-20 11:03:41.508  WARN tokio-runtime-worker parachain::candidate-backing: Validation yielded an invalid candidate candidate_hash=0xac51ff60c76d9fb250b78f105be706716348d133137b5072b5971de6185e8457 reason=ExecutionError("execute: execute error: AbortedDueToTrap(MessageWithBacktrace { message: \"wasm trap: wasm `unreachable` instruction executed\", backtrace: Some(Backtrace { backtrace_string: \"error while executing at wasm backtrace:\\n    0: 0xbfdb3 - <unknown>!rust_begin_unwind\\n    1: 0xe4d5 - <unknown>!core::panicking::panic_fmt::h7a368385936888dc\\n    2: 0xf1a0 - <unknown>!core::result::unwrap_failed::hbe79a418fab461ff\\n    3: 0x315447 - <unknown>!<sp_state_machine::ext::Ext<H,B> as sp_externalities::Externalities>::next_storage_key::h44090e8d4dadfd41\\n    4: 0x729917 - <unknown>!<wasm function 9290>\\n    5: 0x1de39 - <unknown>!environmental::local_key::LocalKey<T>::with::had71a56877431907\\n    6: 0x2accd - <unknown>!cumulus_pallet_parachain_system::validate_block::implementation::host_storage_next_key::h9c7abace271d41d9\\n    7: 0x721409 - <unknown>!<wasm function 8318>\\n    8: 0x5f719b - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14,TupleElement15,TupleElement16,TupleElement17,TupleElement18,TupleElement19,TupleElement20,TupleElement21,TupleElement22,TupleElement23,TupleElement24,TupleElement25,TupleElement26,TupleElement27,TupleElement28,TupleElement29,TupleElement30,TupleElement31,TupleElement32) as frame_support::traits::hooks::BeforeAllRuntimeMigrations>::before_all_runtime_migrations::hca7d458f1c319734\\n    9: 0x62cd81 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block::h1d8d606276b1ba7c\\n   10: 0x62c010 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::execute_block::hfd08d2b96b662cd6\\n   11: 0x477798 - <unknown>!<cumulus_pallet_aura_ext::BlockExecutor<T,I> as frame_support::traits::misc::ExecuteBlock<Block>>::execute_block::he9e9eb4b6f9b3ff1\\n   12: 0x61d876 - <unknown>!environmental::local_key::LocalKey<T>::with::h7f63e91cfdc26e89\\n   13: 0x30d20f - <unknown>!cumulus_pallet_parachain_system::validate_block::implementation::validate_block::hc7eac773e5fb8368\\n   14: 0x6745af - <unknown>!validate_block\\n   15: 0x72dd9b - <unknown>!<wasm function 9804>\" }) })") traceID=229052971002619427737093459494543230577
2024-02-20 11:03:41.617 DEBUG tokio-runtime-worker parachain::collator-protocol: Timeout hit - already seconded? relay_parent=0x2a97923bbe4fd8431a14277ba2dbade08f5ba643a3e6d57c8535ec0b7ace5be3 collator_id=Public(9a904858b6a2e64b446cf5e20901fe188cc43911ed535d36fe771a2fc6fabc14 (5FZN6Jii...))

[librelois]

@albertov19 can we have a link to their runtime source code? (repo and release tag)

[metricaez]

Hi!

Here is the repo: https://github.com/paritytech/trappist/tree/westend

We branched Trappist and adapted it to westend to make it compatible with Alphanet.