search

status-im / nimbus-eth2

Nim implementation of the Ethereum Beacon Chain
https://nimbus.guide
Other
530 stars 230 forks source link

Connections closed early #1668

Closed sinkingsugar closed 3 years ago

sinkingsugar commented 4 years ago

Testing via multinet I noticed that we often emit attestations for unknown blocks, by checking Lighthouse logs.

Some extracts here:

PS E:\develop\status\multinet> kubectl.exe logs lighthouse-4 -c lighthouse -f | Select-String "16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN"

Sep 16 05:22:42.264 DEBG Connection established                  connection: Incoming, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:22:42.265 DEBG Requesting new peer's metadata          peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p_rpc, service: libp2p
Sep 16 05:22:42.325 DEBG Obtained peer's metadata                new_seq_no: 0, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:22:42.397 DEBG Received Status Request                 head_slot: 0, head_root: 0xa678…f08d, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer: 
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:22:42.397 DEBG Peer with known chain found             remote_latest_finalized_epoch: 0, remote_head_slot: 0, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:22:42.744 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.126/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:24:12.464 DEBG Requesting new metadata from peer       pong_seq_no: 1, known_seq_no: 0, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:24:12.514 DEBG Updating peer's metadata                new_seq_no: 1, known_seq_no: 0, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:27:42.398 DEBG Sending Status Request                  head_slot: 36, head_root: 0xa5e4…f2de, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer: 
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:27:42.454 DEBG Received Status Response                head_slot: 28, head_root: 0x8604…b9b7, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer_id:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:27:42.454 DEBG Peer with known chain found             remote_latest_finalized_epoch: 0, remote_head_slot: 28, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:27:42.699 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.126/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:32:42.456 DEBG Sending Status Request                  head_slot: 86, head_root: 0xa189…cc72, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer: 
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:32:42.457 DEBG Received Status Response                head_slot: 86, head_root: 0xa35c…e50b, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer_id:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:32:42.457 DEBG Peer with known chain found             remote_latest_finalized_epoch: 0, remote_head_slot: 86, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:32:42.699 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.126/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:53.023 DEBG Attestation for unknown block           block: 0x31cf…f418, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:36:54.956 DEBG RPC Error                               score: 0.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:54.956 DEBG Peer score adjusted                     score: -5.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:54.956 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 38, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.142 DEBG RPC Error                               score: -5.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.142 DEBG Peer score adjusted                     score: -10.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.142 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 39, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.163 DEBG RPC Error                               score: -10.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.163 DEBG Peer score adjusted                     score: -15.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.163 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 40, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.180 DEBG RPC Error                               score: -15.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.180 DEBG Peer transitioned to disconnect state   past_state: Healthy, score: -20.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.180 DEBG PeerManager disconnecting peer          reason: Bad Score, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.180 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 41, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.180 DEBG RPC Error                               score: -20.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Handler rejected the request, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.180 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Handler rejected the request, request_id: 42, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.180 DEBG Sync reporting peer                     action: Low Tolerance Error, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: sync
Sep 16 05:36:55.180 DEBG Peer score adjusted                     score: -30.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.198 DEBG Connection closed                       connections: 0, cause: Some(Handler(Handler(Disconnected))), peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:42:31.770 DEBG Peer transitioned to healthy state      past_state: Disconnected, score: -19.93, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:00.164 DEBG Connection established                  connection: Incoming, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:00.165 DEBG Requesting new peer's metadata          peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p_rpc, service: libp2p
Sep 16 05:50:00.761 DEBG Received old metadata                   new_seq_no: 0, known_seq_no: 1, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:01.021 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.126/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:02.857 DEBG Received Status Request                 head_slot: 43, head_root: 0x85be…0ce7, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:50:02.857 DEBG NaivePeer                               reason: lower finalized epoch, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:51:10.447 DEBG RPC Error                               score: -11.17, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Negotiation timeout, protocol: ping, service: libp2p
Sep 16 05:51:10.447 DEBG Peer score adjusted                     score: -12.17, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:51:40.334 DEBG RPC Error                               score: -11.77, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Negotiation timeout, protocol: ping, service: libp2p
Sep 16 05:51:40.334 DEBG Peer score adjusted                     score: -12.77, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:52:33.307 DEBG Attestation for unknown block           block: 0x7dd6…8c25, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:52:39.246 DEBG Attestation for unknown block           block: 0x0d6f…8a9a, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:52:59.067 DEBG Connection closed                       connections: 0, cause: Some(IO(Custom { kind: ConnectionReset, error: "Connection reset by peer (os error 104)" })), peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p

