(draft) Zombienet test with preopen hrmp with zombienet investigation

[bkontur]

Summary

Parachain does not start producing blocks with zombienet [[hrmp_channels]] preopen.
A failed assert is coming from comparing dmq_head and dmq_mqc_head here.

I raised this problem initially on element here, so this is continuing investigation.

As far as I investigated, the problem is with polkadot-parachain and cumulus's test-parachain binaries.

Error from simulation with zombienet in CI

Failed job in CI.
Check logs for collator01 in grafana.
Check logs for collator02 in grafana.

Error from local simulation with polkadot-parachain:

2023-09-18 15:38:12.042 DEBUG tokio-runtime-worker parachain::gossip-support: [Relaychain] New session detected session_index=1
2023-09-18 15:38:12.043 DEBUG tokio-runtime-worker parachain::gossip-support: [Relaychain] Determined past/present/future authorities authority_count=4
2023-09-18 15:38:12.043 DEBUG tokio-runtime-worker parachain::gossip-support: [Relaychain] Issuing a connection request num=0
2023-09-18 15:38:12.043 DEBUG tokio-runtime-worker parachain::gossip-support: [Relaychain] error=NotAValidator
2023-09-18 15:38:12.043 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Validation num_peers=0 removed=0
2023-09-18 15:38:12.043  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🙌 Starting consensus session on top of parent 0xa058d7e03e997ac221bba7ac2412ee7b5ccd468bdcbdae9c78e7092b69f90d75    
2023-09-18 15:38:12.044 ERROR tokio-runtime-worker runtime: [Parachain] panicked at 'assertion failed: `(left == right)`
  left: `0x0000000000000000000000000000000000000000000000000000000000000000`,
 right: `0x8c2c8ac7c300a894f59c59af3ce369026a302785307308265afdb7bd9e31cb37`', /home/bparity/parity/polkadot-sdk/cumulus/pallets/parachain-system/src/lib.rs:1100:9    
2023-09-18 15:38:12.044  WARN tokio-runtime-worker sp_state_machine::overlayed_changes::changeset: [Parachain] 1 storage transactions are left open by the runtime. Those will be rolled back.    
2023-09-18 15:38:12.044  WARN tokio-runtime-worker sp_state_machine::overlayed_changes::changeset: [Parachain] 1 storage transactions are left open by the runtime. Those will be rolled back.    
2023-09-18 15:38:12.044  WARN tokio-runtime-worker basic-authorship: [Parachain] ❗️ Inherent extrinsic returned unexpected error: Error at calling runtime api: Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed
WASM backtrace:
error while executing at wasm backtrace:
    0: 0x21b530 - <unknown>!rust_begin_unwind
    1: 0x4236 - <unknown>!core::panicking::panic_fmt::h2aa6e58b8ba5c6ef
    2: 0x4640 - <unknown>!core::panicking::assert_failed_inner::h08436824881b8806
    3: 0x91c07 - <unknown>!core::panicking::assert_failed::h6bd5b11cdae6ff2b
    4: 0xc8222 - <unknown>!cumulus_pallet_parachain_system::<impl cumulus_pallet_parachain_system::pallet::Pallet<T>>::process_inbound_downward_messages::h0918823ba0aa57f9
    5: 0x14a049 - <unknown>!frame_support::storage::transactional::with_transaction::he29adbb80c1eb617
    6: 0x1ad813 - <unknown>!<cumulus_pallet_parachain_system::pallet::Call<T> as frame_support::traits::dispatch::UnfilteredDispatchable>::dispatch_bypass_filter::{{closure}}::hab5c52ef82b07e17
    7: 0x1afec2 - <unknown>!environmental::local_key::LocalKey<T>::with::h81c29e50f55769ff
    8: 0x6e6bf - <unknown>!<rococo_parachain_runtime::RuntimeCall as frame_support::traits::dispatch::UnfilteredDispatchable>::dispatch_bypass_filter::h1911261d5c69a058
    9: 0x6d2bb - <unknown>!<rococo_parachain_runtime::RuntimeCall as sp_runtime::traits::Dispatchable>::dispatch::h79a63c056b4e14bf
   10: 0x17683d - <unknown>!<sp_runtime::generic::checked_extrinsic::CheckedExtrinsic<AccountId,Call,Extra> as sp_runtime::traits::Applyable>::apply::h1f6bc668fd34fff7
   11: 0x1b4a86 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::apply_extrinsic::hae98089c2dad6735
   12: 0x1ef222 - <unknown>!BlockBuilder_apply_extrinsic. Dropping.    
