Chain stop finalizing blocks

Have a problem in acala testnet now that chain stoped to finalize block， The node log is：

2020-02-28 10:34:56 Handler initialization process is too long with PeerId("QmSveKjM2cY2VNoZ6Lq7w71XmDzPSUFpZsoXrgtP3myn49")
2020-02-28 10:34:59 Idle (12 peers), best: #21962 (0xeec4…cf2c), finalized #15553 (0x8275…58ff), ⬇ 4.4kiB/s ⬆ 5.6kiB/s

====================

Version: 0.3.0-f887701-x86_64-linux-gnu

   0: sp_panic_handler::set::{{closure}}
   1: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:475
   2: std::panicking::begin_panic
   3: frame_executive::Executive<System,Block,Context,UnsignedValidator,AllModules>::execute_block
   4: <acala_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<acala_runtime::Runtime> as sp_runtime::traits::StaticLookup>::Source,acala_runtime::Call,sp_runtime::MultiSignature,(frame_system::CheckVersion<acala_runtime::Runtime>, frame_system::CheckGenesis<acala_runtime::Runtime>, frame_system::CheckEra<acala_runtime::Runtime>, frame_system::CheckNonce<acala_runtime::Runtime>, frame_system::CheckWeight<acala_runtime::Runtime>, orml_oracle::CheckOperator<acala_runtime::Runtime>, module_accounts::ChargeTransactionPayment<acala_runtime::Runtime>, module_cdp_engine::AutomaticLiquidationValidation<acala_runtime::Runtime>)>>>>::execute_block
   5: sp_api::runtime_decl_for_Core::execute_block_native_call_generator::{{closure}}
   6: std::panicking::try::do_call
   7: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:78
   8: std::thread::local::LocalKey<T>::with
   9: std::thread::local::LocalKey<T>::with
  10: sp_state_machine::StateMachine<B,H,N,Exec>::execute_aux
  11: sp_state_machine::StateMachine<B,H,N,Exec>::execute_using_consensus_failure_handler
  12: <sc_client::call_executor::LocalCallExecutor<B,E> as sc_client_api::call_executor::CallExecutor<Block>>::contextual_call
  13: <sc_client::client::Client<B,E,Block,RA> as sp_api::CallApiAt<Block>>::call_api_at
  14: sp_api::Core::execute_block
  15: <&sc_client::client::Client<B,E,Block,RA> as sp_consensus::block_import::BlockImport<Block>>::import_block
  16: <sc_finality_grandpa::import::GrandpaBlockImport<B,E,Block,RA,SC> as sp_consensus::block_import::BlockImport<Block>>::import_block
  17: <sc_consensus_babe::BabeBlockImport<Block,Client,Inner> as sp_consensus::block_import::BlockImport<Block>>::import_block
  18: sp_consensus::import_queue::import_single_block
  19: <futures_util::future::poll_fn::PollFn<F> as core::future::future::Future>::poll
  20: futures_util::future::future::chain::Chain<Fut1,Fut2,Data>::poll
  21: <futures_util::future::poll_fn::PollFn<F> as core::future::future::Future>::poll
  22: futures_executor::thread_pool::PoolState::work
  23: std::sys_common::backtrace::__rust_begin_short_backtrace
  24: std::panicking::try::do_call
  25: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:78
  26: core::ops::function::FnOnce::call_once{{vtable.shim}}
  27: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/5e1a799842ba6ed4a57e91f7ab9435947482f7d8/src/liballoc/boxed.rs:1022
  28: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/5e1a799842ba6ed4a57e91f7ab9435947482f7d8/src/liballoc/boxed.rs:1022
      std::sys_common::thread::start_thread
             at src/libstd/sys_common/thread.rs:13
      std::sys::unix::thread::Thread::new::thread_start
             at src/libstd/sys/unix/thread.rs:80
  29: start_thread
  30: __clone

Thread 'import-queue-worker-0' panicked at 'Transaction has a bad signature', /root/.cargo/git/checkouts/substrate-7e08433d4c370a21/41bb219/frame/executive/src/lib.rs:272

This is a bug. Please report it at:

    https://github.com/AcalaNetwork/Acala/issues

2020-02-28 10:34:59 Block prepare storage changes error:
Execution(RuntimePanicked("Transaction has a bad signature"))
2020-02-28 10:35:04 Idle (12 peers), best: #21962 (0xeec4…cf2c), finalized #15553 (0x8275…58ff), ⬇ 4.9kiB/s ⬆ 4.9kiB/s
2020-02-28 10:35:08 offchain worker start at block: 21962 execute automatic liquidation for collateral: CurrencyId::DOT

We think this problem may be caused by an unsigned transaction submitted by offchain worker.

As we have not yet designed a reward mechanism of running offchain worker, there's no Authority，and no signature verification by Authority for unsigned tx : https://github.com/AcalaNetwork/Acala/blob/d6212fe82c44aa7113ec1bdda9a5c357194b1e09/modules/cdp_engine/src/lib.rs#L355-L360

And the validation for submitted tx we use SingedExtension instead of deprecated unsigned::ValidateUnsigned : https://github.com/AcalaNetwork/Acala/blob/d6212fe82c44aa7113ec1bdda9a5c357194b1e09/modules/cdp_engine/src/lib.rs#L733-L770

There's no InvalidTransaction::BadProof will be throughed by above code.

Is the lack of sign verification by Authority or the incorrect validation for unsigned tx cause this problem? or something else

AcalaNetwork / Acala

Chain stop finalizing blocks #131