search

sigp / lighthouse

Ethereum consensus client in Rust
https://lighthouse.sigmaprime.io/
Apache License 2.0
2.9k stars 736 forks source link

RPC lookups for blobs on local block production #4876

Closed realbigsean closed 10 months ago

realbigsean commented 11 months ago

I observed these logs on devnet 10, it looks like we might be triggering blobs by root lookups during block production:

Oct 24 18:20:24.471 DEBG Produced block on state, slot: 10002, block_size: 80656, service: beacon, module: beacon_chain::beacon_chain:5063
Oct 24 18:20:24.768 DEBG Processed HTTP API request, method: GET, path: /eth/v2/validator/blocks/10002, status: 200 OK, elapsed: 758.572649ms, module: http_api:194
Oct 24 18:20:24.879 DEBG Signed block received in HTTP API, slot: 10002, module: http_api::publish_blocks:64
Oct 24 18:20:24.912 INFO Signed block published to network via HTTP API, publish_delay: 33.432828ms, slot: 10002, module: http_api::publish_blocks:77
Oct 24 18:20:24.912 DEBG Sending pubsub messages, topics: [BeaconBlock, BlobSidecar(0), BlobSidecar(1), BlobSidecar(2), BlobSidecar(3)], count: 5, service: network, module: network::service:678
Oct 24 18:20:25.287 DEBG Invalid sync committee message from network, type: "sync_contribution", peer_id: 16Uiu2HAkvL9e2GrjpBv6nsVQm1qWU25iX1Su7fcLrnwJnwQ3yE66, reason: PastSlot { message_slot: Slot(10001), earliest_permissible_slot: Slot(10002) }, module: network::network_beacon_processor::gossip_methods:2756
Oct 24 18:20:25.316 DEBG Searching for block components, block: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, peer_ids: [BlockAndBlobs(PeerId("16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa"))], service: sync, module: network::sync::block_lookups:232
Oct 24 18:20:25.316 DEBG Sending BlocksByRoot Request, lookup_type: Current, peer: 16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa, block_roots: [0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30], method: BlocksByRoot, service: sync, module: network::sync::network_context:421
Oct 24 18:20:25.316 DEBG Sending BlobsByRoot Request, lookup_type: Current, peer: 16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa, blob_indices: [0, 1, 2, 3, 4, 5], block_root: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, method: BlobsByRoot, service: sync, module: network::sync::network_context:457
Oct 24 18:20:25.343 DEBG Peer returned blob for single lookup, blob_id: BlobIdentifier { block_root: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, index: 0 }, peer_id: 16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa, service: sync, module: network::sync::manager:951
Oct 24 18:20:25.386 DEBG Peer returned blob for single lookup, blob_id: BlobIdentifier { block_root: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, index: 1 }, peer_id: 16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa, service: sync, module: network::sync::manager:951
Oct 24 18:20:25.386 DEBG Peer returned blob for single lookup, blob_id: BlobIdentifier { block_root: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, index: 2 }, peer_id: 16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa, service: sync, module: network::sync::manager:951
Oct 24 18:20:25.386 DEBG Peer returned blob for single lookup, blob_id: BlobIdentifier { block_root: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, index: 3 }, peer_id: 16Uiu2HAmFjiQYJ1DpiLVtNTdKJJV4PFAKRhwCXYWA1GF9otoMdFa, service: sync, module: network::sync::manager:951
Oct 24 18:20:25.393 DEBG RPC blobs received, slot: 10002, block_root: 0x1eaa<E2><80><A6>7b30, indices: [0, 1, 2, 3], module: network::network_beacon_processor::sync_methods:296
Oct 24 18:20:25.401 DEBG Importing fully available block, num_blobs: 4, slot: 10002, block_root: 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30, service: beacon, modu
le: beacon_chain::beacon_chain:3117
Oct 24 18:20:25.403 DEBG Processed HTTP API request, method: GET, path: /eth/v1/node/syncing, status: 200 OK, elapsed: 913.233<C2><B5>s, module: http_api:194
Oct 24 18:20:25.435 WARN Missing components over rpc, slot: 10002, block_hash: 0x1eaa<E2><80><A6>7b30, module: network::network_beacon_processor::sync_methods:328
Oct 24 18:20:25.435 DEBG Block component processed for lookup, result: Ok(MissingComponents(Slot(10002), 0x1eaa789f91d678a371147a1853d00ed3afdd463c215e902d26c2b31d53f17b30)), response_type: Blob, service: sync, module: network::sync::block_lookups:783
Oct 24 18:20:25.463 DEBG Writing blobs to store, count: 4, block_root: 0x1eaa<E2><80><A6>7b30, service: beacon, module: beacon_chain::beacon_chain:3364
Oct 24 18:20:25.475 INFO Valid block from HTTP API, slot: 10002, proposer_index: 226916, root: 0x1eaa<E2><80><A6>7b30, block_delay: 879.135252ms, module: http_api::publish_blocks:224
Oct 24 18:20:25.482 DEBG Beacon block rejected, reason: BlockIsAlreadyKnown, service: beacon, module: beacon_chain::beacon_chain:2999
ethDreamer commented 10 months ago

I've tried to reproduce this on both devnet-11 and kurtosis. Tried multiple versions of lighthouse. I've never seen this happen. Do we have any clue what version of lighthouse produced these logs?

realbigsean commented 10 months ago

Talked about this offline with @ethDreamer , but it was likely this was an issue due to this node being send blobs via the blobber spam tool