Panic: Storage root must match that calculated when changing era

[mikiquantum]

We are running a POS chain based on the version 2.0-alpha1 with:

• https://github.com/centrifuge/centrifuge-chain
• 2 validators
• 2 sentry nodes
• Blocks per era at 14400

From a clean start the chain works fine until the block number 14400 is reached (era change), we reproduced it 3 times (after cleaning up DB and start from genesis) always panicking at the same block on the sentry node side.
Validators stop producing blocks.

Sentry nodes panic log:

Mar 10 22:42:22 publicnode0-0 centrifuge-chain[4044]: 2020-03-10 22:42:22.812 main-tokio- INFO substrate  Idle (6 peers), best: #14399 (0x863b…aedc), finalized #14397 (0x4f8f…d7ea), ⬇ 4.5kiB/s ⬆ 3.3kiB/s
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: 2020-03-10 22:42:24.478 import-queue-worker-0 DEBUG babe  We have 2 logs in this header
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: 2020-03-10 22:42:24.478 import-queue-worker-0 DEBUG babe  Verifying Secondary block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: Hash: given=b91c6eb9a25ad5298b03cb09d73e8217838d8c6e9fdad169aef9db19e966b751, expected=37cbda3d703951315f8726596dd4a1baa48a77d2a2f74208fa541ceb3663b054
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: ====================
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: Version: 2.0.0-6561553-x86_64-linux-gnu
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    0: sp_panic_handler::set::{{closure}}
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    1: std::panicking::rust_panic_with_hook
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at src/libstd/panicking.rs:474
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    2: std::panicking::begin_panic
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    3: frame_executive::Executive<System,Block,Context,UnsignedValidator,AllModules>::execute_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    4: <centrifuge_chain_runtime::Runtime as sp_api::runtime_decl_for_Core::Core<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32,sp_runtime::traits::BlakeTwo256>,sp_runtime::generic::unchecked_extrinsic::UncheckedExtrinsic<<pallet_indices::Module<centrifuge_chain_runtime::Runtime> as sp_runtime::traits::StaticLookup>::Source,centrifuge_chain_runtime::Call,sp_runtime::MultiSignature,(frame_system::CheckVersion<centrifuge_chain_runtime::Runtime>, frame_system::CheckGenesis<centrifuge_chain_runtime::Runtime>, frame_system::CheckEra<centrifuge_chain_runtime::Runtime>, frame_system::CheckNonce<centrifuge_chain_runtime::Runtime>, frame_system::CheckWeight<centrifuge_chain_runtime::Runtime>, pallet_transaction_payment::ChargeTransactionPayment<centrifuge_chain_runtime::Runtime>)>>>>::execute_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    5: sp_api::runtime_decl_for_Core::execute_block_native_call_generator::{{closure}}
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    6: std::panicking::try::do_call
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    7: __rust_maybe_catch_panic
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at src/libpanic_unwind/lib.rs:86
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    8: std::thread::local::LocalKey<T>::with
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:    9: std::thread::local::LocalKey<T>::with
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   10: sp_state_machine::StateMachine<B,H,N,Exec>::execute_aux
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   11: <sc_client::call_executor::LocalCallExecutor<B,E> as sc_client_api::call_executor::CallExecutor<Block>>::contextual_call
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   12: <sc_client::client::Client<B,E,Block,RA> as sp_api::CallApiAt<Block>>::call_api_at
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   13: sp_api::Core::execute_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   14: <&sc_client::client::Client<B,E,Block,RA> as sp_consensus::block_import::BlockImport<Block>>::import_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   15: <sc_finality_grandpa::import::GrandpaBlockImport<B,E,Block,RA,SC> as sp_consensus::block_import::BlockImport<Block>>::import_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   16: <sc_consensus_babe::BabeBlockImport<Block,Client,Inner> as sp_consensus::block_import::BlockImport<Block>>::import_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   17: sp_consensus::import_queue::import_single_block
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   18: <futures_util::future::poll_fn::PollFn<F> as core::future::future::Future>::poll
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   19: futures_util::future::future::chain::Chain<Fut1,Fut2,Data>::poll
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   20: <futures_util::future::poll_fn::PollFn<F> as core::future::future::Future>::poll
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   21: futures_executor::thread_pool::PoolState::work
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   22: std::sys_common::backtrace::__rust_begin_short_backtrace
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   23: std::panicking::try::do_call
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   24: __rust_maybe_catch_panic
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at src/libpanic_unwind/lib.rs:86
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   25: core::ops::function::FnOnce::call_once{{vtable.shim}}
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   26: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at rustc/5e7af4669f80e5f682141f050193ab679afdb4b1/src/liballoc/boxed.rs:1017
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   27: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at rustc/5e7af4669f80e5f682141f050193ab679afdb4b1/src/liballoc/boxed.rs:1017
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:       std::sys_common::thread::start_thread
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at src/libstd/sys_common/thread.rs:13
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:       std::sys::unix::thread::Thread::new::thread_start
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:              at src/libstd/sys/unix/thread.rs:80
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   28: start_thread
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:   29: __clone
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: Thread 'import-queue-worker-0' panicked at 'Storage root must match that calculated.', <::std::macros::panic macros>:2
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: This is a bug. Please report it at:
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]:         centrifuge.io
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: 2020-03-10 22:42:24.535 import-queue-worker-0 WARN sc_client::client  Block prepare storage changes error:
Mar 10 22:42:24 publicnode0-0 centrifuge-chain[4044]: Execution(RuntimePanicked("Storage root must match that calculated."))
Mar 10 22:42:25 publicnode0-0 centrifuge-chain[4044]: 2020-03-10 22:42:25.150 import-queue-worker-0 DEBUG babe  We have 2 logs in this header
Mar 10 22:42:25 publicnode0-0 centrifuge-chain[4044]: 2020-03-10 22:42:25.151 import-queue-worker-0 DEBUG babe  Verifying Secondary block
Mar 10 22:42:25 publicnode0-0 centrifuge-chain[4044]: Hash: given=b91c6eb9a25ad5298b03cb09d73e8217838d8c6e9fdad169aef9db19e966b751, expected=37cbda3d703951315f8726596dd4a1baa48a77d2a2f74208fa541ceb3663b054
Mar 10 22:42:25 publicnode0-0 centrifuge-chain[4044]: ====================

