Jormungandr: Wrong parent hash selection due to low number of block announcements

[MarcelKlammer]

Describe the bug

The network is propagating the wrong parent hash. The previous block was minted over 40 seconds before our slot.

This was the leader event:
[
{
"created_at_time": "2020-01-18T07:31:27.928555+00:00",
"enclave_leader_id": 1,
"finished_at_time": "2020-01-18T11:58:09.007833+00:00",
"scheduled_at_date": "35.30136",
"scheduled_at_time": "2020-01-18T11:58:09+00:00",
"status": {
"Block": {
"block": "9bd58383e8ee450ae556a41fa04c199ab9aaf1ec13cb7aa2c12deb3f0a42465d",
"chain_length": 109019
}
},
"wake_at_time": "2020-01-18T11:58:08.913427+00:00"
}
]

The node got 6 block announcements 40 seconds before the nodes own leader event started.

3 for the correct hash: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f (on chain)
3 for the wrong hash: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff (not on chain).

The leader event service chose to tell my node the wrong hash instead of the correct hash.

The node had 2600 connections at that time.

And the network wasn't able to send more correct block announcements with the correct hash in 40 seconds.

Mandatory Information

1. jcli 0.8.6 (HEAD-7686397, release, macos [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]
2. jormungandr 0.8.6 (HEAD-7686397, release, macos [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

To Reproduce

Logs:

Jan 18 12:57:25.857 INFO
received block announcement from network,
from_node_id: cb923c833f0450b1ebff826c676ec373bdd5b0fe7c3ca38b,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f

Jan 18 12:57:25.861 INFO
received block announcement from network,
from_node_id: cb923c833f0450b1ebff826c676ec373bdd5b0fe7c3ca38b,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff

Jan 18 12:57:25.957 INFO
received block announcement from network,
from_node_id: b885260cc06f5684caaeb189d91555332b57a1ffbc505150,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f

Jan 18 12:57:25.959 INFO update current branch tip, task: block
Jan 18 12:57:25.959 INFO create new branch, task: block

Jan 18 12:57:26.965 INFO
received block announcement from network,
from_node_id: e927f9acac513928a9b4be6ba09a0de09a2eb17564dcb4c4,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f

Jan 18 12:57:26.974 INFO
received block announcement from network,
from_node_id: e927f9acac513928a9b4be6ba09a0de09a2eb17564dcb4c4,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff

Jan 18 12:57:27.600 INFO
received block announcement from network,
from_node_id: 7a56b18599e7907326e8df02f74c0f0215c7ffa154ac8f3a,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff

Jan 18 12:58:08.913 WARN system woke a bit early for the event, delaying until right time., event_end: 2020-01-18T11:58:11+00:00, event_start: 2020-01-18T11:58:09+00:00, event_date: 35.30136, leader_id: 1, task: leadership

Jan 18 12:58:09.007 INFO
Leader event started,
event_remaining_time: 1s 992ms 861us,
event_end: 2020-01-18T11:58:11+00:00,
event_start: 2020-01-18T11:58:09+00:00,
event_date: 35.30136, leader_id: 1, task: leadership

Jan 18 12:58:09.007 INFO
receiving block from leadership service,
date: 35.30136,
parent: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff,
hash: 9bd58383e8ee450ae556a41fa04c199ab9aaf1ec13cb7aa2c12deb3f0a42465d

Jan 18 12:58:09.008 ERRO
cannot process leadership block,
reason: cannot process leadership block,
date: 35.30136,
parent: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff,
hash: 9bd58383e8ee450ae556a41fa04c199ab9aaf1ec13cb7aa2c12deb3f0a42465d, task: block

Jan 18 12:58:17.764 INFO
received block announcement from network,
from_node_id: 954e9153b5ebcdd5e3ddb130b89fa2a5fbe94bbdddafcdb5,
date: 35.30140, parent: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f,
hash: 0378514ecff45a9f39e2721d3550b04537b42ba394e33ccf9a3f2346f428bab3, task: block

Jan 18 12:58:17.833 INFO
received block announcement from network,
from_node_id: e927f9acac513928a9b4be6ba09a0de09a2eb17564dcb4c4,
date: 35.30140, parent: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f,
hash: 0378514ecff45a9f39e2721d3550b04537b42ba394e33ccf9a3f2346f428bab3, task: block

Expected behavior
The network should provide the correct parent hash for a leadership event for the hash production.

Additional context

[rdlrt]

Duplicate of #1513

[MarcelKlammer]

The block announcements need to increase. The nodes sitting there for 30 seconds with two different current block hashes (currently 7300 connections for two nodes):

Two nodes:

blockRecvCnt: 7199
lastBlockContentSize: 0
lastBlockDate: "37.22338"
lastBlockFees: 0
lastBlockHash: 923c519f1ebff72d6a232321a138872faf294cc5d26c13667ea56e13c0bc7ede
lastBlockHeight: "114399"
lastBlockSum: 0
lastBlockTime: "2020-01-20T07:38:13+00:00"
lastBlockTx: 0
lastReceivedBlockTime: "2020-01-20T07:38:14+00:00"
state: Running
txRecvCnt: 1518
uptime: 138640
version: jormungandr 0.8.6-7686397
iMac-Marcel:cardano marcelklammer$ ./jcli rest v0 node stats get -h http://127.0.0.1:3097/api

blockRecvCnt: 7283
lastBlockContentSize: 0
lastBlockDate: "37.22338"
lastBlockFees: 0
lastBlockHash: ea2e98a6260eb1b858bd912037dae57e8e8026e3a31dafbb403680a65bd59dba
lastBlockHeight: "114399"
lastBlockSum: 0
lastBlockTime: "2020-01-20T07:38:13+00:00"
lastBlockTx: 0
lastReceivedBlockTime: "2020-01-20T07:38:13+00:00"
state: Running
txRecvCnt: 1531
uptime: 138641
version: jormungandr 0.8.6-7686397

^ different hashes, same height

Next block, both correct this time:

blockRecvCnt: 7200
lastBlockContentSize: 0
lastBlockDate: "37.22373"
lastBlockFees: 0
lastBlockHash: 45acccedf4c62b0bac3f54dbce5affdbe673714b95228ce335820fefd86ee196
lastBlockHeight: "114400"
lastBlockSum: 0
lastBlockTime: "2020-01-20T07:39:23+00:00"
lastBlockTx: 0
lastReceivedBlockTime: "2020-01-20T07:39:23+00:00"
state: Running
txRecvCnt: 1518
uptime: 138676
version: jormungandr 0.8.6-7686397
iMac-Marcel:cardano marcelklammer$ ./jcli rest v0 node stats get -h http://127.0.0.1:3097/api

blockRecvCnt: 7285
lastBlockContentSize: 0
lastBlockDate: "37.22373"
lastBlockFees: 0
lastBlockHash: 45acccedf4c62b0bac3f54dbce5affdbe673714b95228ce335820fefd86ee196
lastBlockHeight: "114400"
lastBlockSum: 0
lastBlockTime: "2020-01-20T07:39:23+00:00"
lastBlockTx: 0
lastReceivedBlockTime: "2020-01-20T07:39:24+00:00"
state: Running
txRecvCnt: 1531
uptime: 138676

Long waiting time for 114400, so network could have send the correct hash in that time:

2020-01-20 08:38:14 Current block height: "114398" - No new block for 35 sec.
2020-01-20 08:38:19 New block height: "114399" - 138943
2020-01-20 08:38:24 Current block height: "114399" - No new block for 5 sec.
2020-01-20 08:38:29 Current block height: "114399" - No new block for 10 sec.
2020-01-20 08:38:34 Current block height: "114399" - No new block for 15 sec.
2020-01-20 08:38:39 Current block height: "114399" - No new block for 20 sec.
2020-01-20 08:38:44 Current block height: "114399" - No new block for 25 sec.
2020-01-20 08:38:49 Current block height: "114399" - No new block for 30 sec.
2020-01-20 08:38:54 Current block height: "114399" - No new block for 35 sec.
2020-01-20 08:38:59 Current block height: "114399" - No new block for 40 sec.
2020-01-20 08:39:04 Current block height: "114399" - No new block for 45 sec.
2020-01-20 08:39:09 Current block height: "114399" - No new block for 50 sec.
2020-01-20 08:39:14 Current block height: "114399" - No new block for 55 sec.
2020-01-20 08:39:19 Current block height: "114399" - No new block for 60 sec.
2020-01-20 08:39:24 New block height: "114400" - 139008
2020-01-20 08:39:29 Current block height: "114400" - No new block for 5 sec.
2020-01-20 08:39:34 Current block height: "114400" - No new block for 10 sec.
2020-01-20 08:39:39 Current block height: "114400" - No new block for 15 sec.
2020-01-20 08:39:44 Current block height: "114400" - No new block for 20 sec.
2020-01-20 08:39:49 Current block height: "114400" - No new block for 25 sec.
2020-01-20 08:39:54 Current block height: "114400" - No new block for 30 sec.
2020-01-20 08:39:59 Current block height: "114400" - No new block for 35 sec.
2020-01-20 08:40:04 Current block height: "114400" - No new block for 40 sec.
2020-01-20 08:40:09 New block height: "114401" - 139053

The network doesn't promote the correct blocks correctly.

[rinor]

@MarcelKlammer thank you for the report. Let's check a bit in what case the initial issue you reported may happen. I would need to check your logs to confirm this, but the following is a possible scenario.

From your logs it appears that the actual main branch is at tip 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373 when it receives those announcements from network:

Jan 18 12:57:25.857 INFO
received block announcement from network,
from_node_id: cb923c833f0450b1ebff826c676ec373bdd5b0fe7c3ca38b,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f

Jan 18 12:57:25.861 INFO
received block announcement from network,
from_node_id: cb923c833f0450b1ebff826c676ec373bdd5b0fe7c3ca38b,
date: 35.30114,
parent: 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373,
hash: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff
...
Jan 18 12:58:09.007 INFO
receiving block from leadership service,
date: 35.30136,
parent: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff,
hash: 9bd58383e8ee450ae556a41fa04c199ab9aaf1ec13cb7aa2c12deb3f0a42465d

and since we see block 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f announcement arriving first/before the other one 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff, we would expect that first/earlier block to become our main branch tip, but that may not be always the case since, especially in such cases where the notifications are received within few milliseconds, because the block announcement is just the first step and is followed by other steps.
With debug loglevel the flow looks like:

Jan 19 19:22:47.061 INFO received block announcement from network, from_node_id: 36cb77a5a064c680c69d93e28728a031def71b4f1a0abb0c, date: 37.271, parent: c69b26c1a345a13e4d42bf387b093744d24e4e779228f1b50e856961247890e0, hash: 91e4acf46248aaf45722bb05fa32faf06fb001c278745fae2290b1ea456bdda8, task: block
Jan 19 19:22:47.075 DEBG Announced block has a locally stored parent, fetch it, from_node_id: 36cb77a5a064c680c69d93e28728a031def71b4f1a0abb0c, date: 37.271, parent: c69b26c1a345a13e4d42bf387b093744d24e4e779228f1b50e856961247890e0, hash: 91e4acf46248aaf45722bb05fa32faf06fb001c278745fae2290b1ea456bdda8, task: block
Jan 19 19:22:47.076 DEBG sending block solicitation to 36cb77a5a064c680c69d93e28728a031def71b4f1a0abb0c, hashes: [Hash(Blake2b256(0x91e4acf46248aaf45722bb05fa32faf06fb001c278745fae2290b1ea456bdda8))], task: network
Jan 19 19:22:47.077 INFO receiving block stream from network, task: block
Jan 19 19:22:47.440 DEBG applying block to storage, date: 37.271, parent: c69b26c1a345a13e4d42bf387b093744d24e4e779228f1b50e856961247890e0, hash: 91e4acf46248aaf45722bb05fa32faf06fb001c278745fae2290b1ea456bdda8, task: block
Jan 19 19:22:47.534 INFO update current branch tip, task: block
Jan 19 19:22:47.568 DEBG propagating block, hash: 91e4acf46248aaf45722bb05fa32faf06fb001c278745fae2290b1ea456bdda8, task: network

There are more steps/checks done, but leaving the storage aside from the logs we can follow some simple steps:

• received block announcement from network
• Announced block has a locally stored parent, fetch it (decide if interested and what to fetch)
• sending block solicitation (send request to download the needed block(s))
• _receiving block stream from network_ (here we are downloading the block)
• update current branch tip (chain selection decides that our main branch is preferred one (in case there are other branches, but doesn't matter in this case...) and update our main branch tip with the received block)

Now while indeed you got notified first about 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f, it is possible that 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff was processed/downloaded (faster)/before the other one becoming your tip, while the other one 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f ended on e new branch. Hence:

Jan 18 12:57:25.959 INFO update current branch tip, task: block

refers to block 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff becoming the tip (will check and add additional info to that message), and

Jan 18 12:57:25.959 INFO create new branch, task: block

refers to block 1ad3e958e1e2b6775e8d6070565d6a634d2a513ef4c09c0825fb390ec1b1175f creating a new branch.

Both branches at this point have a common point parent 68f838b3a9122cedfc6ad40291a8127f72954d8b50b23a0959b58fc47f062373.

Now when the leader wakes up it checks the tip of our main branch which is indeed 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff so it is what is used as a parent to the block that is about to be created.

Jan 18 12:58:09.007 INFO
receiving block from leadership service,
date: 35.30136,
parent: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff,
hash: 9bd58383e8ee450ae556a41fa04c199ab9aaf1ec13cb7aa2c12deb3f0a42465d

Now what ma be concerning is the message you get cannot process leadership block which needs to be investigated/fixed/clarified why and when it happens:

Jan 18 12:58:09.008 ERRO
cannot process leadership block,
reason: cannot process leadership block,
date: 35.30136,
parent: 4efdbd85d6a65eeaa47095184544440a4acb4f118351dd52fad208a914cdceff,
hash: 9bd58383e8ee450ae556a41fa04c199ab9aaf1ec13cb7aa2c12deb3f0a42465d, task: block

Will be checking this further. Thanks again for the report.

[MarcelKlammer]

Thanks for taking the time to analyse the issue.

Leaving aside the most technical insight:

Should the network be able to decide which branch is correct in a 30 seconds time frame, or is the next minted block necessary to determine the correct branch?

If so, why didn't the minted block (minted 4 slots before the other one) make that decision possible and choose the branch the node was on?

If not (block necessary), why didn't the network tell the node the correct hash to compute the next block from.

I will restart my two nodes with debug instead of info logging and report, if I have any updates.

[rinor]

@MarcelKlammer the problem here is that your node _failed_ to produce the block it was supposed to, cannot process leadership block, so it was not included in you chain neither broadcasted to the network. If it had been produced and broadcasted maybe other nodes would have agreed an chose your view of the chain.

[MarcelKlammer]

The leader service asked the network, whether the block produced is correct?
So it failed, because of the wrong parent?
It determined that in no time and could have easily produce another block on the other chain within the slots' time frame.

But I guess that's not how it's supposed to work and we should have the correct parent hash instead.

[MarcelKlammer]

We had a new chance to produce a block and it failed again.

The time shown as timestamp in these logs differs by 1 hour, but the event started at the correct time.

Jan 22 03:45:10.863 WARN
system woke a bit early for the event, delaying until right time., event_end: 2020-01-22T02:45:13+00:00, event_start: 2020-01-22T02:45:11+00:00, event_date: 39.13547, leader_id: 1, task: leadership

Jan 22 03:45:11.002 INFO
Leader event started,
event_remaining_time: 1s 997ms 283us,
event_end: 2020-01-22T02:45:13+00:00,
event_start: 2020-01-22T02:45:11+00:00,
event_date: 39.13547,
leader_id: 1, task: leadership

Jan 22 03:45:11.003 DEBG
no item scheduled, waiting for next epoch,
task: leadership

Jan 22 03:45:11.003 INFO
receiving block from leadership service,
date: 39.13547,
parent: 41896e3102e12b545277b4fc59856f0b771ddd8bc59ac8c75ebfe80ded3e02bb,
hash: 5ba64897f205084fab7810c91a48378199f5d943ae92aa1c63b3d970bb5a86ec,
task: block

Jan 22 03:45:11.003 DEBG
processing block from leader event,
date: 39.13547,
parent: 41896e3102e12b545277b4fc59856f0b771ddd8bc59ac8c75ebfe80ded3e02bb,
hash: 5ba64897f205084fab7810c91a48378199f5d943ae92aa1c63b3d970bb5a86ec, task: block

Jan 22 03:45:11.004 ERRO
cannot process leadership block,
reason: cannot process leadership block,
date: 39.13547,
parent: 41896e3102e12b545277b4fc59856f0b771ddd8bc59ac8c75ebfe80ded3e02bb,
hash: 5ba64897f205084fab7810c91a48378199f5d943ae92aa1c63b3d970bb5a86ec, task: block

Parent hash was correct this time, from 2 slots before: 39.13545

The logs don't tell anything about the reason the block

"reason: cannot process leadership block, " is not meaningful at this stage.

[rinor]

@MarcelKlammer thank you for the detailed logs.
BlockHeaderVerificationFailed("Block proof is invalid") - is the culprit here. Checking.

[MarcelKlammer]

What can cause that proof failure? Is there a list of reasons, that I could check my setup against?

[MarcelKlammer]

Next try, next fail, 3 minutes before our slot both nodes didn't get any updates anymore. It was around 1am, so wasn't looking closely.

This now let to shutting down the nodes/pool for now. We will wait for the haskell backend and may start over then.

Best Regards and keep it up
Marcel

[MarcelKlammer]

Yesterday I revisited the node/pools setup. It turns out, that while creating the pool, I ended up with a wrong nodesecret.yaml. The private keys didn't produce the correct public key. So I digged deeper and found other logs with the correct private keys, which I now included into the secret.yaml. Will test again whether the block creation process is now working.

In any case, an automatice secret check might help prevent that. Testing the private key agains the blockchain stored public keys on startup, but I guess, that's not a useful feature for everyone.

Cheers
Marcel