search

sigp / lighthouse

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

CRIT error beacon_block_streamer: request not found #5506

Open winksaville opened 3 months ago

winksaville commented 3 months ago

Description

Saw CRIT "request not found" in logs it says to report it so I am:

kendall@ethel 24-04-01T16:38:48.259Z:~/reth-lighthouse-issues/2024-04-01-CRIT
$ rg CRIT beacon/beacon.log.1 
806490:Apr 01 11:45:09.051 CRIT Please notify the devs, root: 0xa6f7e84bdf79e0c2a9230211d1b248ac6c3d51a9bf4a9c4ff3a02949f8bd99a0, beacon_block_streamer: request not found, service: beacon, module: beacon_chain::beacon_block_streamer:523
kendall@ethel 24-04-01T16:39:07.562Z:~/reth-lighthouse-issues/2024-04-01-CRIT

Version

kendall@ethel 24-04-01T16:21:41.379Z:~
$ printf "\nreth --version:\n" && ~/bin/reth --version && printf "\nlighthouse --version:\n" && lighthouse --version && printf "\ninxi:\n" && inxi && printf "\nlsb_release -a:\n" &&  lsb_release -a && printf "\ndf -h:\n" && df -h

reth --version:
reth Version: 0.2.0-beta.4
Commit SHA: c04dbe6e9
Build Timestamp: 2024-03-27T17:50:28.869727319Z
Build Features: jemalloc
Build Profile: release

lighthouse --version:
Lighthouse v5.1.3-3058b96
BLS library: blst-modern
SHA256 hardware acceleration: false
Allocator: jemalloc
Profile: maxperf
Specs: mainnet (true), minimal (false), gnosis (true)

inxi:
CPU: quad core Intel Core i5-8259U (-MT MCP-) speed/min/max: 626/400/3800 MHz
Kernel: 6.5.0-26-generic x86_64 Up: 3d 23h 56m
Mem: 6511.0/31953.5 MiB (20.4%) Storage: 2.73 TiB (7.6% used) Procs: 256
Shell: Bash inxi: 3.3.13

lsb_release -a:
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.4 LTS
Release:    22.04
Codename:   jammy

df -h:
Filesystem      Size  Used Avail Use% Mounted on
tmpfs           3.2G  1.9M  3.2G   1% /run
/dev/nvme0n1p2  916G   58G  812G   7% /
tmpfs            16G     0   16G   0% /dev/shm
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
efivarfs        192K   59K  129K  32% /sys/firmware/efi/efivars
/dev/nvme0n1p1  511M  6.1M  505M   2% /boot/efi
/dev/sda1       1.8T  156G  1.6T   9% /home/kendall/eth2-data
tmpfs           3.2G  108K  3.2G   1% /run/user/125
tmpfs           3.2G   96K  3.2G   1% /run/user/1000
kendall@ethel 24-04-01T16:47:59.299Z:~

Present Behaviour

Everything appears to be ok, will be providing logs shortly.

winksaville commented 3 months ago

Here are logs from reth and lighthouse

ethDreamer commented 3 months ago

Just keeping notes as I go.. This happened on the holesky testnet. Relevant logs:

Apr 01 11:45:08.644 DEBG Received BlocksByRange Request, start_slot: 642592, count: 32, peer_id: 16Uiu2HAmMDQmpbdwJLkHuvhcUAtUdPrHwBbMZpN8ej988LafSf87, module: network::network_beacon_processor::rpc_methods:341
Apr 01 11:45:08.872 DEBG Launching a BeaconBlockStreamer, blocks: 30, service: beacon, module: beacon_chain::beacon_block_streamer:651
Apr 01 11:45:09.051 CRIT Please notify the devs, root: 0xa6f7e84bdf79e0c2a9230211d1b248ac6c3d51a9bf4a9c4ff3a02949f8bd99a0, beacon_block_streamer: request not found, service: beacon, module: beacon_chain::beacon_block_streamer:523
Apr 01 11:45:09.158 DEBG Advanced head state one slot, current_slot: 1339125, state_slot: 1339126, head_root: 0xc2056ee698d2d4e881de23093e8e1a6e1adecb686382292771c95787095e4451, service: state_advance, module: beacon_chain::state_advance_timer:418
Apr 01 11:45:09.158 DEBG Completed state advance, initial_slot: 1339125, advanced_slot: 1339126, head_root: 0xc2056ee698d2d4e881de23093e8e1a6e1adecb686382292771c95787095e4451, service: state_advance, module: beacon_chain::state_advance_timer:514
Apr 01 11:45:09.408 DEBG BeaconBlockStreamer finished, engine requests: 1, failed: 1, succeeded: 29, sent: 30, requested blocks: 30, service: beacon, module: beacon_chain::beacon_block_streamer:608
Apr 01 11:45:09.415 ERRO Error fetching block for peer, error: BlockStreamerError(RequestNotFound), block_root: 0xa6f7e84bdf79e0c2a9230211d1b248ac6c3d51a9bf4a9c4ff3a02949f8bd99a0, module: network::network_beacon_processor::rpc_methods:513

link to problem block

ethDreamer commented 3 months ago

there's also a second instance:

