Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

agressive disconnects on holesky #6842

Closed
macfarla opened this issue Mar 29, 2024 · 12 comments
Closed

agressive disconnects on holesky #6842

macfarla opened this issue Mar 29, 2024 · 12 comments
Labels
peering Stale

Comments

@macfarla
Copy link
Contributor

holesky has 2 bootnodes and besu is disconnecting them perhaps too aggressively

timeout threshold is 3
and useless response threshold is 5

sallymacfarlane@dev-elc-besu-teku-holesky-dev-sally-chain-head-tracker-retry:/var/log/besu$ grep USEFULL -B 3 besu.log
{"@timestamp":"2024-03-28T11:09:51,297","level":"TRACE","thread":"vert.x-eventloop-thread-1","class":"RoutingContext","message":"Calling the  handler","throwable":""}
{"@timestamp":"2024-03-28T11:09:51,297","level":"TRACE","thread":"vert.x-worker-thread-3","class":"AbstractJsonRpcExecutor","message":"{"jsonrpc":"2.0","method":"eth_getBlockByNumber","params":["0x1220d5",false],"id":1209236}","throwable":""}
{"@timestamp":"2024-03-28T11:09:51,297","level":"DEBUG","thread":"vert.x-worker-thread-3","class":"JsonRpcExecutor","message":"JSON-RPC request -> eth_getBlockByNumber ["0x1220d5",false]","throwable":""}
{"@timestamp":"2024-03-28T11:09:51,298","level":"DEBUG","thread":"nioEventLoopGroup-3-2","class":"EthPeers","message":"Disconnected USEFULL peer PeerId: 0xac906289e4b7f12d...... PeerReputation score: 141, timeouts: {15=2}, useless: 5, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode 604034444 inboundInitiated? false initAt 1711618683766], enode://ac906289e4b7f12df423d654c5a962b6ebe5b3a74cc9e06292a85221f9a64a6f1cfdd6b714ed6dacef51578f92b34c60ee91e9ede9c7f8fadc4d347326d95e2b@146.190.13.128:30303","throwable":""}
--
{"@timestamp":"2024-03-28T11:11:53,178","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837......","throwable":""}
{"@timestamp":"2024-03-28T11:11:53,178","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"PeerReputation","message":"Disconnection triggered by exceeding useless response threshold","throwable":""}
{"@timestamp":"2024-03-28T11:11:53,178","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"handleDisconnect - EthPeer PeerId: 0xa3435a0155a3e837...... PeerReputation score: 140, timeouts: {}, useless: 5, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode 1326914939 inboundInitiated? false initAt 1711618683766], enode://a3435a0155a3e837c02f5e7f5662a2f1fbc25b48e4dc232016e1c51b544cb5b4510ef633ea3278c0e970fa8ad8141e2d4d0f9f95456c537ff05fdf9b31c15072@178.128.136.233:30303","throwable":""}
{"@timestamp":"2024-03-28T11:11:53,178","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"EthPeers","message":"Disconnected USEFULL peer PeerId: 0xa3435a0155a3e837...... PeerReputation score: 140, timeouts: {}, useless: 5, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode 1326914939 inboundInitiated? false initAt 1711618683766], enode://a3435a0155a3e837c02f5e7f5662a2f1fbc25b48e4dc232016e1c51b544cb5b4510ef633ea3278c0e970fa8ad8141e2d4d0f9f95456c537ff05fdf9b31c15072@178.128.136.233:30303","throwable":""}
--
{"@timestamp":"2024-03-29T01:31:30,377","level":"TRACE","thread":"nioEventLoopGroup-3-8","class":"MessageCallProcessor","message":"Successful message call of 0x4dd449c32f6b9df455c7e1f608fff4bae4b278a3 to 0x0469760d321d08ab4fce75e2e799902c9f55da59 (Gas remaining: 16222608)","throwable":""}
{"@timestamp":"2024-03-29T01:31:30,377","level":"TRACE","thread":"nioEventLoopGroup-3-8","class":"ContractCreationProcessor","message":"Successful creation of contract 0x4dd449c32f6b9df455c7e1f608fff4bae4b278a3 with code of size 0 (Gas remaining: 16474960)","throwable":""}
{"@timestamp":"2024-03-29T01:31:30,377","level":"TRACE","thread":"EthScheduler-Timer-0","class":"EthPeer","message":"handleDisconnect - EthPeer PeerId: 0xac906289e4b7f12d...... PeerReputation score: 138, timeouts: {9=3}, useless: 2, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode -933742099 inboundInitiated? false initAt 1711674488164], enode://ac906289e4b7f12df423d654c5a962b6ebe5b3a74cc9e06292a85221f9a64a6f1cfdd6b714ed6dacef51578f92b34c60ee91e9ede9c7f8fadc4d347326d95e2b@146.190.13.128:30303","throwable":""}
{"@timestamp":"2024-03-29T01:31:30,378","level":"DEBUG","thread":"EthScheduler-Timer-0","class":"EthPeers","message":"Disconnected USEFULL peer PeerId: 0xac906289e4b7f12d...... PeerReputation score: 138, timeouts: {9=3}, useless: 2, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode -933742099 inboundInitiated? false initAt 1711674488164], enode://ac906289e4b7f12df423d654c5a962b6ebe5b3a74cc9e06292a85221f9a64a6f1cfdd6b714ed6dacef51578f92b34c60ee91e9ede9c7f8fadc4d347326d95e2b@146.190.13.128:30303","throwable":""}
@Beanow
Copy link

Beanow commented Mar 31, 2024

Possibly another heuristic that matters? When you have low peers and the peer you're evaluating is useful in discovery.

I say that because for every bootnode, there's seemingly 10 Nodecrawlers. Which may or may not be useful in discovery. So only having a low water mark might fill those up with crawlers?

@Beanow
Copy link

Beanow commented Mar 31, 2024 •
edited
Loading

🤔 the timeout might also be hit faster than expected.

When syncing we're basically waiting on a good Geth node.

Geth because...

In the context of #6805 trying to resync with 24.3.1 on holesky now.

Using Fast sync will drop all Geth connections:

Disconnecting because no capabilities are shared: PeerInfo{version=5, clientId='Geth/v1.13.11-stable/linux-amd64/go1.21.7', capabilities=[eth/67, eth/68, snap/1], port=0, nodeId=0x9a1922e592...}

Using Snap sync will drop Nethermind:

EthProtocolManager | Received status message from PeerId: 0x740d7d57f13ed2de...... PeerReputation score: 100, timeouts: {}, useless: 0, validated? true, disconnected? false, client: Nethermind/v1.25.3+e64bee70/linux-x64/dotnet8.0.1, [Connection with hashCode -1014883900 inboundInitiated? true initAt 1711893954013], enode://740d7d57f13ed2de007ee4a8c1a2d30c0a4d68dee6d4a8d7a...:30303?discport=0: StatusMessage{code=0, size=80} with connection [Connection with hashCode -1014883900 inboundInitiated? true initAt 1711893954013]
--
EthProtocolManager | Disconnect - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x740d7d57f13ed2de... - 0 peers left


2024-03-31 14:08:09.863+00:00 | nioEventLoopGroup-3-9 | DEBUG | AbstractPeerConnection | New PeerConnection ([Connection with hashCode -1908370887 inboundInitiated? false initAt 1711894089863]) established with peer 0x8934b3a537e0cad7...
2024-03-31 14:08:09.863+00:00 | nioEventLoopGroup-3-9 | DEBUG | RlpxAgent | Outbound connection established to peer: 0x8934b3a537e0cad78d44de17bcec43fa78356f921368a8c930b2b85feb46e776c65895a02c75ae1f3e256becb050bcdd6b072b8cb9bc527527c74ee730e482d6
2024-03-31 14:08:09.885+00:00 | nioEventLoopGroup-3-9 | DEBUG | EthProtocolManager | Received status message from PeerId: 0x8934b3a537e0cad7...... PeerReputation score: 100, timeouts: {}, useless: 0, validated? true, disconnected? false, client: Geth/v1.13.11-stable-8f7eb9cc/linux-amd64/go1.21.6, [Connection with hashCode -1908370887 inboundInitiated? false initAt 1711894089863], enode://8934b3a537e0cad78d44de17bcec43fa78356...:30303?discport=8624: StatusMessage{code=0, size=80} with connection [Connection with hashCode -1908370887 inboundInitiated? false initAt 1711894089863]
2024-03-31 14:08:09.885+00:00 | nioEventLoopGroup-3-9 | DEBUG | ChainHeadTracker | Requesting chain head info from 0x8934b3a537e0cad7......
2024-03-31 14:08:09.886+00:00 | nioEventLoopGroup-3-9 | DEBUG | WaitForPeerTask | Finished waiting for peer connection.
2024-03-31 14:08:09.886+00:00 | nioEventLoopGroup-3-9 | DEBUG | WaitForPeersTask | Complete: 1 peers connected.
2024-03-31 14:08:09.887+00:00 | nioEventLoopGroup-3-9 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 1 peers currently connected.
2024-03-31 14:08:09.912+00:00 | nioEventLoopGroup-3-9 | DEBUG | ChainHeadTracker | Retrieved chain head info 1253505 (0x10ba2c2a9ab9a6f65abbe52b57a751cd6cd3e00760b6bcf2c7f1107bdb310622) from 0x8934b3a537e0cad7......
2024-03-31 14:08:09.912+00:00 | nioEventLoopGroup-3-9 | DEBUG | RetryingGetHeaderFromPeerByHashTask | Get block header by hash 0x3e329825c8107cbad640e8bfbfcc9b2aeed4cc3bb4a2752f59e384778a317a14 from peer PeerId: 0x8934b3a537e0cad7...... PeerReputation score: 101, timeouts: {}, useless: 0, validated? true, disconnected? false, client: Geth/v1.13.11-stable-8f7eb9cc/linux-amd64/go1.21.6, [Connection with hashCode -1908370887 inboundInitiated? false initAt 1711894089863], enode://8934b3a537e0cad78d44de17bcec43fa78356...:30303?discport=8624 has result [BlockHeader{number=1253506, hash=0x3e329825c8107cbad640e8bfbfcc9b2aeed4cc3bb4a2752f59e384778a317a14, parentHash=0x10ba2c2a9ab9a6f65abbe52b57a751cd6cd3e00760b6bcf2c7f1107bdb310622, ommersHash=0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, coinbase=0x59ecf48345a221e0731e785ed79ed40d0a94e2a5, stateRoot=0x32a63524ba4858613bbfdec5f0661ca97945b2b79dfaa1c7582539f7542e3dd3, transactionsRoot=0x8ecb8246a932deda0588938206c96d197e57fd8e39f19034c3096041c925a1c3, receiptsRoot=0xaeac67dfff5056df7346e6a642e24090e87f5e55bad14302c0ba326a5ba309bd, logsBloom=0x00000000080001000000020000a00000400000000400400004110050000140800000000040000200000420800000000000000011008002080004000000204000000000000028000000000009000040002100080000080000000400190080000480000000020000182200210000000800082100000002002052080010012008800008000000000000080000000000008000002000000000040000000004000400130008000004010100008200010040000000000008000040400080060000400000080002000200000000000090080504002000030004201020001840100230000110000000000000000003028108001008000000000011042000601000000000, difficulty=0x0000000000000000000000000000000000000000000000000000000000000000, gasLimit=30000000, gasUsed=3412724, timestamp=1711894080, extraData=0x, baseFee=0x0000000000000000000000000000000000000000000000000000000000000007, mixHashOrPrevRandao=0xa385743d10f312cfe86178f5e81f06ab7ffc97d4aed55f97c3e8371be973fce3, nonce=0, withdrawalsRoot=0x568563f71fd44020462b623ce2161a1e23133fc4f152d65651cd5988e2a7ea7f, blobGasUsed=786432, excessBlobGas=79298560, parentBeaconBlockRoot=0x1ff35b7b98bede9f7e565563e5354301b4432ad9feee6d4484da47de66e05926, }]
2024-03-31 14:08:09.912+00:00 | nioEventLoopGroup-3-9 | DEBUG | PivotSelectorFromSafeBlock | Successfully downloaded pivot block header by hash 1253506 (0x3e329825c8107cbad640e8bfbfcc9b2aeed4cc3bb4a2752f59e384778a317a14)
--
2024-03-31 14:08:14.887+00:00 | EthScheduler-Timer-0 | DEBUG | EthPeer | Timed out while waiting for response from peer 0x8934b3a537e0cad7......
2024-03-31 14:08:14.887+00:00 | EthScheduler-Timer-0 | DEBUG | AbstractRetryingPeerTask | Retrying after recoverable failure from peer task RetryingGetAccountRangeFromPeerTask: Timeout after 5000 MILLISECONDS
2024-03-31 14:08:14.887+00:00 | EthScheduler-Timer-0 | DEBUG | EthPeer | Timed out while waiting for response from peer 0x8934b3a537e0cad7......
2024-03-31 14:08:14.887+00:00 | EthScheduler-Timer-0 | DEBUG | PeerReputation | Disconnection triggered by 3 repeated timeouts for requestCode 1
2024-03-31 14:08:14.887+00:00 | EthScheduler-Timer-0 | DEBUG | EthPeers | Disconnected EthPeer 0x8934b3a537e0cad7...
2024-03-31 14:08:14.887+00:00 | EthScheduler-Timer-0 | DEBUG | EthProtocolManager | Disconnect - Outbound - 0x0b TIMEOUT - 0x8934b3a537e0cad7... - 0 peers left
2024-03-31 14:08:14.888+00:00 | EthScheduler-Timer-0 | DEBUG | AbstractPeerConnection | Disconnecting connection -1908370887, peer 0x8934b3a537e0cad7... reason 0x0b TIMEOUT
2024-03-31 14:08:14.888+00:00 | EthScheduler-Timer-0 | DEBUG | AbstractRetryingPeerTask | Retrying after recoverable failure from peer task RetryingGetAccountRangeFromPeerTask: Timeout after 5000 MILLISECONDS
2024-03-31 14:08:14.888+00:00 | EthScheduler-Timer-0 | DEBUG | WaitForPeerTask | Waiting for new peer connection. 0 peers currently connected.
2024-03-31 14:08:14.912+00:00 | EthScheduler-Timer-0 | DEBUG | EthPeer | Timed out while waiting for response from peer 0x8934b3a537e0cad7......
2024-03-31 14:08:14.912+00:00 | EthScheduler-Timer-0 | DEBUG | PeerReputation | Disconnection triggered by 4 repeated timeouts for requestCode 1

Note the timestamps here.
We're hitting 4 timeouts of 5 seconds, in exactly 5 seconds. Possibly we're hammering parallel requests, making it more likely to cause those timeouts by increasing load on their system (or possibly get rate limited?) and then immediately dropping this peer.

Edit: also seen a few peers dropped because they were still syncing.

2024-03-31 14:36:52.924+00:00 | nioEventLoopGroup-3-2 | DEBUG | TrailingPeerLimiter | Enforcing trailing peers limit (min height 1253244, max trailing peers 0) by disconnecting 0xcb09db81f68591fc...... with height 797543

@Beanow
Copy link

Beanow commented Mar 31, 2024

I wonder if the culprit is: RetryingGetAccountRangeFromPeerTask

  1. We're requesting account ranges that seemingly can time out in 5 seconds.
TRACE | GetAccountRangeFromPeerTask | Requesting account range [0x0000000000000000000000000000000000000000000000000000000000000000 ,0x0fffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff] for state root 0xbab37fa82fed6fec0aaceb8efde3011248b69887dda41e1b24e3802f069964a0 from peer PeerId: 0xa3435a0155a3e837...... PeerReputation score: 100, timeouts: {}, useless: 0, validated? true, disconnected? false, client: Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode -568616745 inboundInitiated? false initAt 1711897982968], enode://a3435a0155a3e837c02f5...:30303 .

  1. Those requests are not rate limited in any special way, so because of a 5 requests outstanding limit per peer, we'll be often sending 3-5 of those request in parallel.

    besu/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/EthPeer.java

    Line 69 in 34fc5ee

    private static final int MAX_OUTSTANDING_REQUESTS = 5;

    Additionally the request can be retried 5 times too:

    besu/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/manager/snap/RetryingGetAccountRangeFromPeerTask.java

    Lines 45 to 46 in 34fc5ee

    super(
    ethContext, 4, data -> data.accounts().isEmpty() && data.proofs().isEmpty(), metricsSystem);

  2. Once timed out those immediately hit the reputation threshold and we initiate a disconnect.

