From 27abe6e53b071f6c51fd4e3982784ecd1979c3d4 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Fri, 1 Dec 2023 09:39:43 +0100 Subject: [PATCH] net: additional disconnection logging Use the word "disconnecting" everywhere for easier grep. --- src/net.cpp | 38 ++++++++++++++++++++++++++++----- test/functional/p2p_timeouts.py | 6 +++--- 2 files changed, 36 insertions(+), 8 deletions(-) diff --git a/src/net.cpp b/src/net.cpp index dc76fdfb445353..55f056c61645cb 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -1886,7 +1886,11 @@ void CConnman::DisconnectNodes() // Disconnect any connected nodes for (CNode* pnode : m_nodes) { if (!pnode->fDisconnect) { - LogPrint(BCLog::NET, "Network not active, dropping peer=%d\n", pnode->GetId()); + LogPrint(BCLog::NET, + "Network not active, disconnecting peer=%d%s\n", + pnode->GetId(), + fLogIPs ? strprintf(" peeraddr=%s", pnode->addr.ToStringAddrPort()) : "" + ); pnode->fDisconnect = true; } } @@ -1979,22 +1983,41 @@ bool CConnman::InactivityCheck(const CNode& node) const if (!ShouldRunInactivityChecks(node, now)) return false; if (last_recv.count() == 0 || last_send.count() == 0) { - LogPrint(BCLog::NET, "socket no message in first %i seconds, %d %d peer=%d\n", count_seconds(m_peer_connect_timeout), last_recv.count() != 0, last_send.count() != 0, node.GetId()); + LogPrint(BCLog::NET, + "socket no message in first %i seconds, %d %d disconnecting peer=%d%s\n", + count_seconds(m_peer_connect_timeout), + last_recv.count() != 0, + last_send.count() != 0, + node.GetId(), + fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : "" + ); return true; } if (now > last_send + TIMEOUT_INTERVAL) { - LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", count_seconds(now - last_send), node.GetId()); + LogPrint(BCLog::NET, + "socket sending timeout: %is, disconnecting peer=%d%s\n", count_seconds(now - last_send), + node.GetId(), + fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : "" + ); return true; } if (now > last_recv + TIMEOUT_INTERVAL) { - LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", count_seconds(now - last_recv), node.GetId()); + LogPrint(BCLog::NET, + "socket receive timeout: %is, disconnecting peer=%d%s\n", count_seconds(now - last_recv), + node.GetId(), + fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : "" + ); return true; } if (!node.fSuccessfullyConnected) { - LogPrint(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId()); + LogPrint(BCLog::NET, + "version handshake timeout, disconnecting peer=%d%s\n", + node.GetId(), + fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : "" + ); return true; } @@ -2121,6 +2144,11 @@ void CConnman::SocketHandlerConnected(const std::vector& nodes, { bool notify = false; if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) { + LogPrint(BCLog::NET, + "receiving message bytes failed for peer=%d%s\n", + pnode->GetId(), + fLogIPs ? strprintf(" peeraddr=%s", pnode->addr.ToStringAddrPort()) : "" + ); pnode->CloseSocketDisconnect(); } RecordBytesRecv(nBytes); diff --git a/test/functional/p2p_timeouts.py b/test/functional/p2p_timeouts.py index b4fa5099d87589..b5a009b64bf1d5 100755 --- a/test/functional/p2p_timeouts.py +++ b/test/functional/p2p_timeouts.py @@ -87,9 +87,9 @@ def run_test(self): no_version_node.send_message(msg_ping()) expected_timeout_logs = [ - "version handshake timeout peer=0", - f"socket no message in first 3 seconds, {'0' if self.options.v2transport else '1'} 0 peer=1", - "socket no message in first 3 seconds, 0 0 peer=2", + "version handshake timeout, disconnecting peer=0", + f"socket no message in first 3 seconds, {'0' if self.options.v2transport else '1'} 0 disconnecting peer=1", + "socket no message in first 3 seconds, 0 0 disconnecting peer=2", ] with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):