Validator logs around same time:

Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.002 main-tokio- DEBUG babe  Claimed slot 263980025
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.002 main-tokio- DEBUG babe  Starting authorship at slot 263980025; timestamp = 1583880150000
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.002 main-tokio- INFO sc_basic_authorship::basic_authorship  Starting consensus session on top of parent 0x863b17af1d7af480d894bf19da39eff9722dc05c298cf06c2d5852a8be88aedc
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.002 main-tokio- DEBUG babe  No block for 1 slots. Applying 2^(1/2) lenience
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.129 tokio-blocking-driver INFO sc_basic_authorship::basic_authorship  Prepared block for proposing at 14400 [hash: 0xd1ebc2c7b5f93850c394abbe354aaafac61d3d973c94bea10fcb5fedbf8a8462; parent_hash: 0x863b…aedc; extrinsics (2): [0x8670…8e46, 0x017d…703d]]
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.129 main-tokio- INFO sc_consensus_slots  Pre-sealed block for proposal at 14400. Hash now 0x6f25ed83963ecb34609ccc2acb925b55acbb07e70a7f109914e305cd0d3e39e1, previously 0xd1ebc2c7b5f93850c394abbe354aaafac61d3d973c94bea10fcb5fedbf8a8462.
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.129 main-tokio- INFO babe  New epoch 4 launching at block 0x6f25…39e1 (block slot 263980025 >= start slot 263980025).
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.129 main-tokio- INFO babe  Next epoch starts at slot 263983625
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.130 main-tokio- INFO substrate  Imported #14400 (0x6f25…39e1)
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.131 main-tokio- TRACE sync  Updating peer QmZhtuLG148jnWier4AkhhzCPwqRAL46Lwy9t38Q1dbecT info, ours=14400, common=14399->14399, their best=14399
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.131 main-tokio- TRACE sync  Updating peer QmYcu44oJVFL6rRR56cZYqeK33aGshDLm3Gc2921QftqHg info, ours=14400, common=14396->14396, their best=14396
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.131 main-tokio- TRACE sync  Announcing block 0x6f25ed83963ecb34609ccc2acb925b55acbb07e70a7f109914e305cd0d3e39e1 to QmZhtuLG148jnWier4AkhhzCPwqRAL46Lwy9t38Q1dbecT
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.131 main-tokio- TRACE sync  Announcing block 0x6f25ed83963ecb34609ccc2acb925b55acbb07e70a7f109914e305cd0d3e39e1 to QmYcu44oJVFL6rRR56cZYqeK33aGshDLm3Gc2921QftqHg
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.131 main-tokio- TRACE afg  Polling round 63533, state = State { prevote_ghost: None, finalized: None, estimate: None, completable: false }, step = Some(Start)
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.132 main-tokio- DEBUG afg  Last round estimate has been finalized, not sending primary block hint for round 63533
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.175 main-tokio- TRACE sync  BlockRequest 8110 from QmZhtuLG148jnWier4AkhhzCPwqRAL46Lwy9t38Q1dbecT: from Number(14400) to None max Some(1)
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.175 main-tokio- TRACE sync  Sending BlockResponse with 1 blocks
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.267 main-tokio- TRACE sync  BlockRequest 8111 from QmZhtuLG148jnWier4AkhhzCPwqRAL46Lwy9t38Q1dbecT: from Number(14399) to None max Some(1)
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.268 main-tokio- TRACE sync  Sending BlockResponse with 1 blocks
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.268 main-tokio- TRACE sync  BlockRequest 8112 from QmZhtuLG148jnWier4AkhhzCPwqRAL46Lwy9t38Q1dbecT: from Number(14399) to None max Some(1)
Mar 10 22:42:30 validator0-0 centrifuge-chain[4243]: 2020-03-10 22:42:30.268 main-tokio- TRACE sync  Sending BlockResponse with 1 blocks

Any help would be much appreciated!