Same peer lost 4 times on shutdown

[arnetheduck]

Notice there are supposedly 21 peers, but only a few are "lost" on shutdown - mostly notably though 16Uiu2HAmBqaNcNitjW1kar4voXHhuHoJkfqr8yS4s1xCSqJVM3Vb is lost 4 times.

 peers: 21 ❯ finalized: abfa25a6:4034 ❯ head: 3850762f:4045:6 ❯ time: 4336:3 (138755)                                                                                                                                                                                                                                                                                                                                                                                                                                                           ETH: 31.419676989 INF 2020-06-15 08:31:06+02:00 Shutting down after having received SIGINT topics="beacnde" tid=1613235 file=nimbus_binary_common.nim:53
INF 2020-06-15 08:31:06+02:00 Graceful shutdown                          topics="beacnde" tid=1613235 file=beacon_node.nim:755
DBG 2020-06-15 08:31:06+02:00 Closing discovery node                     topics="discv5" tid=1613235 file=protocol.nim:769 node=Node[unaddressable]
DBG 2020-06-15 08:31:06+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAm8Cv8tCXbAaV9MfvUuTP7BF5y1pZXRainP5VxkpVvZnZa
DBG 2020-06-15 08:31:06+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmNRyPwJUaSAqwiLQA9k3ibZnTkqSHyQvYrtTBbDTgkdL5
DBG 2020-06-15 08:31:06+02:00 Error processing request                   topics="networking" tid=1613235 file=eth2_network.nim:412 errMsg="Incomplete request" peer=16Uiu2HAmLPDjXtPnXzaPUv9LPTvaypV7f3PGduRCmReGCtwVPTXN responseCode=InvalidRequest
DBG 2020-06-15 08:31:06+02:00 Error processing an incoming request       topics="sync" tid=1613235 file=eth2_network.nim:646 err="Stream Closed!\nAsync traceback:\nException message: Stream Closed!\nException type:" msgName=beaconBlocksByRangeObj
DBG 2020-06-15 08:31:06+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmLPDjXtPnXzaPUv9LPTvaypV7f3PGduRCmReGCtwVPTXN
DBG 2020-06-15 08:31:06+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmTXz3fiywgagb1wLE3eFBFqYUjwgAgijetQyq7SayYf1L
DBG 2020-06-15 08:31:06+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmD2SAQRGmXTaZF3eFqpzqyvUdr9Ds6qRU8ZuQtLq34iRr
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmEM6HYXuMCeKUeMtmjYdQsz23MekUrp2TB3bADiijLj3e
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmUbV7rQw8Z573Dh7cQPFm8PTQzmfuQgYjLcinnfCwgGzr
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmE9WLt69mHL1cPkATAMCgFisUCrWLmJAAXg2omMTkW1za
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmVKjTm3YePQgQLxm3fsfAUVgE58opRHZGDXRNLNsqvzBv
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmMvENue2gXZ4vExdZVDeW5ZK8vnCYMHCWzxTxsjkHxaMV
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAkucMAVckq8yyLU51pbnzjTZ6JptPLKdpH5USBGuuvinHP
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAm295TBWmcnwmUTw3KJB3NQ7iGtWs2crUZvc1RKAPSZzLe
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmNU5LnMBkM6xsXEnBBLiLqXefJoxmkbgNmFamDkJQeQ7m
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmK3aw5p4Uw7RYRFeUcL4u1pg3u6JN8MnyT5wRshNLvHqU
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmBqaNcNitjW1kar4voXHhuHoJkfqr8yS4s1xCSqJVM3Vb
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmBqaNcNitjW1kar4voXHhuHoJkfqr8yS4s1xCSqJVM3Vb
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmBqaNcNitjW1kar4voXHhuHoJkfqr8yS4s1xCSqJVM3Vb
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmBqaNcNitjW1kar4voXHhuHoJkfqr8yS4s1xCSqJVM3Vb
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmPvD41dmBsf6FYgqacPQ4B7FQk5copxwTTdMayMdProvj
DBG 2020-06-15 08:31:07+02:00 Peer (incoming) lost                       topics="networking" tid=1613235 file=eth2_network.nim:671 peer=16Uiu2HAmPgSLr36xcCqsm7nZ7ueiqzJ74KG3bpYV7jvGwHzpAGVe
DBG 2020-06-15 08:31:07+02:00 Peer (outgoing) lost                       topics="networking" tid=1613235 file=eth2_network.nim:655 peer=16Uiu2HAmNL6L5nmaDeQun8TRUpSQNERrswEsyh1FAAuiqTXZ2E5T

[cheatfate]

I think this issue is fixed, i can't see any more duplicates in lost logs. But for some reason prevailing amount of connections here are incoming, this is very strange.

[arnetheduck]

I saw it yesterday - they are incoming because the incoming / outgoing flag is set late in the process and generally holds an invalid value until it's set (ping @zah )

[zah]

@arnetheduck, can you clarify what you mean?

The flag in the Peer object is called wasDialed and the default value is false (in other words "incoming peer"). wasDialed is set to true for the outgoing peers very early, right after we have a LibP2P connection with the peer, but before we have tried to perform the Eth2 handshake:

https://github.com/status-im/nim-beacon-chain/blob/master/beacon_chain/eth2_network.nim#L708

[arnetheduck]

well, it's obviously wrong here because all these peers in the log are outgoing (I don't have ports open for incoming connections)

[arnetheduck]

fixed with peer events in libp2p