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

Investigate Connect/Disconnect Events Ordering #4091

Closed
iamhsk opened this issue Jul 13, 2022 · 8 comments
Closed

Investigate Connect/Disconnect Events Ordering #4091

iamhsk opened this issue Jul 13, 2022 · 8 comments
Assignees
@macfarla
Labels
mainnet peering TeamRevenant GH issues worked on by Revenant Team

Comments

@iamhsk
Copy link

iamhsk commented Jul 13, 2022 •
edited by mbaxter
Loading

This may help identifying the problems with #2689

Per @mbaxter's comment:
There could be a race condition wrt how connect and disconnect events are dispatched. For example, say we’re in the process of handling a new connection and in another thread, we receive a disconnect message from the newly connected peer. Is it possible we’re dispatching the disconnect event before the connection event? This would cause stale, disconnected peers to persist in the EthPeers collection. If this is actually the issue, it should be possible to rework disconnect events so that they are only dispatched after the connection event is dispatched.
@iamhsk iamhsk added the TeamRevenant GH issues worked on by Revenant Team label Jul 13, 2022
@macfarla macfarla self-assigned this Jul 13, 2022
@macfarla
Copy link
Contributor

it broke some ATs but it works locally with my 3 nodes setup trying this one out in goerli #4100

@macfarla
Copy link
Contributor

