Tokio-runtime-worker panicked "Externalities not allowed to fail"

[SimonKraus]

Hey brains!

My main collator just went into a crash-loop with given error:

May 06 17:39:40 moonbeam moonbeam[1188421]: ====================
May 06 17:39:40 moonbeam moonbeam[1188421]: Version: 0.31.1-b71106f4510
May 06 17:39:40 moonbeam moonbeam[1188421]:    0: sp_panic_handler::set::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:    1: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/alloc/src/boxed.rs:2002:9
May 06 17:39:40 moonbeam moonbeam[1188421]:       std::panicking::rust_panic_with_hook
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:692:13
May 06 17:39:40 moonbeam moonbeam[1188421]:    2: std::panicking::begin_panic_handler::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:579:13
May 06 17:39:40 moonbeam moonbeam[1188421]:    3: std::sys_common::backtrace::__rust_end_short_backtrace
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/sys_common/backtrace.rs:137:18
May 06 17:39:40 moonbeam moonbeam[1188421]:    4: rust_begin_unwind
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:575:5
May 06 17:39:40 moonbeam moonbeam[1188421]:    5: core::panicking::panic_fmt
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/panicking.rs:64:14
May 06 17:39:40 moonbeam moonbeam[1188421]:    6: core::result::unwrap_failed
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/result.rs:1790:5
May 06 17:39:40 moonbeam moonbeam[1188421]:    7: <sp_state_machine::ext::Ext<H,B> as sp_externalities::Externalities>::storage
May 06 17:39:40 moonbeam moonbeam[1188421]:    8: sp_io::storage::get_version_1
May 06 17:39:40 moonbeam moonbeam[1188421]:    9: sp_io::storage::ExtStorageGetVersion1::call
May 06 17:39:40 moonbeam moonbeam[1188421]:   10: <F as wasmtime::func::IntoFunc<T,(wasmtime::func::Caller<T>,A1),R>>::into_func::wasm_to_host_shim
May 06 17:39:40 moonbeam moonbeam[1188421]:   11: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   12: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   13: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   14: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   15: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   16: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   17: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   18: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   19: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   20: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   21: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   22: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   23: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   24: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   25: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   26: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   27: <unknown>
May 06 17:39:40 moonbeam moonbeam[1188421]:   28: wasmtime_runtime::traphandlers::catch_traps::call_closure
May 06 17:39:40 moonbeam moonbeam[1188421]:   29: wasmtime_setjmp
May 06 17:39:40 moonbeam moonbeam[1188421]:   30: sc_executor_wasmtime::runtime::perform_call
May 06 17:39:40 moonbeam moonbeam[1188421]:   31: <sc_executor_wasmtime::runtime::WasmtimeInstance as sc_executor_common::wasm_runtime::WasmInstance>::call_with_allocation_stats
May 06 17:39:40 moonbeam moonbeam[1188421]:   32: sc_executor_common::wasm_runtime::WasmInstance::call_export
May 06 17:39:40 moonbeam moonbeam[1188421]:   33: sc_executor::native_executor::WasmExecutor<H>::with_instance::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   34: <sc_executor::native_executor::NativeElseWasmExecutor<D> as sp_core::traits::CodeExecutor>::call
May 06 17:39:40 moonbeam moonbeam[1188421]:   35: sp_state_machine::execution::StateMachine<B,H,Exec>::execute_aux
May 06 17:39:40 moonbeam moonbeam[1188421]:   36: sp_state_machine::execution::StateMachine<B,H,Exec>::execute_using_consensus_failure_handler
May 06 17:39:40 moonbeam moonbeam[1188421]:   37: <sc_service::client::client::Client<B,E,Block,RA> as sp_api::CallApiAt<Block>>::call_api_at
May 06 17:39:40 moonbeam moonbeam[1188421]:   38: <moonbeam_runtime::RuntimeApiImpl<__SR_API_BLOCK__,RuntimeApiImplCall> as sp_api::Core<__SR_API_BLOCK__>>::__runtime_api_internal_call_api_at
May 06 17:39:40 moonbeam moonbeam[1188421]:   39: <&sc_service::client::client::Client<B,E,Block,RA> as sc_consensus::block_import::BlockImport<Block>>::import_block::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   40: <alloc::sync::Arc<T> as sc_consensus::block_import::BlockImport<B>>::import_block::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   41: <fc_consensus::FrontierBlockImport<B,I,C> as sc_consensus::block_import::BlockImport<B>>::import_block::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   42: <nimbus_consensus::import_queue::NimbusBlockImport<I> as sc_consensus::block_import::BlockImport<Block>>::import_block::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   43: <alloc::boxed::Box<dyn sc_consensus::block_import::BlockImport<B>+Error = sp_consensus::error::Error+Transaction = Transaction+core::marker::Sync+core::marker::Send> as sc_consensus::block_import::BlockImport<B>>::import_block::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   44: sc_consensus::import_queue::basic_queue::BlockImportWorker<B>::new::{{closure}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   45: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
May 06 17:39:40 moonbeam moonbeam[1188421]:   46: <tracing_futures::Instrumented<T> as core::future::future::Future>::poll
May 06 17:39:40 moonbeam moonbeam[1188421]:   47: tokio::runtime::task::raw::poll
May 06 17:39:40 moonbeam moonbeam[1188421]:   48: std::sys_common::backtrace::__rust_begin_short_backtrace
May 06 17:39:40 moonbeam moonbeam[1188421]:   49: core::ops::function::FnOnce::call_once{{vtable.shim}}
May 06 17:39:40 moonbeam moonbeam[1188421]:   50: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/alloc/src/boxed.rs:1988:9
May 06 17:39:40 moonbeam moonbeam[1188421]:       <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/alloc/src/boxed.rs:1988:9
May 06 17:39:40 moonbeam moonbeam[1188421]:       std::sys::unix::thread::Thread::new::thread_start
May 06 17:39:40 moonbeam moonbeam[1188421]:              at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/sys/unix/thread.rs:108:17
May 06 17:39:40 moonbeam moonbeam[1188421]:   51: start_thread
May 06 17:39:40 moonbeam moonbeam[1188421]:   52: clone
May 06 17:39:40 moonbeam moonbeam[1188421]: Thread 'tokio-runtime-worker' panicked at 'Externalities not allowed to fail within runtime: "Trie lookup error: Database missing expected key: 0x3f98c55d9f62adf74703eb8e9fed939a1ea94981ea10cc29fb35a90bc3eb7e7e"', /home/gh-actions/.cargo/git/checkouts/substrate-189071a041b0d328/3323a76/primitives/state-machine/src/ext.rs:189
May 06 17:39:40 moonbeam moonbeam[1188421]: This is a bug. Please report it at:
May 06 17:39:40 moonbeam moonbeam[1188421]:         https://github.com/PureStake/moonbeam/issues/new

I left the node in that state for now - in case you need more logs or sth else just let me know.

[perltk45]

Just in case the time and exact slot are helpful, here is the very first panic event for Simon's node:

May 6 14:32:46 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:46 [🌗] 💤 Idle (27 peers), best: #3504325 (0x1427…1e4f), finalized #3504324 (0xc304…93fd), ⬇ 6.7kiB/s ⬆ 7.2kiB/s
May 6 14:32:47 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:47 [Relaychain] 💤 Idle (500 peers), best: #15404323 (0x7950…4229), finalized #15404320 (0xc225…1384), ⬇ 1.2MiB/s ⬆ 786.0kiB/s
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [Relaychain] ✨ Imported #15404324 (0x6e2e…4ac7)
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [🌗] Starting collation. relay_parent=0x6e2ed0fd9af286367b6ee5a202bcbf78c32ebea1c27f19a64f4823764bca4ac7 at=0xa393bd29942a679b967638f39ef1096e58aea03ca8d9b324a5bef15ba0cfb823
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [🌗] 🔮 Skipping candidate production because we are not eligible for slot 15404324
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [Relaychain] ♻️ Reorg on #15404324,0x6e2e…4ac7 to #15404324,0x8d9b…4a47, common ancestor #15404323,0x7950…4229
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [Relaychain] ✨ Imported #15404324 (0x8d9b…4a47)
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [🌗] Starting collation. relay_parent=0x8d9bc4c524fb99f37eb952e8d023e7b7bcc3a2922cdb383133af6a65eae44a47 at=0xa393bd29942a679b967638f39ef1096e58aea03ca8d9b324a5bef15ba0cfb823
May 6 14:32:48 Crifferent_Prod moonbeam[917707]: 2023-05-06 14:32:48 [🌗] 🔮 Skipping candidate production because we are not eligible for slot 15404324
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: ====================
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: Version: 0.31.1-b71106f4510
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 0: sp_panic_handler::set::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 1: <alloc::boxed::Box<F,A> as core::ops::function::Fn>::call
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/alloc/src/boxed.rs:2002:9
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: std::panicking::rust_panic_with_hook
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:692:13
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 2: std::panicking::begin_panic_handler::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:579:13
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 3: std::sys_common::backtrace::__rust_end_short_backtrace
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/sys_common/backtrace.rs:137:18
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 4: rust_begin_unwind
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:575:5
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 5: core::panicking::panic_fmt
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/panicking.rs:64:14
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 6: core::result::unwrap_failed
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/result.rs:1790:5
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 7: <sp_state_machine::ext::Ext<H,B> as sp_externalities::Externalities>::storage
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 8: sp_io::storage::get_version_1
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 9: sp_io::storage::ExtStorageGetVersion1::call
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 10: <F as wasmtime::func::IntoFunc<T,(wasmtime::func::Caller,A1),R>>::into_func::wasm_to_host_shim
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 11:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 12:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 13:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 14:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 15:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 16:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 17:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 18:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 19:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 20:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 21:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 22:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 23:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 24:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 25:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 26:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 27:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 28: wasmtime_runtime::traphandlers::catch_traps::call_closure
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 29: wasmtime_setjmp
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 30: sc_executor_wasmtime::runtime::perform_call
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 31: <sc_executor_wasmtime::runtime::WasmtimeInstance as sc_executor_common::wasm_runtime::WasmInstance>::call_with_allocation_stats
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 32: sc_executor_common::wasm_runtime::WasmInstance::call_export
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 33: sc_executor::native_executor::WasmExecutor::with_instance::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 34: <sc_executor::native_executor::NativeElseWasmExecutor as sp_core::traits::CodeExecutor>::call
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 35: sp_state_machine::execution::StateMachine<B,H,Exec>::execute_aux
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 36: sp_state_machine::execution::StateMachine<B,H,Exec>::execute_using_consensus_failure_handler
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 37: <sc_service::client::client::Client<B,E,Block,RA> as sp_api::CallApiAt>::call_api_at
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 38: <moonbeam_runtime::RuntimeApiImpl<SR_API_BLOCK,RuntimeApiImplCall> as sp_api::Core<SR_API_BLOCK>>::__runtime_api_internal_call_api_at
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 39: <&sc_service::client::client::Client<B,E,Block,RA> as sc_consensus::block_import::BlockImport>::import_block::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 40: <alloc::sync::Arc as sc_consensus::block_import::BlockImport>::import_block::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 41: <fc_consensus::FrontierBlockImport<B,I,C> as sc_consensus::block_import::BlockImport>::import_block::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 42: <nimbus_consensus::import_queue::NimbusBlockImport as sc_consensus::block_import::BlockImport>::import_block::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 43: <alloc::boxed::Box<dyn sc_consensus::block_import::BlockImport+Error = sp_consensus::error::Error+Transaction = Transaction+core::marker::Sync+core::marker::Send> as sc_consensus::block_import::BlockImport>::import_block::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 44: sc_consensus::import_queue::basic_queue::BlockImportWorker::new::{{closure}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 45: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 46: <tracing_futures::Instrumented as core::future::future::Future>::poll
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 47: tokio::runtime::task::raw::poll
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 48: std::sys_common::backtrace::__rust_begin_short_backtrace
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 49: core::ops::function::FnOnce::call_once{{vtable.shim}}
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 50: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce>::call_once
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/alloc/src/boxed.rs:1988:9
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce>::call_once
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/alloc/src/boxed.rs:1988:9
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: std::sys::unix::thread::Thread::new::thread_start
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: at rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/sys/unix/thread.rs:108:17
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 51: start_thread
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: 52: clone
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: Thread 'tokio-runtime-worker' panicked at 'Externalities not allowed to fail within runtime: "Trie lookup error: Database missing expected key: 0x3f98c55d9f62adf74703eb8e9fed939a1ea94981ea10cc29fb35a90bc3eb7e7e"', /home/gh-actions/.cargo/git/checkouts/substrate-189071a041b0d328/3323a76/primitives/state-machine/src/ext.rs:189
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: This is a bug. Please report it at:
May 6 14:32:49 Crifferent_Prod moonbeam[917707]: #11https://github.com/PureStake/moonbeam/issues/new

[crystalin]

Thank you,

Can you provide the parameters you use? specially the database

[SimonKraus]

For sure @crystalin !!

ExecStart=/var/lib/moonbeam-data/moonbeam \
     --validator \
     --port 30333 \
     --rpc-port 9933 \
     --ws-port 9944 \
     --execution wasm \
     --wasm-execution compiled \
     --db-cache 32000 \
     --database paritydb \
     --base-path /var/lib/moonbeam-data \
     --chain moonbeam \
     --name "Sik | crifferent(dot)de" \
     -- \
     --port 30334 \
     --rpc-port 9934 \
     --ws-port 9945 \
     --in-peers 250 \
     --out-peers 250 \
     --database paritydb \
     --blocks-pruning 100 \
     --state-pruning 100 \
     --name="Sik | crifferent(dot)de"

[SimonKraus]

For the hardware specs:
It's an 2386G with 64gig RAM, NVME and 1gig dedicated uplink.