Mar 25 18:59:42.286 DEBG Received BlocksByRange Request, start_slot: 670368, count: 32, peer_id: 16Uiu2HAmT1bf8VQDqZkreLnJ5iH4LHGEdZSFv9QiWYw74McdZnQw, module: network::network_beacon_processor::rpc_methods:342
...
Mar 25 18:59:42.493 DEBG Launching a BeaconBlockStreamer, blocks: 30, service: beacon, module: beacon_chain::beacon_block_streamer:651
Mar 25 18:59:42.503 DEBG Obtained peer's metadata, new_seq_no: 691, peer_id: 16Uiu2HAmR4MiEaPfwgYFwXw8TBvXRuc7xNZpzV56r6hq5LR3C1nZ, service: libp2p, module: lighthouse_network::peer_manager:698
Mar 25 18:59:42.516 DEBG Obtained peer's metadata, new_seq_no: 42, peer_id: 16Uiu2HAmQd848bGFeLp9auR4ksbpKHJHNCJa4kHm32ZBqVkhUcsp, service: libp2p, module: lighthouse_network::peer_manager:698
Mar 25 18:59:42.519 DEBG Obtained peer's metadata, new_seq_no: 97, peer_id: 16Uiu2HAmDw25Z3h6FVAVg9Uk5KQ4sMFLzgDTUUH7evMZSD5ANuXU, service: libp2p, module: lighthouse_network::peer_manager:698
Mar 25 18:59:42.521 DEBG Received Status Response, fork_digest: [105, 174, 14, 153], finalized_epoch: 40338, finalized_root: 0x6e58…20f5, head_slot: 1290898, head_root: 0x9abe…fadc, peer_id: 16Uiu2HAmDw25Z3h6FVAVg9Uk5KQ4sMFLzgDTUUH7evMZSD5ANuXU, service: router, module: network::router:235
Mar 25 18:59:42.619 DEBG Received Status Response, fork_digest: [105, 174, 14, 153], finalized_epoch: 40338, finalized_root: 0x6e58…20f5, head_slot: 1290898, head_root: 0x9abe…fadc, peer_id: 16Uiu2HAm899ELSUs4tBh4dy2iej9nUPLoeqEijNdbZHpHEbnwgsE, service: router, module: network::router:235
Mar 25 18:59:42.674 CRIT Please notify the devs, root: 0xa52acce9cfb461891bef667f3c3d009dd083463eea5c3275e58f53d8a4a21f69, beacon_block_streamer: request not found, service: beacon, module: beacon_chain::beacon_block_streamer:523
Mar 25 18:59:42.709 DEBG Connection established, connection: Dialer, multiaddr: /ip4/109.199.111.231/tcp/13000/p2p/16Uiu2HAmFLTGb23tubwqVgU8NAbh4gyVm3CAj8ikLZ8Efk5GrbtU, peer_id: 16Uiu2HAmFLTGb23tubwqVgU8NAbh4gyVm3CAj8ikLZ8Efk5GrbtU, service: libp2p, module: lighthouse_network::peer_manager::network_behaviour:237
Mar 25 18:59:42.709 DEBG Sending Status Request, fork_digest: [105, 174, 14, 153], finalized_epoch: 40338, finalized_root: 0x6e58…20f5, head_slot: 1290898, head_root: 0x9abe…fadc, peer: 16Uiu2HAmFLTGb23tubwqVgU8NAbh4gyVm3CAj8ikLZ8Efk5GrbtU, service: router, module: network::router:423
Mar 25 18:59:42.859 DEBG Obtained peer's metadata, new_seq_no: 1, peer_id: 16Uiu2HAmFLTGb23tubwqVgU8NAbh4gyVm3CAj8ikLZ8Efk5GrbtU, service: libp2p, module: lighthouse_network::peer_manager:698
Mar 25 18:59:42.859 DEBG Identified Peer, protocols: ["/eth2/beacon_chain/req/beacon_blocks_by_range/2/ssz_snappy", "/eth2/beacon_chain/req/beacon_blocks_by_root/2/ssz_snappy", "/eth2/beacon_chain/req/blob_sidecars_by_range/1/ssz_snappy", "/eth2/beacon_chain/req/blob_sidecars_by_root/1/ssz_snappy", "/eth2/beacon_chain/req/goodbye/1/ssz_snappy", "/eth2/beacon_chain/req/metadata/2/ssz_snappy", "/eth2/beacon_chain/req/ping/1/ssz_snappy", "/eth2/beacon_chain/req/status/1/ssz_snappy", "/floodsub/1.0.0", "/ipfs/id/1.0.0", "/ipfs/id/push/1.0.0", "/meshsub/1.0.0", "/meshsub/1.1.0"], observed_address: "/ip4/23.119.164.150/tcp/48652", listening_addresses: ["/ip4/109.199.111.231/tcp/13000", "/ip4/172.23.0.12/tcp/13000"], agent_version: Prysm/v5.0.1/a1a81d1720a0a3b850992d4825d0a023baa8e65a, protocol_version: , peer: 16Uiu2HAmFLTGb23tubwqVgU8NAbh4gyVm3CAj8ikLZ8Efk5GrbtU, service: libp2p, module: lighthouse_network::peer_manager:460
Mar 25 18:59:42.900 DEBG BeaconBlockStreamer finished, engine requests: 1, failed: 1, succeeded: 29, sent: 30, requested blocks: 30, service: beacon, module: beacon_chain::beacon_block_streamer:608
Mar 25 18:59:42.901 ERRO Error fetching block for peer, error: BlockStreamerError(RequestNotFound), block_root: 0xa52acce9cfb461891bef667f3c3d009dd083463eea5c3275e58f53d8a4a21f69, module: network::network_beacon_processor::rpc_methods:514

link to problem block