2023-09-18 15:38:12.044 ERROR tokio-runtime-worker runtime: [Parachain] panicked at 'set_validation_data inherent needs to be present in every block!', /home/bparity/parity/polkadot-sdk/cumulus/pallets/parachain-system/src/lib.rs:248:13    
2023-09-18 15:38:12.044 ERROR tokio-runtime-worker aura::cumulus: [Parachain] err=Error { inner: Proposing

Caused by:
    0: Error at calling runtime api: Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed
       WASM backtrace:
       error while executing at wasm backtrace:
           0: 0x21b530 - <unknown>!rust_begin_unwind
           1: 0x4236 - <unknown>!core::panicking::panic_fmt::h2aa6e58b8ba5c6ef
           2: 0xc2dca - <unknown>!<cumulus_pallet_parachain_system::pallet::Pallet<T> as frame_support::traits::hooks::OnFinalize<<<<T as frame_system::pallet::Config>::Block as sp_runtime::traits::HeaderProvider>::HeaderT as sp_runtime::traits::Header>::Number>>::on_finalize::hf9b199c2e36b4960
           3: 0x62c3f - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14) as frame_support::traits::hooks::OnFinalize<BlockNumber>>::on_finalize::h32cd78e57055dc48
           4: 0x1b5001 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::idle_and_finalize_hook::h72ce54501b530cbe
           5: 0x1ef322 - <unknown>!BlockBuilder_finalize_block
    1: Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed
       WASM backtrace:
       error while executing at wasm backtrace:
           0: 0x21b530 - <unknown>!rust_begin_unwind
           1: 0x4236 - <unknown>!core::panicking::panic_fmt::h2aa6e58b8ba5c6ef
           2: 0xc2dca - <unknown>!<cumulus_pallet_parachain_system::pallet::Pallet<T> as frame_support::traits::hooks::OnFinalize<<<<T as frame_system::pallet::Config>::Block as sp_runtime::traits::HeaderProvider>::HeaderT as sp_runtime::traits::Header>::Number>>::on_finalize::hf9b199c2e36b4960
           3: 0x62c3f - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14) as frame_support::traits::hooks::OnFinalize<BlockNumber>>::on_finalize::h32cd78e57055dc48
           4: 0x1b5001 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::idle_and_finalize_hook::h72ce54501b530cbe
           5: 0x1ef322 - <unknown>!BlockBuilder_finalize_block }
2023-09-18 15:38:12.044 DEBUG tokio-runtime-worker parachain::collation-generation: [Relaychain] collator returned no collation on collate para_id=2000
2023-09-18 15:38:13.591  WARN tokio-runtime-worker peerset: [Parachain] Report 12D3KooWGxGeJwpCbuMDezRLhkvHLKxDmtmWnhhYLwkccJhrDDV6: -2147483648 to -2147483648. Reason: Genesis mismatch. Banned, disconnecting.    
2023-09-18 15:38:14.571  INFO tokio-runtime-worker substrate: [Relaychain] 💤 Idle (5 peers), best: #11 (0xb623…77dd), finalized #8 (0x72a8…016c), ⬇ 3.2kiB/s ⬆ 2.8kiB/s   

Error from local simulation with test-parachain:

