Debugging - HackMD

# Debugging Logs: https://drive.google.com/file/d/1M5rcOt_WvilZIUgxabjMrSg7kMtPRBTQ/view What happened to `0x5e060d315a364b3cc84cd3984ddca9792057f853218e9197c3f49104361fb189`? > Note: > > This document refers to two blocks: > > - [The parent: 1b28](https://beaconcha.in/slot/4779417) > - [The child: 5e06](https://beaconcha.in/slot/4779418) > - [The grandchild: 45fd](https://beaconcha.in/slot/4779419) ## Significant Log Events We try to look for the parent (1b28) (I didn't bother to figure out the cause of this lookup): ``` Sep 26 07:23:55.224 DEBG Searching for block, block: 0x1b28…49c4, peer_id: 16Uiu2HAmT4bUv8e8XWUH4XaB4J3ipAgHrEGcYFLbXjdYYuuoyugP, service: sync, module: network::sync::block_lookups:81 ``` We still haven't managed to import 1b28, although we've requested/searched for the it a lot. Now, we receive the grandchild and realise we don't know the child: ``` Sep 26 07:23:59.750 DEBG Rejected gossip block, slot: 4779418, graffiti: , error: ParentUnknown(parent_root:0x1b28…49c4), service: beacon, module: beacon_chain::beacon_chain:2403 Sep 26 07:23:59.754 DEBG Unknown parent for gossip block, root: 0x5e060d315a364b3cc84cd3984ddca9792057f853218e9197c3f49104361fb189, module: network::beacon_processor::worker::gossip_methods:774 ``` We process a parent chain referencing the child, but don't import any blocks (`was_non_empty: false`): ``` Sep 26 07:24:09.359 DEBG Parent chain processed, result: Success { was_non_empty: false }, chain_hash: 0x5e06…b189, service: sync, module: network::sync::block_lookups:603 ``` We reject a descendant of the child: ``` Sep 26 07:24:14.339 DEBG Rejected gossip block, slot: 4779419, graffiti: Lido ⚡️Allnodes, error: ParentUnknown(parent_root:0x5e06…b189), service: beacon, module: beacon_chain::beacon_chain:2403 Sep 26 07:24:14.354 DEBG Unknown parent for gossip block, root: 0x45fd94dd71e8d21f59782110e91b335ba64c296b8a6dcc488871f55cc511d097, module: network::beacon_processor::worker::gossip_methods:774 ``` We fail to process the parent due to a bad chain of block roots: ``` Sep 26 07:24:17.022 DEBG Processing parent lookup, blocks: 2, chain_hash: > 0x1b28…49c4, module: network::beacon_processor::worker::sync_methods:210 Sep 26 07:24:17.055 DEBG Invalid block received, outcome: NonLinearParentRoots, msg: peer sent invalid block, module: network::beacon_processor::worker::sync_methods:497 Sep 26 07:24:17.055 DEBG Parent lookup failed, error: Peer sent invalid block. Reason: NonLinearParentRoots, module: network::beacon_processor::worker::sync_methods:222 Sep 26 07:24:17.055 DEBG Parent chain processed, result: NonFaultyFailure, chain_hash: 0x1b28…49c4, service: sync, module: network::sync::block_lookups:603 ``` Now, we reject another parent lookup which has a chain hash of the grandchild. Notably, this lookup contains 1 block (the child, I assume) and we downscore the peer because we didn't know the parent (but recall that we rejected the parent chain in the previous logs): ``` Sep 26 07:24:22.217 DEBG Parent lookup failed, error: Block has an unknown parent: 0x1b28…49c4, module: network::beacon_processor::worker::sync_methods:222 Sep 26 07:24:22.217 DEBG Parent chain processed, result: FaultyFailure { imported_blocks: false, penalty: LowToleranceError }, chain_hash: 0x45fd…d097, service: sync, module: network::sync::block_lookups:603 ``` We import a parent chain with a chain hash of the child (5e06), however we set its parent (1b28) as the head. Fork choice always chooses the tip of the chain, so this means we didn't import 5e06 (only its parent): ``` Sep 26 07:24:23.350 DEBG Fork choice updated head, old_head: 0xebf4e958d6079a4b70f4ca3e0fcb806d8c3d86a0b3e032ce198649b2e4420d3d, old_head_weight: Some(431872000000000), new_head: 0x1b285b21f3d94a6d063791557b87ffe9c2f5f512553a306f72a413a3656049c4, new_head_weight: Some(0), service: beacon, module: beacon_chain::canonical_head:1072 Sep 26 07:24:23.350 DEBG Parent chain processed, result: Success { was_non_empty: true }, chain_hash: 0x5e06…b189, service: sync, module: network::sync::block_lookups:603 ``` 5e06 is imported via RPC: ``` Sep 26 07:24:33.232 INFO New RPC block received, hash: 0x5e06…b189, slot: 4779418, module: network::beacon_processor::worker::sync_methods:95 ``` 5e06 is set as head only a tiny bit late: ``` Sep 26 07:24:33.242 DEBG Fork choice updated head, old_head: 0x1b285b21f3d94a6d063791557b87ffe9c2f5f512553a306f72a413a3656049c4, old_head_weight: Some(430784000000000), new_head: 0x5e060d315a364b3cc84cd3984ddca9792057f853218e9197c3f49104361fb189, new_head_weight: Some(0), service: beacon, module: beacon_chain::canonical_head:1072 Sep 26 07:24:33.280 DEBG Delayed head block, set_as_head_delay: Some(48.012041ms), imported_delay: Some(711.793779ms), observed_delay: Some(33.520171113s), block_delay: 34.279976933s, slot: 4779418, proposer_index: 431327, block_root: 0x5e060d315a364b3cc84cd3984ddca9792057f853218e9197c3f49104361fb189, service: beacon, module: beacon_chain::canonical_head:1351 ``` 5e06 is no longer head: ``` Sep 26 07:25:28.930 DEBG Fork choice updated head, old_head: 0x5e060d315a364b3cc84cd3984ddca9792057f853218e9197c3f49104361fb189, old_head_weight: Some(431648000000000), new_head: 0x45fd94dd71e8d21f59782110e91b335ba64c296b8a6dcc488871f55cc511d097, new_head_weight: Some(0), service: beacon, module: beacon_chain::canonical_head:1072 ``` End ## Analysis It seems that things are generally working as expected, considering the user has low-spec hardware. It seems that a peer sent us invalid blocks (non-linear roots), however that's not interesting on its own. What is interesting is why we have a `Parent Chain Processed` with `chain_hash: 0x5e06…b189`, but then later declare that `0x5e06…b189` is unknown. I would think that's impossible since when a `ParentLookup` is created the child block (the one with the unknown parent) is automatically added to `downloaded_blocks`: https://github.com/sigp/lighthouse/blob/01e84b71f524968f5b940fbd2fa31d29408b6581/beacon_node/network/src/sync/block_lookups/parent_lookup.rs#L71 However, I did find that `ParentLookup::chain_blocks` will `mem::take` those `downloaded_blocks` and leave an empty vec in its place: https://github.com/sigp/lighthouse/blob/01e84b71f524968f5b940fbd2fa31d29408b6581/beacon_node/network/src/sync/block_lookups/parent_lookup.rs#L129 We can see in [this code](https://github.com/sigp/lighthouse/blob/01e84b71f524968f5b940fbd2fa31d29408b6581/beacon_node/network/src/sync/block_lookups/mod.rs#L524-L529) that we pull the parent lookup from `parent_queue`, run `ParentLookup::chain_blocks`, and then put it back in the `parent_queue`. This means that it's somewhat possible for a parent lookup to exist in the parent queue which does not contain the original child block (the one with the missing parent). Looking at some more logs, we can see this sequence: ``` Sep 26 07:24:07.972 DEBG Processing parent lookup, blocks: 13, chain_hash: 0x5e06…b189, module: network::beacon_processor::worker::sync_methods:210 ...redacted for brevity... Sep 26 07:24:09.013 DEBG Requesting parent, chain_hash: 0x5e06…b189, request: parent, hash: 0x1b28…49c4, downloading_peer: 16Uiu2HAmQXbkSnwNXPgZosAe2kdNozHWSNcKVoEetDF1vQx2sPd1, failed_downloads: 0, failed_processing: 0, downloaded_blocks: 1, service: sync, module: network::sync::block_lookups:699 ...redacted for brevity... Sep 26 07:24:09.359 DEBG Parent lookup processed successfully, module: network::beacon_processor::worker::sync_methods:232 Sep 26 07:24:09.359 DEBG Parent chain processed, result: Success { was_non_empty: false }, chain_hash: 0x5e06…b189, service: sync, module: network::sync::block_lookups:603 ``` Here we can see that whilst we are processing a chain segment we create another `ParentLookup` for the same chain hash. When the chain segment was imported, it would have called `BlockLookups::parent_chain_processed` which would then [try to remove the `ParentLookup` via the `chain_hash`](https://github.com/sigp/lighthouse/blob/01e84b71f524968f5b940fbd2fa31d29408b6581/beacon_node/network/src/sync/block_lookups/mod.rs#L593-L601). If it happened to remove the parent lookup that was created whilst it was running (rather than the one that triggered it), then I believe it's possible that the `ParentLookup` that exists in `parent_queue` does not have any downloaded blocks, therefore making it possible for a `Parent Chain Processed` log to be emitted whilst the `chain_hash` it references was not applied to the `BeaconChain`. I haven't managed to link the logs all the way through to showing the end result of the parent being imported without the child, however this might be a good start towards that.