Block not found at get_weight/3

[rodrigo-o]

Despite tackling #1315 the addition of the Maximum clock disparity into the equation to calculate future slots appeared to not be enough. After running a test with #1318 branch, the node was stable for ~40hours before the following happened:

2024-10-06 02:33:12.006	[Libp2p] Slot transition
2024-10-06 02:33:00.585	[Fork choice] Failed to add block: block is from the future
2024-10-06 02:33:00.585	[PendingBlocks] Saving block as invalid after ForkChoice.on_block/2 error: block is from the future
2024-10-06 02:33:00.529	[Optimistic Sync] Waiting 15.0 seconds to discover some peers before requesting blocks.
2024-10-06 02:33:00.529	[Fork choice] Adding new block
2024-10-06 02:33:00.468	Last message: {#Port<0.15>, {:data, <<10, 242, 74, 10, 40, 47, 101, 116, 104, 50, 47, 100, 51, 49, 102, 54, 49, 57, 49, 47, 98, 108, 111, 98, 95, 115, 105, 100, 101, 99, 97, 114, 95, 49, 47, 115, 115, 122, 95, 115, 110, 97, 112, 112, 121, 26, ...>>}}" mfa=:gen_server.error_info/8 pid=#PID<0.444.0>
2024-10-06 02:33:00.468	    (elixir 1.16.2) lib/stream.ex:1828: Enumerable.Stream.do_each/4
2024-10-06 02:33:00.468	    (elixir 1.16.2) lib/enum.ex:4839: Enumerable.List.reduce/3
2024-10-06 02:33:00.468	    (elixir 1.16.2) lib/stream.ex:1816: anonymous fn/3 in Enumerable.Stream.reduce/3
2024-10-06 02:33:00.468	    (elixir 1.16.2) lib/enum.ex:4396: anonymous fn/3 in Enum.reduce/3
2024-10-06 02:33:00.468	    (lambda_ethereum_consensus 0.1.0) lib/lambda_ethereum_consensus/fork_choice/head.ex:50: anonymous fn/6 in LambdaEthereumConsensus.ForkChoice.Head.get_weight/3
2024-10-06 02:33:00.468	    (elixir 1.16.2) lib/map.ex:450: Map.put_new_lazy/3
2024-10-06 02:33:00.468	    (lambda_ethereum_consensus 0.1.0) lib/types/store.ex:120: Types.Store.get_ancestor/3
2024-10-06 02:33:00.468	    (lambda_ethereum_consensus 0.1.0) lib/lambda_ethereum_consensus/store/blocks.ex:72: LambdaEthereumConsensus.Store.Blocks.get_block!/1
2024-10-06 02:33:00.468	** (RuntimeError) Block not found: 0x75e7d39a4266b27fb6260f64e2903e29e7de4fd0cfbc3af8e58fa28f7aaa0afa
2024-10-06 02:33:00.468	ts=2024-10-06T05:33:00.468 level=error msg="GenServer LambdaEthereumConsensus.Libp2pPort terminating
2024-10-06 02:33:00.446	[Fork choice] Block processed. Recomputing head.
2024-10-06 02:33:00.226	[Fork choice] Adding new block
2024-10-06 02:33:00.146	[Gossip] Block received, block.slot: 6038265.
2024-10-06 02:33:00.017	[Libp2p] Slot transition
2024-10-06 02:32:49.096	[Fork choice] Recomputed head
2024-10-06 02:32:49.096	[Fork choice] Added new block
2024-10-06 02:32:48.814	[Fork choice] Block processed. Recomputing head.
2024-10-06 02:32:48.625	[Fork choice] Adding new block

Things to have into account:

• The block was marked as invalid while it just needed to wait 1 slot (if it really came before the slot transition)
• In reality it came just after the slot transition! so it shoulded just work
• Marking a canonnical block as invalid stops the following state transitions. We shouldn't mark a block as invalid if its from the futurre, maybe just leave them where it was.
• We need a way to debug this in situ, because as far as the logs shows, the block was processed exactly at the time its slot was happening, so there is no chance it was from the future

[rodrigo-o]

The points detailed are an explanation of why the node stoped processing new blocks, but the issue was not caused by the block in the future error as first thought, instead it was caused by a missing block in the store, which after a restart of Libp2p made the store point again at the initial checkpoint and that caused the future block. The cause is really the missed block at the get_weight function.

[rodrigo-o]

This happened today in the morning again.

[rodrigo-o]

This issue is not stopping the node anymore on main. At least for what I was able to check, even with lots of warning, the node continues processing:

  |   | 2025-02-04 11:43:38.275 | [Fork choice] Recomputed head |  
  |   | 2025-02-04 11:43:38.275 | [Fork choice] Added new block |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.263 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.253 | No ancestor found for vote root: |  
  |   | 2025-02-04 11:43:38.253 | No ancestor found for vote root:

Filtering the warning we get a view of the node running as expected

  |   | 2025-02-04 11:54:25.606 | [Fork choice] Recomputed head |  
  |   | 2025-02-04 11:54:25.606 | [Fork choice] Added new block |  
  |   | 2025-02-04 11:54:24.978 | [Fork choice] Block processed. Recomputing head. |  
  |   | 2025-02-04 11:54:24.821 | [Fork choice] Adding new block |  
  |   | 2025-02-04 11:54:24.818 | [Gossip] Block received, block.slot: 6912272. |  
  |   | 2025-02-04 11:54:24.012 | [Libp2p] Slot transition |  
  |   | 2025-02-04 11:54:13.479 | [Fork choice] Recomputed head |  
  |   | 2025-02-04 11:54:13.479 | [Fork choice] Added new block |  
  |   | 2025-02-04 11:54:12.935 | [Fork choice] Block processed. Recomputing head. |  
  |   | 2025-02-04 11:54:12.694 | [Fork choice] Adding new block |  
  |   | 2025-02-04 11:54:12.526 | [Gossip] Block received, block.slot: 6912271. |  
  |   | 2025-02-04 11:54:12.015 | [Libp2p] Slot transition |  
  |   | 2025-02-04 11:54:01.449 | [Fork choice] Recomputed head |  
  |   | 2025-02-04 11:54:01.449 | [Fork choice] Added new block |  
  |   | 2025-02-04 11:54:00.917 | [Fork choice] Block processed. Recomputing head. |  
  |   | 2025-02-04 11:54:00.666 | [Fork choice] Adding new block |  
  |   | 2025-02-04 11:54:00.656 | [Gossip] Block received, block.slot: 6912270.