Running up RC2 (with and without this change #4100) on local setup, goerli and mainnet to see if the "stale disconnected peers" is still a problem.

@macfarla
Copy link
Contributor

macfarla commented Jul 21, 2022 •
edited
Loading

Locally - RC2 locally with besu-local-nodes setup (3 x besu, one is a bootnode for the other 2) - I still get the stale disconnected duplicate every time (on the bootnode)

2022-07-21 11:23:55.746+10:00 | nioEventLoopGroup-3-4 | DEBUG | EthProtocolManager | Disconnect - Outbound - 0x05 ALREADY_CONNECTED - PeerInfo{version=5, clientId='besu/v22.7.0-dev-1ff3967d/osx-x86_64/openjdk-java-11', capabilities=[eth/63, eth/64, eth/65, eth/66, snap/1], port=50505, nodeId=0xdcb9390953aec5dde1d60dd556c36827053ca9adaefd1b03f531592fea43824bae2919743f620bb8a9b6c2b9a54439771d4f9a74d261b74af7a10c2dd9f13c97} - 2 peers left
2022-07-21 11:23:55.746+10:00 | nioEventLoopGroup-3-4 | TRACE | EthProtocolManager | 2 EthPeers {
Peer 0x3548c87b9920ff16aa... PeerReputation 100, validated? true, disconnected? true,
Peer 0x3548c87b9920ff16aa... PeerReputation 101, validated? true, disconnected? false}
2022-07-21 11:23:55.746+10:00 | nioEventLoopGroup-3-4 | TRACE | RlpxAgent | 2 ConnectionsById {
RemotelyInitiatedRlpxConnection initiatedAt:1658366625488 to 0x3548c87b9920ff16aa4bdcf01c85f25117a29ae1574d759bad48cc9463d8e9f7c3c1d1e9fb0d28e73898951f90e02714abb770fd6d22e90371882a45658800e9 disconnected? false,
RemotelyInitiatedRlpxConnection initiatedAt:1658366635743 to 0xdcb9390953aec5dde1d60dd556c36827053ca9adaefd1b03f531592fea43824bae2919743f620bb8a9b6c2b9a54439771d4f9a74d261b74af7a10c2dd9f13c97 disconnected? false}
2022-07-21 11:23:55.747+10:00 | nioEventLoopGroup-3-4 | DEBUG | EthProtocolManager | Sending status message to Peer 0xdcb9390953aec5dde1... PeerReputation 100, validated? true, disconnected? false.
2022-07-21 11:23:55.748+10:00 | nioEventLoopGroup-3-4 | TRACE | EthProtocolManager | 3 EthPeers {
Peer 0x3548c87b9920ff16aa... PeerReputation 100, validated? true, disconnected? true,
Peer 0xdcb9390953aec5dde1... PeerReputation 100, validated? true, disconnected? false,
Peer 0x3548c87b9920ff16aa... PeerReputation 101, validated? true, disconnected? false}

@macfarla
Copy link
Contributor

macfarla commented Jul 21, 2022 •
edited
Loading

mainnet with RC2
zero stale peers after 1 hour
the only results for this grep are responses from disconnected peers - which can happen

mainnet-dev-sally-eth-peers-80369e81:~$ grep "validated? true, disconnected? true" /var/log/besu/besu.log
2022-07-21 00:46:24.398+00:00 | EthScheduler-Transactions-1 | DEBUG | EthPeer | Received useless response for receipts from peer Peer 0xfb9e83d5069af7bc33... PeerReputation 954, validated? true, disconnected? true
2022-07-21 00:49:19.451+00:00 | nioEventLoopGroup-3-3 | DEBUG | EthPeer | Received useless response for receipts from peer Peer 0x5d17c5c0bfc1507098... PeerReputation 188, validated? true, disconnected? true
2022-07-21 00:53:23.829+00:00 | nioEventLoopGroup-3-6 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0x4f74b1a923d042983d... PeerReputation 1150, validated? true, disconnected? true
2022-07-21 01:17:42.185+00:00 | nioEventLoopGroup-3-7 | DEBUG | EthPeer | Received useless response for receipts from peer Peer 0x916be8495734b1641f... PeerReputation 4145, validated? true, disconnected? true

This grep for validated false does return some stale peers - but again, they are transient.

grep "validated? false, disconnected? true" /var/log/besu/besu.log > tmp.txt
sallymacfarlane@mainnet-dev-sally-eth-peers-80369e81:~$ cat tmp.txt  | wc -l
5488
sallymacfarlane@mainnet-dev-sally-eth-peers-80369e81:~$ less tmp.txt
sallymacfarlane@mainnet-dev-sally-eth-peers-80369e81:~$ cat tmp.txt | sort | uniq > sorted.txt
sallymacfarlane@mainnet-dev-sally-eth-peers-80369e81:~$ cat sorted.txt | wc -l
151

~20 unique stale peers - but all with validated = false

126 2022-07-21 02:01:08.239+00:00 | EthScheduler-Timer-0 | DEBUG | GetHeadersFromPeerByNumberTask | Requesting 1 headers from peer Peer 0xb522637f3c92f7d2d2... PeerReputation 101, validated? false, disconnected? true.
127 2022-07-21 02:01:47.670+00:00 | nioEventLoopGroup-3-9 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0x571a4fc1184e9d7ec4... PeerReputation 100, validated? false, disconnected? true
128 2022-07-21 02:01:47.932+00:00 | nioEventLoopGroup-3-9 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0xd5908ff35f09221e4a... PeerReputation 100, validated? false, disconnected? true
129 2022-07-21 02:01:52.961+00:00 | EthScheduler-Timer-0 | DEBUG | GetHeadersFromPeerByNumberTask | Requesting 1 headers from peer Peer 0x77260125a138fcbefb... PeerReputation 101, validated? false, disconnected? true.
130 2022-07-21 02:01:57.376+00:00 | nioEventLoopGroup-3-8 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0x0ec3ea3972823bf1e3... PeerReputation 100, validated? false, disconnected? true
131 Peer 0x0c8dd71bd4496cf8c4... PeerReputation 100, validated? false, disconnected? true,
132 Peer 0x14a9737cd1c2bf67f0... PeerReputation 100, validated? false, disconnected? true,
133 Peer 0x229a29dec21d68779c... PeerReputation 100, validated? false, disconnected? true,
134 Peer 0x359e0b1509d0f802ae... PeerReputation 100, validated? false, disconnected? true,
135 Peer 0x36e9a9c605f5a32938... PeerReputation 100, validated? false, disconnected? true,
136 Peer 0x3a0f6935910fe538d0... PeerReputation 100, validated? false, disconnected? true,
137 Peer 0x4e2b786d94183134e8... PeerReputation 100, validated? false, disconnected? true,
138 Peer 0x6bd4942ba74cbdf587... PeerReputation 100, validated? false, disconnected? true,
139 Peer 0x73b9870bba16ebc407... PeerReputation 100, validated? false, disconnected? true,
140 Peer 0x767c940827b244f5b5... PeerReputation 100, validated? false, disconnected? true,
141 Peer 0x7e5c8891ceaac9898c... PeerReputation 100, validated? false, disconnected? true,
142 Peer 0x8b3519f77c8d31d669... PeerReputation 100, validated? false, disconnected? true,
143 Peer 0xa9882c8dbbe2b19661... PeerReputation 100, validated? false, disconnected? true,
144 Peer 0xba95155945f524d3e2... PeerReputation 100, validated? false, disconnected? true,
145 Peer 0xc9f7831ec2da571de1... PeerReputation 100, validated? false, disconnected? true,
146 Peer 0xca776ff9688242aac3... PeerReputation 100, validated? false, disconnected? true,
147 Peer 0xcce28640376ab1ca3b... PeerReputation 100, validated? false, disconnected? true,
148 Peer 0xd094aaee3baa666249... PeerReputation 100, validated? false, disconnected? true,
149 Peer 0xfac6b6cef0f9222167... PeerReputation 100, validated? false, disconnected? true,
150 Peer 0xfbbf9383918ee4c092... PeerReputation 100, validated? false, disconnected? true,
151 Peer 0xfe9cf74b82c235197d... PeerReputation 100, validated? false, disconnected? true,

latest contents of EthPeers. max size I have seen is 26.

2022-07-21 02:00:03.622+00:00 | nioEventLoopGroup-3-4 | DEBUG | EthProtocolManager | Disconnect - Outbound - 0x10 SUBPROTOCOL_TRIGGERED - PeerInfo{version=5, clientId='Geth/v1.10.1-stable-c2d2f4ed/linux-amd64/go1.17.2', capabilities=[eth/64, eth/65, eth/66, snap/1], port=0, nodeId=0x1b9f01fab982c8621ef78588cd07ce276688e9921c6c02f6072f10856a10521be4544ca6295d17e8b1a589fda5bfa1d05e61fc0ff313d6014b0bca6fc373b210} - 24 peers left
2022-07-21 02:00:03.622+00:00 | nioEventLoopGroup-3-4 | TRACE | EthProtocolManager | 24 EthPeers {
Peer 0x54447c865e2ed69e05... PeerReputation 97, validated? true, disconnected? false,
Peer 0x4dbdfb7780bf6de078... PeerReputation 98, validated? true, disconnected? false,
Peer 0x7e5c8891ceaac9898c... PeerReputation 100, validated? false, disconnected? true,
Peer 0x7175786f4600218a97... PeerReputation 100, validated? true, disconnected? false,
Peer 0xb5044d696f951dd7f3... PeerReputation 100, validated? true, disconnected? false,
Peer 0x8b70a20f56758736ac... PeerReputation 162, validated? true, disconnected? false,
Peer 0xe0afef6292e34c2479... PeerReputation 2014, validated? true, disconnected? false,
Peer 0xb59c40030e61edc266... PeerReputation 2523, validated? true, disconnected? false,
Peer 0xa5f98757a5cca70a8e... PeerReputation 5174, validated? true, disconnected? false,
Peer 0xbb30e00d9788286f3d... PeerReputation 6682, validated? true, disconnected? false,
Peer 0x9496091968442f60a4... PeerReputation 6844, validated? true, disconnected? false,
Peer 0x80ee0f6f4d7c9dc440... PeerReputation 7833, validated? true, disconnected? false,
Peer 0x12d128248d9df39b93... PeerReputation 7942, validated? true, disconnected? false,
Peer 0x64a370fc49ccdd6449... PeerReputation 8020, validated? true, disconnected? false,
Peer 0xf5d5463c5eacf750d2... PeerReputation 8139, validated? true, disconnected? false,
Peer 0x46724e6992659fe567... PeerReputation 8877, validated? true, disconnected? false,
Peer 0x7c5e3b08253275c219... PeerReputation 9081, validated? true, disconnected? false,
Peer 0xfa006c9f8a2904b558... PeerReputation 9090, validated? true, disconnected? false,
Peer 0xc9f7831ec2da571de1... PeerReputation 9191, validated? true, disconnected? false,
Peer 0x7905672741b7f39121... PeerReputation 9373, validated? true, disconnected? false,
Peer 0x0afb70813ff36b8e13... PeerReputation 9926, validated? true, disconnected? false,
Peer 0x2a17b2c016a9fa6fe7... PeerReputation 10872, validated? true, disconnected? false,
Peer 0xe6316690ba3d88acfc... PeerReputation 12589, validated? true, disconnected? false,
Peer 0x05e9f05046094d22d2... PeerReputation 12895, validated? true, disconnected? false}

@macfarla
Copy link
Contributor

macfarla commented Jul 21, 2022 •
edited
Loading

goerli with RC2
~ 300 unique incidences of stale peers after 3 hours

sallymacfarlane@goerli-dev-sally-eth-peers-80369e81:~$ grep "validated? true, disconnected? true" /var/log/besu/besu.log > tmp.txt
sallymacfarlane@goerli-dev-sally-eth-peers-80369e81:~$ cat tmp.txt | wc -l
265857
sallymacfarlane@goerli-dev-sally-eth-peers-80369e81:~$ cat tmp.txt | sort | uniq > sorted.txt
sallymacfarlane@goerli-dev-sally-eth-peers-80369e81:~$ cat sorted.txt | wc -l
301

and the results in sorted.txt are 50/50 responses from disconnected peers and stale disconnected peers

119 2022-07-21 01:22:50.330+00:00 | nioEventLoopGroup-3-5 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0xdc120520857d081bf5... PeerReputation 1253, validated? true, disconnected? true
120 2022-07-21 01:24:57.291+00:00 | nioEventLoopGroup-3-3 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0xc1f8b7c2ac4453271f... PeerReputation 100, validated? true, disconnected? true
121 2022-07-21 01:30:44.814+00:00 | nioEventLoopGroup-3-6 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0x9fa79a3216b36da24a... PeerReputation 100, validated? true, disconnected? true
122 2022-07-21 01:32:33.365+00:00 | nioEventLoopGroup-3-2 | DEBUG | EthPeer | Received useless response for bodies from peer Peer 0x9fa79a3216b36da24a... PeerReputation 113, validated? true, disconnected? true
123 2022-07-21 01:38:36.175+00:00 | nioEventLoopGroup-3-8 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0xa3b2326a562a6acdd6... PeerReputation 100, validated? true, disconnected? true
124 2022-07-21 01:39:07.130+00:00 | nioEventLoopGroup-3-7 | DEBUG | EthPeer | Received useless response for headers from peer Peer 0xa3b2326a562a6acdd6... PeerReputation 100, validated? true, disconnected? true
125 Peer 0x01f5f55966260756fd... PeerReputation 100, validated? true, disconnected? true,
126 Peer 0x02124d01773875e388... PeerReputation 100, validated? true, disconnected? true,
127 Peer 0x043ec9c426b5459d01... PeerReputation 100, validated? true, disconnected? true,
128 Peer 0x087998e720e0a08d64... PeerReputation 100, validated? true, disconnected? true,
129 Peer 0x091f7d3fccc8c5129f... PeerReputation 100, validated? true, disconnected? true,
130 Peer 0x09329d00c72a861a0b... PeerReputation 100, validated? true, disconnected? true,
131 Peer 0x0b94e5109af8b17e4f... PeerReputation 100, validated? true, disconnected? true,

@macfarla
Copy link
Contributor

macfarla commented Jul 21, 2022 •
edited
Loading

goerli with 4100
~ 100 unique incidences of stale peers after 18 hours

sallymacfarlane@goerli-dev-sally-4001:~$ grep "validated? true, disconnected? true" /var/log/besu/besu.log > tmp.txt
sallymacfarlane@goerli-dev-sally-4001:~$ cat tmp.txt | wc -l
142
sallymacfarlane@goerli-dev-sally-4001:~$ cat sorted.txt | wc -l
138

It's about 70/30 stale peers and responses

Peer 670289121 0xe19fa955c58ef2fe73... PeerReputation 100, validated? true, disconnected? true,
 96 Peer 69032829 0xcdcb2d4a61bfdb943e... PeerReputation 100, validated? true, disconnected? true,
 97 Peer 692187735 0x99dcf2c3e56534e259... PeerReputation 100, validated? true, disconnected? true,
 98 Peer 730465720 0x851d38b40c90c0d1e3... PeerReputation 100, validated? true, disconnected? true,
 99 Peer 730475202 0xc4c9fed80520ff6778... PeerReputation 100, validated? true, disconnected? true,
100 Peer 75217378 0xd6518f4f318a172158... PeerReputation 100, validated? true, disconnected? true,
101 Peer 792382767 0x65a8545b97b8331d54... PeerReputation 100, validated? true, disconnected? true,
102 Peer 798963790 0xa11be9a634a0fcfdc6... PeerReputation 100, validated? true, disconnected? true,
103 Peer 833205436 0xe205b1c859ae321051... PeerReputation 100, validated? true, disconnected? true,
104 Peer 929481047 0xc1f109416ce13d4df4... PeerReputation 100, validated? true, disconnected? true,
105 {"@timestamp":"2022-07-20T06:55:48,493","level":"DEBUG","thread":"nioEventLoopGroup-3-7","class":"EthPeer","message":"Received useless response for headers from peer Peer 1322450591 0xbd527c4969165bec48... PeerReputati    on 100, validated? true, disconnected? true","throwable":""}
106 {"@timestamp":"2022-07-20T06:55:51,846","level":"DEBUG","thread":"nioEventLoopGroup-3-1","class":"EthPeer","message":"Received useless response for headers from peer Peer 333858630 0x5e9c0eb5e496d6bd78... PeerReputatio    n 100, validated? true, disconnected? true","throwable":""}
107 {"@timestamp":"2022-07-20T06:56:07,293","level":"DEBUG","thread":"nioEventLoopGroup-3-8","class":"EthPeer","message":"Received useless response for headers from peer Peer 1845761819 0xc94e917ff178d4d0b5... PeerReputati    on 100, validated? true, disconnected? true","throwable":""}

latest contents of EthPeers

{"@timestamp":"2022-07-21T01:58:44,994","level":"TRACE","thread":"nioEventLoopGroup-3-5","class":"EthProtocolManager","message":"on disconnect: 25 EthPeers {
Peer 1538216632 0x860f6852a7890332d5... PeerReputation 100, validated? true, disconnected? false,
Peer 547561703 0x2a06b3bfaa3c35920a... PeerReputation 102, validated? true, disconnected? false,
Peer 513063988 0x186fffadc7f954f686... PeerReputation 102, validated? true, disconnected? false,
Peer 293386613 0x9cdfdf5c289d471b43... PeerReputation 104, validated? true, disconnected? false,
Peer 158703338 0xda88dc0fe9ec8f93ac... PeerReputation 108, validated? true, disconnected? false,
Peer 891589840 0x9f016d14e6c309490c... PeerReputation 123, validated? true, disconnected? false,
Peer 2053244661 0x632c1dd9e3a609e9f0... PeerReputation 153, validated? true, disconnected? false,
Peer 484131586 0xf6d8236998c54e5fa5... PeerReputation 180, validated? true, disconnected? false,
Peer 1062400970 0x1d99a53c0c6c24e621... PeerReputation 352, validated? true, disconnected? false,
Peer 1871026841 0x8866424bff9b18ba16... PeerReputation 747, validated? true, disconnected? false,
Peer 218740909 0x2183ae56082b00d4af... PeerReputation 1711, validated? true, disconnected? false,
Peer 293822992 0x97fec34494b30caa11... PeerReputation 3228, validated? true, disconnected? false,
Peer 1869606984 0xeb4d23d657e9b964c1... PeerReputation 3744, validated? true, disconnected? false,
Peer 1728000883 0x4f3c2bdfb8c33a4cb1... PeerReputation 8401, validated? true, disconnected? false,
Peer 1239904491 0x9888390ced7f6c2c1d... PeerReputation 10486, validated? true, disconnected? false,
Peer 1244919122 0x83e042eae862759794... PeerReputation 12752, validated? true, disconnected? false,
Peer 1251696998 0x1de62c406ce902797f... PeerReputation 14445, validated? true, disconnected? false,
Peer 1433417271 0x2d8ba444dc9ceb8b32... PeerReputation 23225, validated? true, disconnected? false,
Peer 113549481 0x1e2b9a6fd46ee8ec26... PeerReputation 28876, validated? true, disconnected? false,
Peer 90856304 0xf6c8f9aad5fcb25260... PeerReputation 30230, validated? true, disconnected? false,
Peer 893609276 0xf3b72a2d82e03545f0... PeerReputation 32473, validated? true, disconnected? false,
Peer 79587359 0x68d90c7c2cbcbf0f5a... PeerReputation 35441, validated? true, disconnected? false,
Peer 1940587090 0x43975047d1d1df1268... PeerReputation 35738, validated? true, disconnected? false,
Peer 1538265151 0x5694e56be5672d3b21... PeerReputation 52821, validated? true, disconnected? false,
Peer 871514133 0xa6fa82cb4a766500c7... PeerReputation 68875, validated? true, disconnected? false}","throwable":""}

@macfarla
Copy link
Contributor

macfarla commented Jul 21, 2022 •
edited
Loading

^ in both cases on goerli I can see the stale peers in the logs but they don't persist, and the size doesn't grow over time. They do eventually get removed. Max size I have seen is 26.

@macfarla
Copy link
Contributor

Closing this one - conclusion is that there isn't a problem on mainnet/goerli

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@macfarla macfarla

Labels
mainnet peering TeamRevenant GH issues worked on by Revenant Team
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@iamhsk @macfarla