net: SocketHandler logs peer id for close and disconnect #17251

pull Sjors wants to merge 1 commits into bitcoin:master from Sjors:2019/10/net-socket-peer changing 1 files +4 −3

Sjors commented at 1:41 PM on October 25, 2019: member

When combined with -logips this makes it easier to diagnose disconnects.

To test on macOS, find a connection you want to disrupt:

lsof -nP -iTCP:8333 -sTCP:ESTABLISHED

To shut it down gracefully you can use tcpkill or this Python script: https://github.com/google/tcp_killer

The log should say:

2019-10-25T13:26:55Z socket closed for peer=1
2019-10-25T13:26:55Z disconnecting peer=1
2019-10-25T13:26:55Z Cleared nodestate for peer=1

To shut it down ungracefully I made a patch to the above script, adding a -force argument. Careful, this may result in data corruption. Then the log should say:

2019-10-25T13:39:57Z socket select error Bad file descriptor (9)
2019-10-25T13:39:57Z socket recv error for peer=0: Bad file descriptor (9)
2019-10-25T13:39:57Z disconnecting peer=0
2019-10-25T13:39:57Z Socket close failed: 35. Error: Bad file descriptor (9)
2019-10-25T13:39:57Z Cleared nodestate for peer=0

fanquake added the label P2P on Oct 25, 2019
laanwj commented at 1:45 PM on October 25, 2019: member

ACK b62013c277db6fa600a994d2d5851bffc58aa983
MarcoFalke commented at 1:48 PM on October 25, 2019: member

This is already printed in the very next line
Sjors commented at 1:53 PM on October 25, 2019: member

@MarcoFalke true. It's not very grep-friendly though, and many other log messages do include peer=N. And I also mistook the error code for the node id.
emilengler commented at 4:52 PM on October 25, 2019: contributor

Don't know if it's a thing but why isn't the IP being displayed as well?
Sjors commented at 5:23 PM on October 25, 2019: member

@emilengler putting IP addresses in the log was disabled by default in #3764 for privacy reasons
[net] SocketHandler: log peer id for close and disconnect 04dbdd613f
Sjors commented at 6:06 PM on October 25, 2019: member

@TheBlueMatt suggested making the error message debug=net only
Sjors force-pushed on Oct 25, 2019
MarcoFalke commented at 6:39 PM on October 25, 2019: member

unsigned ACK 04dbdd613fe5c0a742de915e07553614cd4cbf46
TheBlueMatt commented at 6:53 PM on October 25, 2019: member

unsigned ACK 04dbdd613fe5c0a742de915e07553614cd4cbf46 LGTM!
theuni commented at 6:58 PM on October 25, 2019: member

I've definitely hacked this in locally before.

unsigned ACK 04dbdd613fe5c0a742de915e07553614cd4cbf46.
fanquake referenced this in commit 25d7e2e781 on Oct 25, 2019
fanquake merged this on Oct 25, 2019
fanquake closed this on Oct 25, 2019
Sjors deleted the branch on Oct 25, 2019
jasonbcox referenced this in commit 7fa3480bcc on Oct 14, 2020
MarcoFalke locked this on Dec 16, 2021

Contributors

Labels