Jormungandr: 0.7.1 Frequent Warning - WARN blockchain is not moving up....

Created on 22 Nov 2019  路  9Comments  路  Source: input-output-hk/jormungandr

Describe the bug
After upgrading my nightly test net node to 0.7.1, I've continued to get this warning frequently. The node just seems to stall and will stay at the same block date until you restart it. After a restart, it jumps to a newer block date then stalls again. Many have had to restart their nodes multiple times until the node has synced. Some have reported better luck starting with an up to date db, rather than deleting their storage.

Here is an example from the log:

Nov 22 21:00:27.363 WARN blockchain is not moving up, the last block was 178364 seconds ago, task: blockchain_stuck_notifier

Mandatory Information

  1. jcli --full-version output;
    jcli 0.7.1 (HEAD-c57466d, release, linux [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]
  1. jormungandr --full-version output;
    jormungandr 0.7.1 (HEAD-c57466d, release, linux [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]

To Reproduce
Start and 0.7.1 node and connect it to the current nightly test network.

bug
Source
picture Linicks
👍1

Most helpful comment

I have this same issue. After bootstrap my Jormungandr stalled at Epoch 5 while climbing to Epoch 45. It also stalled at Epochs 8, 11, 24 and 42 requiring a restart every 15 minutes until it reached the current epoch which was 45 at the time.

I am also running 0.7.1 on the nightly.

picture rickymac68 on 23 Nov 2019
👍2

All 9 comments

Hmmm, can you tell how many blocks are retrieved on each restart. Is it smth like 2000 blocks?

rinor picture rinor on 23 Nov 2019

I have this same issue. After bootstrap my Jormungandr stalled at Epoch 5 while climbing to Epoch 45. It also stalled at Epochs 8, 11, 24 and 42 requiring a restart every 15 minutes until it reached the current epoch which was 45 at the time.

I am also running 0.7.1 on the nightly.

rickymac68 picture rickymac68 on 23 Nov 2019
👍2

This issue appears to be causing crashes now:

Nov 23 11:25:30.616 WARN blockchain is not moving up, the last block was 687993 seconds ago, task: blockchain_stuck_notifier
Nov 23 11:25:30.619 INFO connecting to peer, node_id: 8adfd28d4ecc8f55abdd1f3f93de155d05ab5d2b3b1bc2da, peer_addr: 40.67.162.249:3001, task: network
Nov 23 11:25:32.721 ERRO Error while accepting connection on 192.168.1.116:3100: Os { code: 22, kind: InvalidInput, message: "Invalid argument" }, task: network
Nov 23 11:25:32.723 INFO switching to new candidate branch, task: block
thread 'network6' panicked at 'Box', jormungandr/src/main.rs:240:30
stack backtrace:
Nov 23 11:25:32.724 ERRO Cannot process block event, reason: Cannot propagate block to network, task: block
Nov 23 11:25:32.724 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 04ff718358dbed1899f53e00021a943187d04e3382811845, peer_addr: 3.124.247.6:3000, task: network
Nov 23 11:25:32.724 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 117a189c54e1b35594334daa80409da25435ea4058fabe76, peer_addr: 52.8.248.82:3000, task: network
Nov 23 11:25:32.724 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 62c9ca2f26f7aadbe570c3fb76844372c5d7296b05e285b5, peer_addr: 3.124.88.217:3000, task: network
Nov 23 11:25:32.724 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 666c2858fbf542e5860f1afdeb014efa49ded8552d462aa7, peer_addr: 18.195.141.52:3000, task: network
Nov 23 11:25:32.724 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: e4fda5a674f0838b64cacf6d22bbae38594d7903aba2226f, peer_addr: 13.230.137.72:3000, task: network
Nov 23 11:25:32.725 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 74a9949645cdb06d0358da127e897cbb0a7b92a1d9db8e70, peer_addr: 18.196.168.220:3000, task: network
Nov 23 11:25:32.725 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 24bad5871f2da23ee0701c030277609d6ee767c68e091a19, peer_addr: 101.81.58.246:3200, task: network
Nov 23 11:25:32.725 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: acaba9c8c4d8ca68ac8bad5fe9bd3a1ae8de13816f40697c, peer_addr: 184.169.162.15:3000, task: network
Nov 23 11:25:32.725 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 27e6f018dd39a1c399073772140e349ab1ae4b4f24a1a0d8, peer_addr: 52.69.92.151:3000, task: network
Nov 23 11:25:32.725 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: bcfc82c9660e28d4dcb4d1c8a390350b18d04496c2ac8474, peer_addr: 13.56.87.134:3000, task: network
Nov 23 11:25:32.725 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 1a7fbd7723ccf012bab02f0a57d01037ffa9f6df7270ee0b, peer_addr: 82.255.117.36:3007, task: network
Nov 23 11:25:32.726 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: f917cb2b2af013274e54e63ccdc10294ff8096d5fd229b7f, peer_addr: 18.176.204.240:3000, task: network
Nov 23 11:25:32.726 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 408581c4a3358f808ad43b53193ebc4e13fa6b76185c205d, peer_addr: 98.127.116.122:7071, task: network
Nov 23 11:25:32.726 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 9c9af917412ee2147e8ec984fdae3166be287d3e85f6ebbd, peer_addr: 78.47.64.64:3100, task: network
Nov 23 11:25:32.726 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 1c9f9c7e86a8a82acd8f72060b6b04a392a8428af86dcfb5, peer_addr: 120.146.185.63:3000, task: network
Nov 23 11:25:32.726 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 431214988b71f3da55a342977fea1f3d8cba460d031a839c, peer_addr: 3.124.132.123:3000, task: network
Nov 23 11:25:32.727 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: b93e465963ded9f3212fa0a443a81ec467cccb1310c467e2, peer_addr: 167.71.118.1:3000, task: network
Nov 23 11:25:32.727 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 9d2b48d372afb6ba8e076bd3b8585afcfe83ec11bc2de32c, peer_addr: 98.127.116.122:7073, task: network
Nov 23 11:25:32.727 ERRO failed to send block announcement to the block task, reason: send failed because receiver is gone, direction: in, stream: block_events, node_id: 84bd248ba429592cfcd3a162c9a0e1641bd373009dc7fa6b, peer_addr: 52.8.169.161:3000, task: network
Nov 23 11:25:32.727 INFO Shutting down node
0: 0x104878e95 - ::fmt::h66f38d4abb2e41c1
1: 0x10489b4d0 - core::fmt::write::h4f487e714088986d
2: 0x10487355b - std::io::Write::write_fmt::h7bd7b6fe8b47c5fb
3: 0x10487b19a - std::panicking::default_hook::{{closure}}::heee79636c241547c
4: 0x10487aea5 - std::panicking::default_hook::hfcbd07059d15441e
5: 0x10487b867 - std::panicking::rust_panic_with_hook::h0c4b67125f55410a
6: 0x1048a1551 - std::panicking::begin_panic::h817647a7cd322460
7: 0x103ed89b0 - jormungandr::start_services::{{closure}}::{{closure}}::hbe6ccf2504f41799
8: 0x103f99e92 - std::panicking::try::do_call::h14fc7badb6d62f7a
9: 0x10487f10f - __rust_maybe_catch_panic
10: 0x103fd9472 - as futures::future::Future>::poll::h46dac3a96d1bb17b
11: 0x103eb2cd2 - as futures::future::Future>::poll::h25b5e4709dcfb12e
12: 0x10414a09b - futures::future::chain::Chain::poll::h22b10e87d8543eeb
13: 0x104859c4d - futures::task_impl::std::set::hf6a81d7ad603e678
14: 0x1048597e6 - std::panicking::try::do_call::hcd8daf8285f047e0
15: 0x10487f10f - __rust_maybe_catch_panic
16: 0x10485924c - tokio_threadpool::task::Task::run::h760436a59674e20c
17: 0x104853fe2 - tokio_threadpool::worker::Worker::run_task::ha7990cca7b384af0
18: 0x104853650 - tokio_threadpool::worker::Worker::run::hcce58b75f670a94e
19: 0x10483715d - std::thread::local::LocalKey::with::h10e97151fce0e682
20: 0x104837423 - std::thread::local::LocalKey::with::h8bd1893f4e1dcef8
21: 0x1048372d5 - std::thread::local::LocalKey::with::h25cef123f17cae5c
22: 0x104838f21 - tokio::runtime::threadpool::builder::Builder::build::{{closure}}::h936dd1a535065305
23: 0x104856cdb - std::thread::local::LocalKey::with::h4ea373a2c47f8794
24: 0x10485678b - std::thread::local::LocalKey::with::h144e317d6ab1920c
25: 0x10484ff60 - std::sys_common::backtrace::__rust_begin_short_backtrace::h75b0980a2f3dd595
26: 0x104859750 - std::panicking::try::do_call::h2b96ac45e1874e98
27: 0x10487f10f - __rust_maybe_catch_panic
28: 0x1048518b7 - core::ops::function::FnOnce::call_once{{vtable.shim}}::he746ca0ef6339ffd
29: 0x10486c85e - as core::ops::function::FnOnce>::call_once::hd1afe4d791e3679f
30: 0x10487e62e - std::sys::unix::thread::Thread::new::thread_start::h785fcf8d81bd0f52
31: 0x7fff69934d36 - _pthread_start
Nov 23 11:25:32.827 CRIT Task panicked, task: network
Nov 23 11:25:32.829 WARN Shutting down service client-query (up since 5m 2s 224ms 768us 201ns): receiving on a closed channel, task: client-query

rickymac68 picture rickymac68 on 23 Nov 2019

Issue reproducible also on QA testnet (internal one)

dorin100 picture dorin100 on 25 Nov 2019

Still happens on 0.7.5 when starting a passive node with an empty storage folder... during bootstrapping first 2000 blocks are fetched from a trusted peer, after that stalling ensues (sometimes extra 32 blocks are fetched in my case but after that the last block height seems to be permanently stuck).

hodlonaut picture hodlonaut on 27 Nov 2019
👍1

The 2000 blocks limit used to be imposed by the node that the blockchain is bootstrapped _from_, so if the trusted peers were not updated, the stream will still be cut off. The testnet nodes should be updated to 0.7.5 or later for the limit to be removed end to end.

mzabaluev picture mzabaluev on 27 Nov 2019

Following up from previous comment, can confirm that passive 0.7.5 node with empty storage bootstrapped okay from 0.7.5 trusted node, i.e. 2000 block limit issue was not encountered.

hodlonaut picture hodlonaut on 28 Nov 2019
👍1

did not see this issue anymore when using 0.8.0-rc3, connected to nightly testnet.

dorin100 picture dorin100 on 2 Dec 2019

I believe this is fixed with #1290 and #1292 . It will be included in the next release

NicolasDP picture NicolasDP on 6 Dec 2019
🎉1
Was this page helpful?
0 / 5 - 0 ratings

Related issues
Linicks picture Linicks  路  13Comments
bjarnekvae picture bjarnekvae  路  12Comments
NicolasDP picture NicolasDP  路  19Comments
rickymac68 picture rickymac68  路  18Comments
dorin100 picture dorin100  路  28Comments