BlockTooEarly/InvalidResult Testnet node stuck

VirgileD · September 21, 2022, 12:19pm

Hello,
we have an ubuntu testnet node 4.3.1 and since this morning we have a problem we searched a fix for in vain for hours.
When restarting the node, it rapidly catches up with the chain, showing the usual “Block received/block Stats/finalization/finalization stats”.
Then there is, like 30 messages like (with - I suppose our - 4 different peers):

[WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 0000000000000005 due to error code InvalidResult

Then one info message of catch-up:

[INFO  concordium_node::plugins::consensus] Sent a direct message to peer 0000000000000006 containing a catch-up status message

Then for a few seconds, a bunch of regular block received/stats and finalization/stats logs.

Then a few (with - I suppose our - 4 different peers):

[INFO  concordium_node::plugins::consensus] Sent a direct message to peer 000000000000000c containing a catch-up status message

which I suppose are there to indicate that we told the peers that we were up to date.
But then, immediatly after these, we get:

[ERROR concordium_node::p2p::connectivity] [receiving from 195.249.104.111:8889] Connection reset by peer (os error 104)
[ERROR concordium_node::p2p::connectivity] [receiving from 35.179.96.229:8888] Connection reset by peer (os error 104)
[ERROR concordium_node::p2p::connectivity] [receiving from 34.88.64.241:8889] Connection reset by peer (os error 104)
[ERROR concordium_node::p2p::connectivity] [receiving from 195.249.104.111:3387] Connection reset by peer (os error 104)
[WARN  concordium_node::p2p::connectivity] Received 7 invalid messages from peer 000000000000000c
[WARN  concordium_node::p2p::connectivity] Received 13 invalid messages from peer 0000000000000006
[WARN  concordium_node::p2p::connectivity] Received 54 invalid messages from peer 0000000000000009
[WARN  concordium_node::p2p::connectivity] Received 5 invalid messages from peer 0000000000000005
[WARN  concordium_node::plugins::consensus] Couldn't process a block from peer 000000000000000c due to error code BlockTooEarly
[WARN  concordium_node::plugins::consensus] Couldn't process a block from peer 000000000000000c due to error code BlockTooEarly
[WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 000000000000000c due to error code InvalidResult
[WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 000000000000000c due to error code InvalidResult

And then the node is stucked and do nothing but logging, in loop, around 30 messages like):

[WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 0000000000000006 due to error code InvalidResult

then 4 messages like:

[WARN  concordium_node::p2p::connectivity] Received 47 invalid messages from peer 000000000000000c

and a bunch of

[WARN  concordium_node::plugins::consensus] Couldn't process a block from peer 0000000000000009 due to error code BlockTooEarly

The node doesn’t seem to receive any block and is stucked at the same height ever after. Restarting the node service just work until the catch-up is done and then the same happens again.
We couldn’t find any information about BlockTooEarly, and nothing seems related for InvalidResult

Any help would be much appreciated.

abizjak · September 21, 2022, 2:58pm

BlockTooEarly typically means that the clock of the system is incorrect. Are you sure that the system clock is correct?

VirgileD · September 22, 2022, 6:19am

Hi, thank you for your answer.
We were aware of that potential problem. We checked the date which seemed alright and nonetheless setup a ntp service to be sure. It didn’t change a thing:

:~/tools$ date && ./concordium-client_4.1.0 consensus status --grpc-port=10001
**Thu 22 Sep 2022 06:07:45 AM UTC**
Best block:                  a94a966da0dc136dc53dc379ee5716567d683da5320d3d412395546014da9c52
Genesis block:               4221332d34e1694168c2a0c0b3fd0f273809612cb13d000d5c2e00e85f50f796
Genesis time:                2022-06-13 10:00:00 UTC
.....
**Last finalized time:         Thu, 22 Sep 2022 06:07:45 UTC**
...

It really look like the catch up message sent to the peers trigger some bad behaviour because the errors/warnings shows up as soon as they’re sent. This morning I restarted the node service and the same happenned again: it goes very fast to catchup the missed blocks and then:

Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Block 1f3204e8bc9a04d6f6071b1a8c7616f0cc4d856108a2e2b2ef6698ecfdbc3170 is finalized at height 867035 with finalization delta=0
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Finalization statistics: finalizationCount=5299 lastFinalizedTime=1.6638268721129668e9 finalizationPeriodEMA=Just 5.407175045546361e-2 finalizationPeriodEMSD=Just 4.7928989685180716e-2
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Block 1c114ffbbbf532636dbb939e484092f35085e9427d5419723a1a3e2cce869222 (4) arrived
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Arrive statistics: blocksVerifiedCount=5765 blockLastArrive=1.6638268721499538e9 blockArriveLatencyEMA=119.53183817330269 blockArriveLatencyEMSD=130.2353203986254 blockArrivePeriodEMA=Just 5.2517988979790146e-2 blockArrivePeriodEMSD=Just 4.568694694851033e-2 transactionsPerBlockEMA=1.0258686156107552e-3 transactionsPerBlockEMSD=3.222620256627388e-2
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Received block fabef7877cbf142ac66192e677f32c1b38cc571b57f3221ded9fc0e0b953a279 (1004)
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Receive statistics: blocksReceivedCount=5766 blockLastReceived=1.6638268721502266e9 blockReceiveLatencyEMA=171.03984294087246 blockReceiveLatencyEMSD=166.6445322134318 blockReceivePeriodEMA=Just 8.160201495868788e-2 blockReceivePeriodEMSD=Just 6.654632060728267e-2
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Block 1c114ffbbbf532636dbb939e484092f35085e9427d5419723a1a3e2cce869222 is finalized at height 867036 with finalization delta=0
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Finalization statistics: finalizationCount=5300 lastFinalizedTime=1.663826872156562e9 finalizationPeriodEMA=Just 5.302408480991725e-2 finalizationPeriodEMSD=Just 4.557792971122829e-2
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Block fabef7877cbf142ac66192e677f32c1b38cc571b57f3221ded9fc0e0b953a279 (1004) arrived
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Arrive statistics: blocksVerifiedCount=5766 blockLastArrive=1.6638268721898108e9 blockArriveLatencyEMA=107.42263543007242 blockArriveLatencyEMSD=128.78202487571488 blockArrivePeriodEMA=Just 5.125188078181113e-2 blockArrivePeriodEMSD=Just 4.350855868733536e-2 transactionsPerBlockEMA=9.232817540496797e-4 transactionsPerBlockEMSD=3.057400914560846e-2
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Block fabef7877cbf142ac66192e677f32c1b38cc571b57f3221ded9fc0e0b953a279 is finalized at height 867037 with finalization delta=0
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::consensus_ffi::ffi] Skov: Finalization statistics: finalizationCount=5301 lastFinalizedTime=1.6638268721959527e9 finalizationPeriodEMA=Just 5.166075332892552e-2 finalizationPeriodEMSD=Just 4.343202693438412e-2
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::plugins::consensus] Sent a direct message to peer 0000000000000006 containing a catch-up status message
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::plugins::consensus] Sent a direct message to peer 0000000000000003 containing a catch-up status message
Sep 22 06:07:52 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::plugins::consensus] Sent a direct message to peer 0000000000000008 containing a catch-up status message
Sep 22 06:07:53 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::plugins::consensus] Sent a direct message to peer 000000000000000b containing a catch-up status message
Sep 22 06:07:53 xdrd2150s concordium-testnet-node-4.3.1[106363]: [INFO  concordium_node::plugins::consensus] Sent a direct message to peer 0000000000000009 containing a catch-up status message
Sep 22 06:07:53 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a block from peer 0000000000000009 due to error code BlockTooEarly
Sep 22 06:08:16 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::p2p::connectivity] Received 1 invalid messages from peer 0000000000000009
Sep 22 06:08:16 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a block from peer 000000000000000c due to error code BlockTooEarly
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 0000000000000008 due to error code InvalidResult
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a block from peer 0000000000000008 due to error code BlockTooEarly
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 000000000000000c due to error code InvalidResult
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 000000000000000c due to error code InvalidResult
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 0000000000000009 due to error code InvalidResult
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 0000000000000009 due to error code InvalidResult
Sep 22 06:08:23 xdrd2150s concordium-testnet-node-4.3.1[106363]: [WARN  concordium_node::plugins::consensus] Couldn't process a finalization message from peer 0000000000000009 due to error code InvalidResult

One more stranger thing, the last finalized block is not the one showed on the dashboard. I restarted once again and it received and finalized around thirty blocks, arriving at 807068 (far from the 807435 showed in the dashboard) and then the “sent a catch up message” appears and it started loosing it again.
I’m kinda stuck here.

abizjak · September 22, 2022, 7:16am

Are you sure you are not running two nodes? The way a node shows up on the network dashboard is that there is a separate service (the collector) which queries the node and posts the data.

Can you restart the node and show the logs since the startup until it starts printing warnings?

You can use journalctl -u concordium-testnet-node --since '1h ago' (or whatever duration is appropriate).

VirgileD · September 26, 2022, 12:30pm

Heelo @abizjak, thanks for your help.
You were right since the beginning, we had a problem with th eentp service on the server and although it seemed synchronized it was not . This morning, after correcting this issue I restarted everything and it’s now working correctly.
I’m sorry for the waste of time, so now I’ll know: BlockTooEarly==ServerDateProblem.
Thanks again.