2023-09-18 15:57:42.036 DEBUG tokio-runtime-worker parachain::gossip-support: [foolish-spy-3933] New session detected session_index=1
2023-09-18 15:57:42.036 DEBUG tokio-runtime-worker parachain::approval-voting: [foolish-spy-3933] Insta-approving all candidates block_hash=0xb27e4e12f480da06a47a5586320c906f45f4e158a8e053808e1e0f1f147a3066
2023-09-18 15:57:42.037 DEBUG tokio-runtime-worker parachain::approval-voting: [foolish-spy-3933] Imported new block. block_number=11 block_hash=0xb27e4e12f480da06a47a5586320c906f45f4e158a8e053808e1e0f1f147a3066 num_candidates=0
2023-09-18 15:57:42.037 DEBUG tokio-runtime-worker parachain::approval-distribution: [foolish-spy-3933] Got new blocks [(0xb27e4e12f480da06a47a5586320c906f45f4e158a8e053808e1e0f1f147a3066, 11)]
2023-09-18 15:57:42.038 DEBUG tokio-runtime-worker parachain::gossip-support: [foolish-spy-3933] Determined past/present/future authorities authority_count=4
2023-09-18 15:57:42.038 DEBUG tokio-runtime-worker parachain::gossip-support: [foolish-spy-3933] Issuing a connection request num=0
2023-09-18 15:57:42.038 DEBUG tokio-runtime-worker parachain::gossip-support: [foolish-spy-3933] error=NotAValidator
2023-09-18 15:57:42.038 DEBUG tokio-runtime-worker parachain::validator-discovery: [foolish-spy-3933] New ConnectToValidators resolved request peer_set=Validation num_peers=0 removed=0
2023-09-18 15:57:42.038  INFO tokio-runtime-worker cumulus-collator: [collator01] Starting collation. relay_parent=0xb27e4e12f480da06a47a5586320c906f45f4e158a8e053808e1e0f1f147a3066 at=0x9e616f63e164be77aed193e5b24beb14a043778ac380b058b913c49cf3778103
2023-09-18 15:57:42.038  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [collator01] 🙌 Starting consensus session on top of parent 0x9e616f63e164be77aed193e5b24beb14a043778ac380b058b913c49cf3778103    
2023-09-18 15:57:42.357 ERROR tokio-runtime-worker runtime: [collator01] panicked at 'assertion failed: `(left == right)`
  left: `0x0000000000000000000000000000000000000000000000000000000000000000`,
 right: `0x8c2c8ac7c300a894f59c59af3ce369026a302785307308265afdb7bd9e31cb37`', /home/bparity/parity/polkadot-sdk/cumulus/pallets/parachain-system/src/lib.rs:1100:9    
2023-09-18 15:57:42.357  WARN tokio-runtime-worker sp_state_machine::overlayed_changes::changeset: [collator01] 1 storage transactions are left open by the runtime. Those will be rolled back.    
2023-09-18 15:57:42.357  WARN tokio-runtime-worker sp_state_machine::overlayed_changes::changeset: [collator01] 1 storage transactions are left open by the runtime. Those will be rolled back.    
2023-09-18 15:57:42.357  WARN tokio-runtime-worker basic-authorship: [collator01] ❗️ Inherent extrinsic returned unexpected error: Error at calling runtime api: Execution failed: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed
WASM backtrace:
error while executing at wasm backtrace:
    0: 0x116b65 - <unknown>!rust_begin_unwind
    1: 0x4f45 - <unknown>!core::panicking::panic_fmt::h2aa6e58b8ba5c6ef
    2: 0x52e3 - <unknown>!core::panicking::assert_failed_inner::h08436824881b8806
    3: 0x44c1a - <unknown>!core::panicking::assert_failed::hd8a03e74da50c0fa
    4: 0xc7163 - <unknown>!cumulus_pallet_parachain_system::<impl cumulus_pallet_parachain_system::pallet::Pallet<T>>::process_inbound_downward_messages::he665a52672f16e6d
    5: 0x3cc85 - <unknown>!frame_support::storage::transactional::with_transaction::h0d06e026a43a52c9
    6: 0x59209 - <unknown>!<cumulus_pallet_parachain_system::pallet::Call<T> as frame_support::traits::dispatch::UnfilteredDispatchable>::dispatch_bypass_filter::{{closure}}::h0d67211c80b28de7
    7: 0x5bc67 - <unknown>!environmental::local_key::LocalKey<T>::with::hc041448c98dd46ac
    8: 0xe969f - <unknown>!<cumulus_test_runtime::RuntimeCall as frame_support::traits::dispatch::UnfilteredDispatchable>::dispatch_bypass_filter::h3c488a64d740cdb1
    9: 0xe93ea - <unknown>!<cumulus_test_runtime::RuntimeCall as sp_runtime::traits::Dispatchable>::dispatch::hbad8087c6e5499f1
   10: 0xbf6cc - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::apply_extrinsic::hce2ea1778c5a2bb5
   11: 0x64ed7 - <unknown>!BlockBuilder_apply_extrinsic. Dropping.    