I wonder if it's even reasonable to expect this account range to be served within 5 seconds?
Not to mention multiple of those ranges in parallel.

Perhaps if we make these ranges shorter we can both resolve the timeouts and effectively throttle these requests more by waiting on outstanding requests?

@Beanow
Copy link

Beanow commented Mar 31, 2024 •
edited
Loading

It's probably not just RetryingGetAccountRangeFromPeerTask.
I tried setting RangeManager.generateAllRanges(4096) and private static final int MAX_OUTSTANDING_REQUESTS = 3;. See Beanow@7fee906
But didn't resolve the timeout logs on them.

Instead I found there tends to be a disconnect message before with a different reason, and these pending requests fail. Being attributed as timeouts.

@jframe jframe added the peering label Apr 3, 2024
@jframe
Copy link
Contributor

jframe commented Apr 3, 2024

Possibly fixed by #6877

@Beanow
Copy link

Beanow commented Apr 5, 2024

So far seeing better success with https://github.com/hyperledger/besu/releases/tag/24.4.0-RC2 on holesky, not disconnecting the bootnodes on new instance syncing from 0.

I tried restarting it halfway through (see gap in bandwidth use) just to try and cause peer counts to drop, but never dropped below 2.

image

@macfarla
Copy link
Contributor Author

reasons for disconnects (inbound and outbound) with holesky bootnodes (running #6609 built from source)

➜  ~ grep 0xa3435a0155a3e837... disconnects-6609*
disconnects-6609-51.log:{"@timestamp":"2024-04-15T04:58:56,490","level":"DEBUG","thread":"nioEventLoopGroup-3-4","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR  - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
disconnects-6609-51.log:{"@timestamp":"2024-04-15T05:01:28,904","level":"DEBUG","thread":"nioEventLoopGroup-3-6","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Inbound - 0x10 SUBPROTOCOL_TRIGGERED  - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
disconnects-6609-52.log:{"@timestamp":"2024-04-15T04:58:56,489","level":"DEBUG","thread":"nioEventLoopGroup-3-6","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR  - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
disconnects-6609-52.log:{"@timestamp":"2024-04-15T05:01:28,939","level":"DEBUG","thread":"nioEventLoopGroup-3-10","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Inbound - 0x10 SUBPROTOCOL_TRIGGERED  - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
➜  ~ grep ac906289e4b disconnects-6609*
disconnects-6609-51.log:{"@timestamp":"2024-04-15T05:51:14,935","level":"DEBUG","thread":"nioEventLoopGroup-3-7","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR  - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
disconnects-6609-52.log:{"@timestamp":"2024-04-15T05:51:14,911","level":"DEBUG","thread":"nioEventLoopGroup-3-5","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR  - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
disconnects-6609-60.log:{"@timestamp":"2024-04-15T05:51:14,935","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR  - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 0 peers left","throwable":""}
➜  ~

Don't think there's much we can do about the TCP_SUBSYSTEM error but the incoming SUBPROTOCOL_TRIGGERED may be worth investigating

@macfarla
Copy link
Contributor Author

Further analysis from 2 sets of 3 holesky nodes
3 nodes 6609-90,6609-91,6609-92 - (running some variation of #6609) all 3 got almost in sync and then disconnected the bootnodes for useless responses

6609-90	
2024-04-16 18:39:36.064	
{"@timestamp":"2024-04-16T08:39:35,817","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 0 peers left","throwable":""}
2024-04-16 18:39:34.812	
{"@timestamp":"2024-04-16T08:39:34,743","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}

6609-91 
	
2024-04-16 18:40:58.485	
{"@timestamp":"2024-04-16T08:40:58,378","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 0 peers left","throwable":""}
2024-04-16 18:40:58.234	
{"@timestamp":"2024-04-16T08:40:58,057","level":"INFO","thread":"nioEventLoopGroup-3-10","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x10 SUBPROTOCOL_TRIGGERED - 0xba8522b5988e0bda...  - 1 peers left","throwable":""}
2024-04-16 18:40:58.234	
{"@timestamp":"2024-04-16T08:40:57,986","level":"INFO","thread":"nioEventLoopGroup-3-9","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Outbound - 0x10 SUBPROTOCOL_TRIGGERED_MISMATCHED_NETWORK - 0x46aab63552b6cde5... Geth/Indx/v1.13.14-stable-2bd6bd01/windows-amd64/go1.21.6 - 1 peers left","throwable":""}
2024-04-16 18:40:57.483	
{"@timestamp":"2024-04-16T08:40:57,305","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}

6609-92

2024-04-16 18:42:47.112	
{"@timestamp":"2024-04-16T08:42:47,037","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 0 peers left","throwable":""}
2024-04-16 18:42:46.360	
{"@timestamp":"2024-04-16T08:42:46,316","level":"INFO","thread":"nioEventLoopGroup-3-4","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x10 SUBPROTOCOL_TRIGGERED - 0x8ecba5c2582eaf81...  - 1 peers left","throwable":""}
2024-04-16 18:42:46.360	
{"@timestamp":"2024-04-16T08:42:46,121","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0xa6ba0249f383d98a... Nethermind/v1.25.4+20b10b35/linux-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 18:42:46.109	
{"@timestamp":"2024-04-16T08:42:46,039","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_FAILED_TO_RETRIEVE_CHAIN_STATE - 0xcd3032f9fc015581... Nodecrawler/v1.14.0-unstable/linux-amd64/go1.22.1 - 1 peers left","throwable":""}
2024-04-16 18:42:46.109	
{"@timestamp":"2024-04-16T08:42:45,993","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x10 SUBPROTOCOL_TRIGGERED - 0x60939b6effd4e97f...  - 2 peers left","throwable":""}
2024-04-16 18:42:46.109	
{"@timestamp":"2024-04-16T08:42:45,989","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x10 SUBPROTOCOL_TRIGGERED - 0xfdd07b5d976778fb...  - 2 peers left","throwable":""}
2024-04-16 18:42:46.109	
{"@timestamp":"2024-04-16T08:42:45,985","level":"INFO","thread":"nioEventLoopGroup-3-10","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x10 SUBPROTOCOL_TRIGGERED - 0xac3af34e41aa8acc... Geth/v0.4.2-akroma-b00f8ca4/linux-amd64/go1.11.1 - 2 peers left","throwable":""}
2024-04-16 18:42:46.109	
{"@timestamp":"2024-04-16T08:42:45,971","level":"INFO","thread":"nioEventLoopGroup-3-9","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x663f589305fb8bdf... Parity-Ethereum/v2.7.2-stable-2662d19-20200206/x86_64-unknown-linux-gnu/rustc1.41.0 - 2 peers left","throwable":""}
2024-04-16 18:42:46.109	
{"@timestamp":"2024-04-16T08:42:45,967","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 2 peers left","throwable":""}

and some relevant trace logging (from 6609-00 since I didn't have TRACE enabled on 6609-90 but I think it should be the same)

grep "useless respon" /var/log/besu/besu.log | grep -E "0xac906289e4b7f12d|a3435a0155"
{"@timestamp":"2024-04-16T08:58:32,961","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T08:58:34,470","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:00:39,203","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T09:00:42,579","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:01:48,884","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T09:01:52,674","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:04:28,219","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T09:04:29,483","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:05:32,970","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T09:05:36,754","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:06:38,803","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T09:06:41,479","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:06:51,969","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for request type bodies from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T09:07:51,934","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xa3435a0155a3e837...","throwable":""}
{"@timestamp":"2024-04-16T10:34:51,732","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type Request ID incorrect from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T10:34:51,939","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type Request ID incorrect from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T10:34:51,951","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type Request ID incorrect from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T10:34:52,014","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type Request ID incorrect from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T10:34:52,136","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type Request ID incorrect from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T10:34:52,137","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type receipts from peer 0xac906289e4b7f12d...","throwable":""}
{"@timestamp":"2024-04-16T10:34:52,137","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"Received useless response for request type headers from peer 0xac906289e4b7f12d...","throwable":""}

@macfarla
Copy link
Contributor Author

and then I started 6609-00, 6609-01, 6609-02
This time the bootnode disconnects are all TCP_SUBSYSTEM, and it seems the root cause is Connection reset
"DeFramer","message":"IO error while processing incoming message","throwable":" java.net.SocketException: Connection reset\n\tat

6609-00 (0 peers)
2024-04-16 19:08:49.945	
{"@timestamp":"2024-04-16T09:08:49,874","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 0 peers left","throwable":""}

2024-04-16 19:08:38.173	
{"@timestamp":"2024-04-16T09:08:38,041","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0x0b86588d41bc3bc9... Nethermind/v1.25.4+20b10b35/linux-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 19:08:37.925	
{"@timestamp":"2024-04-16T09:08:37,850","level":"INFO","thread":"nioEventLoopGroup-3-10","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0x76052bb42969f993... Nethermind/v1.25.4+20b10b35/windows-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 19:08:17.389	
{"@timestamp":"2024-04-16T09:08:17,284","level":"INFO","thread":"nioEventLoopGroup-3-9","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0x79a46b0301ec1a41... Nethermind/v1.25.4+20b10b35/linux-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 19:08:11.875	
{"@timestamp":"2024-04-16T09:08:11,759","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0x84df2c2b76627b3f... Nethermind/v1.25.4+20b10b35/linux-x64/dotnet8.0.2 - 1 peers left","throwable":""}

2024-04-16 19:07:36.799	
{"@timestamp":"2024-04-16T09:07:36,658","level":"INFO","thread":"nioEventLoopGroup-3-10","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xa30d57d6c6f548e6... bor/v1.2.7/linux-amd64/go1.20.14 - 1 peers left","throwable":""}
2024-04-16 19:07:24.528	
{"@timestamp":"2024-04-16T09:07:24,510","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0x84df2c2b76627b3f... Nethermind/v1.25.4+20b10b35/linux-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 19:07:11.959	
{"@timestamp":"2024-04-16T09:07:11,760","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0x76052bb42969f993... Nethermind/v1.25.4+20b10b35/windows-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 19:07:11.714	
{"@timestamp":"2024-04-16T09:07:11,592","level":"INFO","thread":"nioEventLoopGroup-3-9","class":"EthProtocolManager","message":"Disconnect - active Connection? false - Inbound - 0x04 TOO_MANY_PEERS - 0x276df8ae88dbdb4f... Nethermind/v1.25.4+20b10b35/linux-x64/dotnet8.0.2 - 1 peers left","throwable":""}
2024-04-16 19:06:52.174	
{"@timestamp":"2024-04-16T09:06:51,972","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left

{"@timestamp":"2024-04-16T09:06:51,968","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"DeFramer","message":"IO error while processing incoming message","throwable":" java.net.SocketException: Connection reset\n\tat java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.ja
va:401)\n\tat java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:434)\n\tat io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:255)\n\tat io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)\n\tat io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketCha
nnel.java:357)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)\n\tat io.netty.
channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.j
ava:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:1583)\n"}
{"@timestamp":"2024-04-16T09:06:51,969","level":"TRACE","thread":"vert.x-eventloop-thread-3","class":"RouterImpl","message":"Router: 1447574546 accepting request POST http://127.0.0.1:8551/","throwable":""}
{"@timestamp":"2024-04-16T09:06:51,969","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"handleDisconnect - EthPeer PeerId: 0xac906289e4b7f12d... PeerReputation score: 150, timeouts: {}, useless: 1, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/lin
ux-amd64/go1.21.7, [Connection with hashCode 1941467636 inboundInitiated? false initAt 1713256630206], enode://ac906289e4b7f12df423d654c5a962b6ebe5b3a74cc9e06292a85221f9a64a6f1cfdd6b714ed6dacef51578f92b34c60ee91e9ede9c7f8fadc4d347326d95e2b@146.190.13.128:30303, isServingSNAP true, has height 1357124, conn
ected for 1781763 ms","throwable":""}

6609-01 (3 peers)
 stacks of IO exceptions

{"@timestamp":"2024-04-16T09:06:51,869","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 2 peers left","throwable":""}
{"@timestamp":"2024-04-16T09:08:49,862","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 2 peers left","throwable":""}

6609-02 (0 peers)
over last 30 min, all disconnects are outbound, with TCP_SUBSYSTEM_ERROR and some IO exceptions. both bootnodes disconnected with IO Exception (Connection reset)
	
2024-04-16 19:08:50.075	
{"@timestamp":"2024-04-16T09:08:49,861","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xa3435a0155a3e837... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 0 peers left","throwable":""}
2024-04-16 19:06:52.110	
{"@timestamp":"2024-04-16T09:06:51,890","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x01 TCP_SUBSYSTEM_ERROR - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}

{"@timestamp":"2024-04-16T09:06:51,880","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"DeFramer","message":"IO error while processing incoming message","throwable":" java.net.SocketException: Connection reset\n\tat java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.ja
va:401)\n\tat java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:434)\n\tat io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:255)\n\tat io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)\n\tat io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketCha
nnel.java:357)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)\n\tat io.netty.
channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.j
ava:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:1583)\n"}
{"@timestamp":"2024-04-16T09:06:51,886","level":"TRACE","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"handleDisconnect - EthPeer PeerId: 0xac906289e4b7f12d... PeerReputation score: 150, timeouts: {}, useless: 1, validated? true, disconnected? true, client: Geth/v1.13.14-stable-2bd6bd01/lin
ux-amd64/go1.21.7, [Connection with hashCode 1597405836 inboundInitiated? false initAt 1713256648171], enode://ac906289e4b7f12df423d654c5a962b6ebe5b3a74cc9e06292a85221f9a64a6f1cfdd6b714ed6dacef51578f92b34c60ee91e9ede9c7f8fadc4d347326d95e2b@146.190.13.128:30303, isServingSNAP true, has height 1357124, conn
ected for 1763715 ms","throwable":""}

{"@timestamp":"2024-04-16T09:08:49,860","level":"DEBUG","thread":"nioEventLoopGroup-3-2","class":"DeFramer","message":"IO error while processing incoming message","throwable":" java.net.SocketException: Connection reset\n\tat java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.ja
va:401)\n\tat java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:434)\n\tat io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:255)\n\tat io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)\n\tat io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketCha
nnel.java:357)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)\n\tat io.netty.
channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.j
ava:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:1583)\n"}
{"@timestamp":"2024-04-16T09:08:49,861","level":"TRACE","thread":"nioEventLoopGroup-3-2","class":"EthPeer","message":"handleDisconnect - EthPeer PeerId: 0xa3435a0155a3e837... PeerReputation score: 145, timeouts: {3=1, 5=2, 15=2}, useless: 1, validated? true, disconnected? true, client: Geth/v1.13.14-stabl
e-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode 706370143 inboundInitiated? false initAt 1713256648166], enode://a3435a0155a3e837c02f5e7f5662a2f1fbc25b48e4dc232016e1c51b544cb5b4510ef633ea3278c0e970fa8ad8141e2d4d0f9f95456c537ff05fdf9b31c15072@178.128.136.233:30303, isServingSNAP true, has height
 1357148, connected for 1881695 ms","throwable":""}
{"@timestamp":"2024-04-16T09:08:49,861","level":"DEBUG","thread":"nioEventLoopGroup-3-2","class":"EthPeers","message":"Disconnected USEFUL peer PeerId: 0xa3435a0155a3e837... PeerReputation score: 145, timeouts: {3=1, 5=2, 15=2}, useless: 1, validated? true, disconnected? true, client: Geth/v1.13.14-stable
-2bd6bd01/linux-amd64/go1.21.7, [Connection with hashCode 706370143 inboundInitiated? false initAt 1713256648166], enode://a3435a0155a3e837c02f5e7f5662a2f1fbc25b48e4dc232016e1c51b544cb5b4510ef633ea3278c0e970fa8ad8141e2d4d0f9f95456c537ff05fdf9b31c15072@178.128.136.233:30303, isServingSNAP true, has height
1357148, connected for 1881695 ms","throwable":""}

@macfarla
Copy link
Contributor Author

since they both had zero peers, on 6609-00 and 6609-02 I forcibly added (using admin_addPeer) the 2 holesky bootnodes as peers. So now besu will try to reconnect even if we drop them - and we still are dropping them. But now the reason is useless responses.
eg

6609-00

{"@timestamp":"2024-04-16T10:34:52,139","level":"INFO","thread":"nioEventLoopGroup-3-2","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}
6609-02
{"@timestamp":"2024-04-16T10:34:47,846","level":"INFO","thread":"nioEventLoopGroup-3-10","class":"EthProtocolManager","message":"Disconnect - active Connection? true - Outbound - 0x03 USELESS_PEER_USELESS_RESPONSES - 0xac906289e4b7f12d... Geth/v1.13.14-stable-2bd6bd01/linux-amd64/go1.21.7 - 1 peers left","throwable":""}

6609-90 also has 0 peers but will leave it going overnight to see if it discovers some

@macfarla macfarla mentioned this issue Apr 19, 2024
Closed
8 tasks
@github-actions GitHub Actions
Copy link

This issue is stale because it has been open for 6 months with no activity.

@github-actions github-actions bot added the Stale label Nov 23, 2024
@github-actions GitHub Actions
Copy link

github-actions bot commented Dec 7, 2024

This issue was closed because it has been inactive for 14 days since being marked as stale.

@github-actions github-actions bot closed this as completed Dec 7, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
peering Stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Beanow @jframe @macfarla