FR: Increased peer connect/disconnect logging at INFO level

[bhorvitz]

Currently, the only peer activity logging at INFO level is full_node_server Connection Closed and chia.full_node.full_node peer disconnected.

It might be helpful to also have:
Successful connection logging
Directionality (in/out)
Peer disconnect reason, if available

[BrandtH22]

Hey @bhorvitz , thank you for the request!
Out of curiosity, have you tried setting the log levels to debug to see if that level has the additional logs you are hoping to find at the info level? (can be done by running chia configure --log-level DEBUG then restarting the chia client)

[bhorvitz]

Interestingly, there doesn't seem to be much more information on DEBUG either. There's a lot of noise, but if I filter it down, I see things like this:

2023-08-14T16:25:56.107 full_node full_node_server        : DEBUG    -> handshake to peer 98.165.129.85 67d76b3422af13331d5f21486365d8a0bde3191fe67a0f3ce44314e999350361
2023-08-14T16:25:56.107 full_node full_node_server        : DEBUG    -> new_peak_wallet to peer 98.165.129.85 67d76b3422af13331d5f21486365d8a0bde3191fe67a0f3ce44314e999350361
2023-08-14T16:25:56.147 full_node full_node_server        : DEBUG    Peer closed connection wallet 98.165.129.85:8449/60586
2023-08-14T16:25:56.147 full_node chia.full_node.full_node: INFO     peer disconnected PeerInfo(_ip=IPv4Address('98.165.129.85'), _port=8449)
...
2023-08-14T16:26:19.986 full_node full_node_server        : DEBUG    -> handshake to peer 188.163.8.152 fbcf7f03eb44236bdd9362f1028b5d9a13221bdddb955166b25bcb7ef6e55cd2
2023-08-14T16:26:19.986 full_node full_node_server        : DEBUG    -> new_peak_wallet to peer 188.163.8.152 fbcf7f03eb44236bdd9362f1028b5d9a13221bdddb955166b25bcb7ef6e55cd2
2023-08-14T16:26:20.191 full_node full_node_server        : DEBUG    Peer closed connection wallet 188.163.8.152:8449/34651
2023-08-14T16:26:20.192 full_node chia.full_node.full_node: INFO     peer disconnected PeerInfo(_ip=IPv4Address('188.163.8.152'), _port=8449)

For the heck of it, here's an IPv6 doing about the same:

2023-08-14T16:31:17.070 full_node full_node_server        : DEBUG    -> handshake to peer 2406:da14:93e:a803:1156:c980:1c92:f3b1 040dc5cafea6fb3406ffd4d79adc58f7490d6d9e45fdcd398473961c67075040
2023-08-14T16:31:17.072 full_node full_node_server        : DEBUG    -> new_peak to peer 2406:da14:93e:a803:1156:c980:1c92:f3b1 040dc5cafea6fb3406ffd4d79adc58f7490d6d9e45fdcd398473961c67075040
2023-08-14T16:31:17.187 full_node full_node_server        : DEBUG    <- request_peers from peer 040dc5cafea6fb3406ffd4d79adc58f7490d6d9e45fdcd398473961c67075040 2406:da14:93e:a803:1156:c980:1c92:f3b1
2023-08-14T16:31:17.296 full_node full_node_server        : DEBUG    Time taken to process request_peers from 040dc5cafea6fb3406ffd4d79adc58f7490d6d9e45fdcd398473961c67075040 is 0.10972857475280762 seconds
2023-08-14T16:31:17.297 full_node full_node_server        : DEBUG    -> respond_peers to peer 2406:da14:93e:a803:1156:c980:1c92:f3b1 040dc5cafea6fb3406ffd4d79adc58f7490d6d9e45fdcd398473961c67075040
2023-08-14T16:31:17.545 full_node full_node_server        : DEBUG    Peer closed connection full_node 2406:da14:93e:a803:1156:c980:1c92:f3b1:8444/60832
2023-08-14T16:31:17.546 full_node chia.full_node.full_node: INFO     peer disconnected PeerInfo(_ip=IPv6Address('2406:da14:93e:a803:1156:c980:1c92:f3b1'), _port=8444)

Now it may be that this is all perfectly normal communication, but as you can see from the INFO level logs, the only thing that gets logged in any of this is "peer disconnected". It's not too practical to run DEBUG logs all the time.

[BrandtH22]

Would the "handshake to peer" log be sufficient for what are needing in the INFO logs or are you wanting additional logs outside of what is available in DEBUG mode?

[bhorvitz]

I wouldn't say "need". This is a nice to have, which is why it's just FR.

I'm not super sure what "handshake to peer" actually means in terms of the things I was talking about my original post. For instance, is that a success? A fail? These particular ones look like fails or immediate disconnects for some reason.