2023-09-18 15:57:42.357 ERROR tokio-runtime-worker runtime: [collator01] panicked at 'set_validation_data inherent needs to be present in every block!', /home/bparity/parity/polkadot-sdk/cumulus/pallets/parachain-system/src/lib.rs:248:13    
2023-09-18 15:57:42.357 ERROR tokio-runtime-worker cumulus-consensus-relay-chain: [collator01] Proposing failed. error=RuntimeApiError(Application(Execution(AbortedDueToTrap(MessageWithBacktrace { message: "wasm trap: wasm `unreachable` instruction executed", backtrace: Some(Backtrace { backtrace_string: "error while executing at wasm backtrace:\n    0: 0x116b65 - <unknown>!rust_begin_unwind\n    1: 0x4f45 - <unknown>!core::panicking::panic_fmt::h2aa6e58b8ba5c6ef\n    2: 0xc224e - <unknown>!<cumulus_pallet_parachain_system::pallet::Pallet<T> as frame_support::traits::hooks::OnFinalize<<<<T as frame_system::pallet::Config>::Block as sp_runtime::traits::HeaderProvider>::HeaderT as sp_runtime::traits::Header>::Number>>::on_finalize::h432beb35932997eb\n    3: 0x51c1b - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7) as frame_support::traits::hooks::OnFinalize<BlockNumber>>::on_finalize::hfa2e63d1bf2ed603\n    4: 0xbfc4e - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::idle_and_finalize_hook::hd0401bd6eae93a4d\n    5: 0x64fd7 - <unknown>!BlockBuilder_finalize_block" }) }))))
2023-09-18 15:57:42.357 DEBUG tokio-runtime-worker parachain::collation-generation: [foolish-spy-3933] collator returned no collation on collate para_id=2000

[claravanstaden]

We ran into the same issue while working on Snowfork/snowbridge#965. @alistair-singh

[bkontur]

We ran into the same issue while working on Snowfork/snowbridge#965. @alistair-singh

@claravanstaden @alistair-singh as a workaround, I commented out [[hrmp_channels]] section in zombienet and used force_open_hrmp_channel from relay chain with sudo like here.

[claravanstaden]

We ran into the same issue while working on Snowfork/snowbridge#965. @alistair-singh

@claravanstaden @alistair-singh as a workaround, I commented out [[hrmp_channels]] section in zombienet and used force_open_hrmp_channel from relay chain with sudo like here.

Great, thanks @bkontur! That worked. 🥳

[AlexD10S]

We ran into the same issue while working on Snowfork/snowbridge#965. @alistair-singh

@claravanstaden @alistair-singh as a workaround, I commented out [[hrmp_channels]] section in zombienet and used force_open_hrmp_channel from relay chain with sudo like here.

Running into the same issue.
Thanks for sharing this workaround

[bkchr]

@bkontur can we close this?

[f33r0]

@bkontur can we close this?

it was finally fixed?

[bkontur]

@bkontur can we close this?

it was finally fixed?

@f33r0 sorry, not yet, I just rebased that