and

PS E:\develop\status\multinet> kubectl.exe logs lighthouse-0 -c lighthouse -f | Select-String "16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN"

Sep 16 05:22:42.264 DEBG Connection established                  connection: Incoming, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:22:42.264 DEBG Requesting new peer's metadata          peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p_rpc, service: libp2p
Sep 16 05:22:42.325 DEBG Obtained peer's metadata                new_seq_no: 0, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:22:42.397 DEBG Received Status Request                 head_slot: 0, head_root: 0xa678…f08d, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:22:42.397 DEBG Peer with known chain found             remote_latest_finalized_epoch: 0, remote_head_slot: 0, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:22:42.744 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.116/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:24:12.374 DEBG Requesting new metadata from peer       pong_seq_no: 1, known_seq_no: 0, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:24:12.424 DEBG Updating peer's metadata                new_seq_no: 1, known_seq_no: 0, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:27:42.398 DEBG Sending Status Request                  head_slot: 36, head_root: 0xa5e4…f2de, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:27:42.446 DEBG Received Status Response                head_slot: 28, head_root: 0x8604…b9b7, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer_id:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:27:42.446 DEBG Peer with known chain found             remote_latest_finalized_epoch: 0, remote_head_slot: 28, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:27:42.698 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.116/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:32:42.448 DEBG Sending Status Request                  head_slot: 86, head_root: 0xa189…cc72, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer: 
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:32:42.452 DEBG Received Status Response                head_slot: 86, head_root: 0xa35c…e50b, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer_id:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:32:42.452 DEBG Peer with known chain found             remote_latest_finalized_epoch: 0, remote_head_slot: 86, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:32:42.698 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.116/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:53.039 DEBG Attestation for unknown block           block: 0x31cf…f418, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:36:54.997 DEBG RPC Error                               score: 0.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:54.997 DEBG Peer score adjusted                     score: -5.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:54.997 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 38, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.157 DEBG RPC Error                               score: -5.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.157 DEBG Peer score adjusted                     score: -10.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.157 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 39, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.174 DEBG RPC Error                               score: -10.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.174 DEBG Peer score adjusted                     score: -15.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.174 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 40, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.196 DEBG RPC Error                               score: -15.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Stream ended unexpectedly, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.197 DEBG Peer transitioned to disconnect state   past_state: Healthy, score: -20.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.197 DEBG PeerManager disconnecting peer          reason: Bad Score, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.197 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Stream ended unexpectedly, request_id: 41, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.197 DEBG RPC Error                               score: -20.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, client: Nimbus: version: 0.0.1, os_version: unknown, err: Handler rejected the request, protocol: beacon_blocks_by_root, service: libp2p
Sep 16 05:36:55.197 DEBG RPC Error                               client: Nimbus: version: 0.0.1, os_version: unknown, error: Handler rejected the request, request_id: 42, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: router
Sep 16 05:36:55.197 DEBG Sync reporting peer                     action: Low Tolerance Error, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: sync
Sep 16 05:36:55.197 DEBG Peer score adjusted                     score: -30.00, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:36:55.254 DEBG Connection closed                       connections: 0, cause: Some(Handler(Handler(Disconnected))), peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:42:32.328 DEBG Peer transitioned to healthy state      past_state: Disconnected, score: -19.93, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:00.031 DEBG Connection established                  connection: Incoming, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:00.031 DEBG Requesting new peer's metadata          peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p_rpc, service: libp2p
Sep 16 05:50:00.534 DEBG Received old metadata                   new_seq_no: 0, known_seq_no: 1, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:00.899 DEBG Identified Peer                         protocols: [], observed_address: "/ip4/10.1.5.116/tcp/50001", listening_ addresses: ["/ip4/0.0.0.0/tcp/9000"], agent_version: nim-libp2p/0.0.1, protocol_version: ipfs/0.1.0, peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:50:02.814 DEBG Received Status Request                 head_slot: 42, head_root: 0xc626…090e, finalized_epoch: Epoch(0), finalized_root: 0x0000000000000000000000000000000000000000000000000000000000000000, fork_digest: [55, 253, 78, 231], peer:
16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:50:02.814 DEBG NaivePeer                               reason: lower finalized epoch, peer: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:52:11.790 DEBG Attestation for unknown block           block: 0x7dd6…8c25, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:52:18.857 DEBG Attestation for unknown block           block: 0x0d6f…8a9a, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:52:20.651 DEBG Attestation for unknown block           block: 0x0d6f…8a9a, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN
Sep 16 05:52:58.811 DEBG Sync reporting peer                     action: Low Tolerance Error, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: sync
Sep 16 05:52:58.811 DEBG Peer transitioned to disconnect state   past_state: Healthy, score: -20.12, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:52:58.811 DEBG PeerManager disconnecting peer          reason: Bad Score, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:52:58.866 DEBG Connection closed                       connections: 0, cause: Some(IO(Kind(BrokenPipe))), peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
Sep 16 05:53:02.327 DEBG Peer transitioned to healthy state      past_state: Disconnected, score: -19.45, peer_id: 16Uiu2HAmMn9e9zjuUfCrsBrH3Kzqsm4ALHEPJrN5u49RSW38ZZBN, service: libp2p
arnetheduck commented 4 years ago

