After upgrading one of Pop template's to polkadot-v1.10.0 I noticed some unexpected logs. Even though the parachain include blocks, emits the expected events from the executed extrinsics and so on.
The logs show the following:
2024-05-23 11:06:42 [Parachain] 🙌 Starting consensus session on top of parent 0xf03169103f7fa5281ad9dd9a994e5e8ffe948e1859e1acbfc16bbc888d259b17
2024-05-23 11:06:42 [Parachain] 🎁 Prepared block for proposing at 1 (2 ms) [hash: 0x08c6370abf09fe95bb9d8d946e1b80eb63d53be0ff7860c796bb55b185dc1f8e; parent_hash: 0xf031…9b17; extrinsics (2): [0x46e4…d5a6, 0xb93b…be31]
2024-05-23 11:06:42 [Parachain] 🔖 Pre-sealed block for proposal at 1. Hash now 0x0ce8e5cf3b8f90a31bf8c1fc059b9969e879c893590378d623941928030146d6, previously 0x08c6370abf09fe95bb9d8d946e1b80eb63d53be0ff7860c796bb55b185dc1f8e.
2024-05-23 11:06:42 [Parachain] ✨ Imported #1 (0x0ce8…46d6)
2024-05-23 11:06:42 [Parachain] PoV size { header: 0.216796875kb, extrinsics: 3.2431640625kb, storage_proof: 1.7265625kb }
2024-05-23 11:06:42 [Parachain] Compressed PoV size: 4.4853515625kb
2024-05-23 11:06:42 [Parachain] 🙌 Starting consensus session on top of parent 0x0ce8e5cf3b8f90a31bf8c1fc059b9969e879c893590378d623941928030146d6
2024-05-23 11:06:42 [Parachain] panicked at /home/alemart/.cargo/registry/src/index.crates.io-6f17d22bba15001f/cumulus-pallet-parachain-system-0.11.0/src/lib.rs:139:13:
Relay chain block number needs to strictly increase between Parachain blocks!
2024-05-23 11:06:42 [Parachain] 1 storage transactions are left open by the runtime. Those will be rolled back.
2024-05-23 11:06:42 [Parachain] 1 storage transactions are left open by the runtime. Those will be rolled back.
2024-05-23 11:06:42 [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: 0x3e0a8c - <unknown>!rust_begin_unwind
1: 0x10c29 - <unknown>!core::panicking::panic_fmt::h1549e5ec3a801cca
2: 0x2d1f28 - <unknown>!frame_support::storage::transactional::with_transaction::h7422fe844890f9e6
3: 0x2934fe - <unknown>!<cumulus_pallet_parachain_system::pallet::Call<T> as frame_support::traits::dispatch::UnfilteredDispatchable>::dispatch_bypass_filter::{{closure}}::h1e5f20a533a38241
4: 0x2a0931 - <unknown>!frame_support::dispatch_context::run_in_context::hb92f5b171018d329
5: 0x229e96 - <unknown>!<parachain_template_runtime::RuntimeCall as frame_support::traits::dispatch::UnfilteredDispatchable>::dispatch_bypass_filter::he4c84498b2d6727d
6: 0x22122c - <unknown>!<parachain_template_runtime::RuntimeCall as sp_runtime::traits::Dispatchable>::dispatch::hfe949263cd1fc032
7: 0x3aad0f - <unknown>!<sp_runtime::generic::checked_extrinsic::CheckedExtrinsic<AccountId,Call,Extra> as sp_runtime::traits::Applyable>::apply::he6f7ff7065c99010
8: 0x2b2109 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::apply_extrinsic::hd1cbeb8d7f91525b
9: 0x224ddb - <unknown>!BlockBuilder_apply_extrinsic. Dropping.
2024-05-23 11:06:42 [Parachain] panicked at /home/alemart/.cargo/registry/src/index.crates.io-6f17d22bba15001f/cumulus-pallet-parachain-system-0.11.0/src/lib.rs:266:18:
set_validation_data inherent needs to be present in every block!
2024-05-23 11:06:42 [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: 0x3e0a8c - <unknown>!rust_begin_unwind
1: 0x10c29 - <unknown>!core::panicking::panic_fmt::h1549e5ec3a801cca
2: 0x10b6f - <unknown>!core::option::expect_failed::h1123e1cae37cdc9c
3: 0x1faff5 - <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::h4c810fdbfd3c16cb
4: 0x284396 - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14,TupleElement15,TupleElement16) as frame_support::traits::hooks::OnFinalize<BlockNumber>>::on_finalize::hf185b1ca06e7e2e5
5: 0x2b34b5 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::finalize_block::hce3695f2cc028071
6: 0x224e95 - <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: 0x3e0a8c - <unknown>!rust_begin_unwind
1: 0x10c29 - <unknown>!core::panicking::panic_fmt::h1549e5ec3a801cca
2: 0x10b6f - <unknown>!core::option::expect_failed::h1123e1cae37cdc9c
3: 0x1faff5 - <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::h4c810fdbfd3c16cb
4: 0x284396 - <unknown>!<(TupleElement0,TupleElement1,TupleElement2,TupleElement3,TupleElement4,TupleElement5,TupleElement6,TupleElement7,TupleElement8,TupleElement9,TupleElement10,TupleElement11,TupleElement12,TupleElement13,TupleElement14,TupleElement15,TupleElement16) as frame_support::traits::hooks::OnFinalize<BlockNumber>>::on_finalize::hf185b1ca06e7e2e5
5: 0x2b34b5 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::finalize_block::hce3695f2cc028071
6: 0x224e95 - <unknown>!BlockBuilder_finalize_block }
2024-05-23 11:06:42 [Relaychain] 💤 Idle (3 peers), best: #11 (0xa9d4…e88c), finalized #8 (0x583a…41d0), ⬇ 2.1kiB/s ⬆ 2.9kiB/s
2024-05-23 11:06:42 [Parachain] 💤 Idle (0 peers), best: #1 (0x0ce8…46d6), finalized #0 (0xf031…9b17), ⬇ 0.2kiB/s ⬆ 0.2kiB/s
2024-05-23 11:06:47 [Relaychain] 💤 Idle (3 peers), best: #11 (0xa9d4…e88c), finalized #8 (0x583a…41d0), ⬇ 0.9kiB/s ⬆ 0.9kiB/s
2024-05-23 11:06:47 [Parachain] 💤 Idle (0 peers), best: #1 (0x0ce8…46d6), finalized #0 (0xf031…9b17), ⬇ 0.3kiB/s ⬆ 0.2kiB/s
I thought about maybe polkadot-v1.10.1 patch being something that could help with this, so I bumped the deps to polkadot-v1.11.0, which includes the patch. But I still can see the logs have the same panics.
Any comment is appreciated. I wonder if this is somehow related to other issues we have seen regarding async backing. As the logs are certainly similar, but not the same.
- How to instantly seal parachain block with async backing?
- https://github.com/paritytech/polkadot-sdk/issues/4466
Solution: It seems we had a regression in our template and just reverting the offending change was enough to get back to the expected behavior: https://github.com/r0gue-io/base-parachain/pull/25
Context
Changes I made to the template: https://github.com/r0gue-io/contracts-parachain/pull/5
Gist with the logs: https://gist.github.com/al3mart/e60bf22dac427658bcf9e2c7694a9cad
