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

fanquake · fanquake · commit 25d7e2e78137 · 2019-10-25T15:07:58.000-04:00
04dbdd6 [net] SocketHandler: log peer id for close and disconnect (Sjors Provoost) Pull request description: 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 ``` ACKs for top commit: MarcoFalke: unsigned ACK 04dbdd6 TheBlueMatt: unsigned ACK 04dbdd6 LGTM! theuni: unsigned ACK 04dbdd6. Tree-SHA512: 415313908484f97ffe11a48b4ed6afab3ab0be660c788adb9ad975f88b69aa1cfd5ccbe5859350cdf19ef8fde191fd530fb22cef34e70638defdc9f3d761c71d
diff --git a/src/net.cpp b/src/net.cpp
@@ -1361,7 +1361,7 @@ void CConnman::SocketHandler()
             {
                 // socket closed gracefully
                 if (!pnode->fDisconnect) {
-                    LogPrint(BCLog::NET, "socket closed\n");
+                    LogPrint(BCLog::NET, "socket closed for peer=%d\n", pnode->GetId());
                 }
                 pnode->CloseSocketDisconnect();
             }
@@ -1371,8 +1371,9 @@ void CConnman::SocketHandler()
                 int nErr = WSAGetLastError();
                 if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS)
                 {
-                    if (!pnode->fDisconnect)
-                        LogPrintf("socket recv error %s\n", NetworkErrorString(nErr));
+                    if (!pnode->fDisconnect) {
+                        LogPrint(BCLog::NET, "socket recv error for peer=%d: %s\n", pnode->GetId(), NetworkErrorString(nErr));
+                    }
                     pnode->CloseSocketDisconnect();
                 }
             }

Original file line number	Diff line number	Diff line change
`@@ -1361,7 +1361,7 @@ void CConnman::SocketHandler()`
`1361`	`1361`	`{`
`1362`	`1362`	`// socket closed gracefully`
`1363`	`1363`	`if (!pnode->fDisconnect) {`
`1364`		`- LogPrint(BCLog::NET, "socket closed\n");`
	`1364`	`+ LogPrint(BCLog::NET, "socket closed for peer=%d\n", pnode->GetId());`
`1365`	`1365`	`}`
`1366`	`1366`	`pnode->CloseSocketDisconnect();`
`1367`	`1367`	`}`
`@@ -1371,8 +1371,9 @@ void CConnman::SocketHandler()`
`1371`	`1371`	`int nErr = WSAGetLastError();`
`1372`	`1372`	`if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS)`
`1373`	`1373`	`{`
`1374`		`- if (!pnode->fDisconnect)`
`1375`		`- LogPrintf("socket recv error %s\n", NetworkErrorString(nErr));`
	`1374`	`+ if (!pnode->fDisconnect) {`
	`1375`	`+ LogPrint(BCLog::NET, "socket recv error for peer=%d: %s\n", pnode->GetId(), NetworkErrorString(nErr));`
	`1376`	`+ }`
`1376`	`1377`	`pnode->CloseSocketDisconnect();`
`1377`	`1378`	`}`
`1378`	`1379`	`}`