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.

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

PeerManager infinite loops peer retry after remote ports changed #603

Closed
SomberNight opened this issue Sep 18, 2018 · 2 comments

Comments

@SomberNight
Copy link
Contributor

commented Sep 18, 2018

On 515156f, bitcoin mainnet.

log:

{"log":"INFO:PeerManager:accepted new peer electrum.mindspot.org from e.keff.org\n","stream":"stdout","time":"2018-09-13T14:55:36.145762262Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.1s\n","stream":"stdout","time":"2018-09-13T14:55:37.278075514Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 2.5s\n","stream":"stdout","time":"2018-09-14T14:45:39.82742095Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.9s\n","stream":"stdout","time":"2018-09-15T14:35:41.701179949Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 4.1s\n","stream":"stdout","time":"2018-09-16T14:25:45.842013565Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.1s\n","stream":"stdout","time":"2018-09-17T14:15:46.936702542Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.1s\n","stream":"stdout","time":"2018-09-18T14:05:48.067136671Z"}
{"log":"INFO:PeerManager:accepted add_peer request from 172.103.153.90 for electrum.mindspot.org\n","stream":"stdout","time":"2018-09-18T17:51:16.394915753Z"}
{"log":"INFO:PeerManager:ports changed for electrum.mindspot.org\n","stream":"stdout","time":"2018-09-18T17:51:16.395645596Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:17.990950094Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.4s\n","stream":"stdout","time":"2018-09-18T17:51:19.349682843Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.5s\n","stream":"stdout","time":"2018-09-18T17:51:20.884505293Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.4s\n","stream":"stdout","time":"2018-09-18T17:51:22.242322539Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.5s\n","stream":"stdout","time":"2018-09-18T17:51:23.725167713Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:25.362258338Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:26.987569454Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.8s\n","stream":"stdout","time":"2018-09-18T17:51:28.741657646Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:30.327719177Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:31.940408662Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.7s\n","stream":"stdout","time":"2018-09-18T17:51:33.645604656Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.4s\n","stream":"stdout","time":"2018-09-18T17:51:35.089324183Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:36.656868087Z"}
{"log":"INFO:PeerManager:[electrum.mindspot.org:50002 SSL] verified in 1.6s\n","stream":"stdout","time":"2018-09-18T17:51:38.260433431Z"}

In the last day, my server has tried and succeeded to verify this peer over 10k times.

peer list:

Host                           Status   TCP   SSL Server             Min  Max  Pruning   Last Good    Last Try Tries               Source IP Address
electrum.mindspot.org          good         50002 ElectrumX 1.8.7    1.1  1.4                  00s         00s     1                 peer 172.103.153.90
7jwtirwsaogb6jv2.onion         good   50001 50002 ElectrumX 1.3+     0.9  1.2          03h 21m 23s 03h 21m 29s     0                 peer
node.ispol.sk                  good   50001 50002 ElectrumX 1.3+     0.9  1.2          03h 25m 07s 03h 25m 08s     0                 peer 193.58.196.212
...

Notice the line INFO:PeerManager:ports changed for electrum.mindspot.org.
Also notice that the SSL port seemingly did not change.
Also notice that currently there is no TCP port advertised for that server.
My guess is that there was a TCP port also for that server and was removed just before the issue started.

for match in matches:
if match.check_ports(peer):
self.logger.info(f'ports changed for {peer}')
match.retry_event.set()

Note that check_ports will notice that the TCP port got removed and set retry_event.

def check_ports(self, other):
'''Remember differing ports in case server operator changed them
or removed one.'''
if other.ssl_port != self.ssl_port:
self.other_port_pairs.add(('SSL', other.ssl_port))
if other.tcp_port != self.tcp_port:
self.other_port_pairs.add(('TCP', other.tcp_port))
return bool(self.other_port_pairs)

Then in _should_drop_peer, is_good will get set as the SSL port still works,

is_good = True

so it will return False.
So _monitor_peer will enter an infinite loop.
while peer in self.peers:

await peer.retry_event.wait()

@shsmith

This comment has been minimized.

Copy link
Contributor

commented Sep 19, 2018

Found the same sequence in logs on two of my servers.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Sep 24, 2018

I think this is fixed.

shyba added a commit to lbryio/electrumx that referenced this issue Oct 16, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.