The attestations messages here are fine - the more problematic issues are the RPC error logs which indicate we're not fully sending data, and the subsequent descoring.

sinkingsugar commented 4 years ago

@arnetheduck some updates:

major

Sep 29 23:57:18.144 DEBG Received BlocksByRoot Request           returned: 1, requested: 1, peer: 16Uiu2HAmFSvNoxtKJpKCTC9AqKYiRL6zHFVX3SibBR4Cf7f3bUHB
Sep 29 23:57:18.146 DEBG RPC Error                               score: 0.00, peer_id: 16Uiu2HAmFSvNoxtKJpKCTC9AqKYiRL6zHFVX3SibBR4Cf7f3bUHB, client: Nimbus: version: 0.0.1, os_version: unknown, err: Internal error: Sending responses to closed inbound substream, protocol: beacon_blocks_by_root, service: libp2p

minor:

Sep 30 01:16:12.769 DEBG RPC Error                               score: -2.66, peer_id: 16Uiu2HAm9tFkvT3ZzGFLMRnQb5FZXbhUR3AyjiHhgKQ7g3Bqm9co, client: Nimbus: version: 0.0.1, os_version: unknown, err: Negotiation timeout, protocol: ping, service: libp2p

So yeah not much to add, will try to trace LH

sinkingsugar commented 4 years ago

tl;dr both logs show it's something related to BlocksByRoot

sinkingsugar commented 4 years ago

I've asked about this. in terms of LH perspective it would seem that we closed our end of the stream too early.

arnetheduck commented 4 years ago

is this still happening with the latest nimbus?

arnetheduck commented 4 years ago

also, "too early" would need to be more precise: in mplex, are they saying we send the "close" message before the request is through or something else?

sinkingsugar commented 4 years ago

Quoting the answer to "how bad is this log"

Its either you closed your end too early or we took to long to respond. We don't penalize very harshly for it We keep track of the time. So if we shouldn't try and respond after the timeout. So it means from our perspective you closed your end of the stream early

I definitely see them still in devel, but might just be my gossip wip branch , Altho this issue is eth2 rpcs no? So not gossip related afaik