Relay scenario failure - one of the node is out of sync

[dkijania]

Describe the bug
For given topology:

and Scenario in which every node (except relay nodes) is receiving some transaction.

One of the node is out of sync, and we can check that in logs are some grpc errors

09 05:37:24.528 INFO error processing an incoming header stream, reason: the parent block f15f1e0cfb9a7dc03f4cfd326f57efae90dc9dc3ac0280b517f12786e6e999a1 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.528 INFO error processing request, reason: the parent block 2071e80c7becbd6be7393894479f965018f83aeba990c82dfdcc1ee49321e328 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.528 INFO error processing request, reason: the parent block f15f1e0cfb9a7dc03f4cfd326f57efae90dc9dc3ac0280b517f12786e6e999a1 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.528 INFO error processing an incoming header stream, reason: the parent block a20593b7acb03ce7d46cddbec67dd218a95381d4f9ee72e3e03db95a07761eff of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.528 INFO error processing request, reason: the parent block a20593b7acb03ce7d46cddbec67dd218a95381d4f9ee72e3e03db95a07761eff of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.528 INFO receiving header stream from network, task: block
Oct 09 05:37:24.528 INFO receiving header stream from network, task: block
Oct 09 05:37:24.528 INFO error processing an incoming header stream, reason: the parent block c086e65e3e829015b384f4eaa61859e97889ebe71b36a7342e61ec127e1a2c76 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.528 INFO error processing request, reason: the parent block c086e65e3e829015b384f4eaa61859e97889ebe71b36a7342e61ec127e1a2c76 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.528 INFO error processing an incoming header stream, reason: the parent block 345762edf406f911d596790381250b3be4bb75c2cc64199d940fef08c77ccf9c of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.528 INFO error processing request, reason: the parent block 345762edf406f911d596790381250b3be4bb75c2cc64199d940fef08c77ccf9c of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.530 INFO receiving header stream from network, task: block
Oct 09 05:37:24.530 INFO receiving header stream from network, task: block
Oct 09 05:37:24.530 INFO error processing an incoming header stream, reason: the parent block 2071e80c7becbd6be7393894479f965018f83aeba990c82dfdcc1ee49321e328 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.531 INFO receiving header stream from network, task: block
Oct 09 05:37:24.531 INFO error processing request, reason: the parent block 2071e80c7becbd6be7393894479f965018f83aeba990c82dfdcc1ee49321e328 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.531 INFO error processing an incoming header stream, reason: the parent block f15f1e0cfb9a7dc03f4cfd326f57efae90dc9dc3ac0280b517f12786e6e999a1 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.531 INFO error processing request, reason: the parent block f15f1e0cfb9a7dc03f4cfd326f57efae90dc9dc3ac0280b517f12786e6e999a1 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.531 INFO error processing an incoming header stream, reason: the parent block 345762edf406f911d596790381250b3be4bb75c2cc64199d940fef08c77ccf9c of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.531 INFO error processing request, reason: the parent block 345762edf406f911d596790381250b3be4bb75c2cc64199d940fef08c77ccf9c of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.536 INFO receiving header stream from network, task: block
Oct 09 05:37:24.536 INFO error processing an incoming header stream, reason: the parent block fd084945679a6d1527289f1d239c94962851b81c38de4eec2c586b0b839000cb of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.536 INFO receiving header stream from network, task: block
Oct 09 05:37:24.536 INFO error processing request, reason: the parent block fd084945679a6d1527289f1d239c94962851b81c38de4eec2c586b0b839000cb of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.536 INFO receiving header stream from network, task: block
Oct 09 05:37:24.536 INFO error processing an incoming header stream, reason: the parent block a20593b7acb03ce7d46cddbec67dd218a95381d4f9ee72e3e03db95a07761eff of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.536 INFO error processing request, reason: the parent block a20593b7acb03ce7d46cddbec67dd218a95381d4f9ee72e3e03db95a07761eff of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.536 INFO receiving header stream from network, task: block
Oct 09 05:37:24.536 INFO error processing an incoming header stream, reason: the parent block 642c0359f6a83ae1228d7c89012ea04f56b0f6f31eb1e9f56439f0d231fb2e26 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.536 INFO error processing request, reason: the parent block 642c0359f6a83ae1228d7c89012ea04f56b0f6f31eb1e9f56439f0d231fb2e26 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.536 INFO error processing an incoming header stream, reason: the parent block 8c26938e35b2f5086db967309c2137647387035274f075abf56e139428a916d3 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.537 INFO error processing request, reason: the parent block 8c26938e35b2f5086db967309c2137647387035274f075abf56e139428a916d3 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.543 INFO receiving header stream from network, task: block
Oct 09 05:37:24.543 INFO receiving header stream from network, task: block
Oct 09 05:37:24.543 INFO error processing an incoming header stream, reason: the parent block 8c26938e35b2f5086db967309c2137647387035274f075abf56e139428a916d3 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.543 INFO error processing an incoming header stream, reason: the parent block c086e65e3e829015b384f4eaa61859e97889ebe71b36a7342e61ec127e1a2c76 of the first received block header is not found in storage, sub_task: chain_pull, task: block
Oct 09 05:37:24.543 INFO error processing request, reason: the parent block c086e65e3e829015b384f4eaa61859e97889ebe71b36a7342e61ec127e1a2c76 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.543 INFO error processing request, reason: the parent block 8c26938e35b2f5086db967309c2137647387035274f075abf56e139428a916d3 of the first received block header is not found in storage, request: PushHeaders, sub_task: server, task: network
Oct 09 05:37:24.662 INFO PushHeaders request failed, error: Error { code: FailedPrecondition, source: Status { code: FailedPrecondition, message: "system state does not permit the operation (the parent block 1e14ea290a21063b6f2df7b20953688b0d3e362bccf1bb79b4a6d61846b38b6e of the first received block header is not found in storage)", metadata: MetadataMap { headers: {"content-type": "application/grpc", "date": "Fri, 09 Oct 2020 05:37:24 GMT"} } } }, peer_address: /ip4/127.0.0.1/tcp/12040, peer: 127.0.0.1:12040, task: network
Oct 09 05:37:25.001 INFO Leader event started, event_remaining_time: 998ms 570us 7ns, event_end: 2020-10-09T05:37:26+00:00, event_start: 2020-10-09T05:37:25+00:00, event_date: 1.15, leader_id: 1, task: leadership
Oct 09 05:37:25.001 INFO receiving block from leadership service, date: 1.15, parent: 451812e2c8f4a373e493a97aa53f48a6adb9f0501e943f86737bcaaa65f10788, hash: ec4bdcbbaeace8b37fd4e5e41f1899912ecd5de5dac520a54498391dbbaf4168, task: block
Oct 09 05:37:25.005 INFO received block announcement from network, from_node_id: /ip4/127.0.0.1/tcp/49308, date: 1.15, parent: 451812e2c8f4a373e493a97aa53f48a6adb9f0501e943f86737bcaaa65f10788, hash: 6d1aeddb01014007b915ab374675985228593af8b986305c7ba1949dead139db, task: block
Oct 09 05:37:25.005 ERRO task process leadership block finished with error, error: Error(BlockHeaderVerificationFailed("Block proof is invalid: Invalid Vrf Proof value in ec4bdcbb-00000039-1.15, poolId: 40e95e4824648cb374154f74b0a840606c14bcf40fde724724f87fc071065588"), State { next_error: None, backtrace: InternalBacktrace { backtrace: Some(   0: error_chain::backtrace::imp::InternalBacktrace::new
   1: <error_chain::State as core::default::Default>::default
   2: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   3: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   4: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
   5: tokio::runtime::task::harness::Harness<T,S>::poll
   6: std::thread::local::LocalKey<T>::with
   7: tokio::runtime::thread_pool::worker::Context::run_task
   8: tokio::runtime::thread_pool::worker::Context::run
   9: tokio::macros::scoped_tls::ScopedKey<T>::set
  10: tokio::runtime::thread_pool::worker::run
  11: tokio::runtime::task::core::Core<T,S>::poll
  12: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
  13: tokio::runtime::task::harness::Harness<T,S>::poll
  14: tokio::runtime::blocking::pool::Inner::run
  15: tokio::runtime::context::enter
  16: std::sys_common::backtrace::__rust_begin_short_backtrace
  17: core::ops::function::FnOnce::call_once{{vtable.shim}}
  18: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/alloc/src/boxed.rs:1042:9
      <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/alloc/src/boxed.rs:1042:9
      std::sys::unix::thread::Thread::new::thread_start
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys/unix/thread.rs:87:17
  19: start_thread
  20: __clone
) } }), task: block
Oct 09 05:37:25.005 INFO receiving block stream from network, task: block

Mandatory Information

1. jcli --full-version output;
   jcli 0.10.0-dev (cf7b0e7a5+, release, windows [x86_64]) - [rustc 1.46.0-beta.1 (e51b714db 2020-07-15)]
2. jormungandr --full-version output;
   jormungandr 0.10.0-dev (cf7b0e7a5+, release, windows [x86_64]) - [rustc 1.46.0-beta.1 (e51b714db 2020-07-15)]

To Reproduce
Steps to reproduce the behavior:
cd testing\jormungandr-scenario-tests
cargo run -- --scenario relay --root-dir relay

Expected behavior
No errors in logs

Additional context
full log: leader 2.txt

[mzabaluev]

This is again incompatibility of legacy vs. current.

[dkijania]

Apologies, put wrong reproduction steps. Scenario is called 'relay'. I fixed description

[mzabaluev]

Likely underlying cause: #2719 (comment)