diff --git a/src/net.cpp b/src/net.cpp index 0f2e7e23d9..50fe391862 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -558,7 +558,6 @@ void CNode::CloseSocketDisconnect() fDisconnect = true; LOCK(m_sock_mutex); if (m_sock) { - LogDebug(BCLog::NET, "disconnecting peer=%d\n", id); m_sock.reset(); } m_i2p_sam_session.reset(); @@ -696,6 +695,13 @@ bool CNode::ReceiveMsgBytes(Span msg_bytes, bool& complete) return true; } +std::string CNode::DisconnectMsg(bool log_ip) const +{ + return strprintf("disconnecting peer=%d%s", + GetId(), + log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : ""); +} + V1Transport::V1Transport(const NodeId node_id) noexcept : m_magic_bytes{Params().MessageStart()}, m_node_id{node_id} { @@ -1635,7 +1641,7 @@ std::pair CConnman::SocketSendData(CNode& node) const // error int nErr = WSAGetLastError(); if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) { - LogDebug(BCLog::NET, "socket send error for peer=%d: %s\n", node.GetId(), NetworkErrorString(nErr)); + LogDebug(BCLog::NET, "socket send error, %s: %s\n", node.DisconnectMsg(fLogIPs), NetworkErrorString(nErr)); node.CloseSocketDisconnect(); } } @@ -1879,7 +1885,7 @@ void CConnman::DisconnectNodes() // Disconnect any connected nodes for (CNode* pnode : m_nodes) { if (!pnode->fDisconnect) { - LogDebug(BCLog::NET, "Network not active, dropping peer=%d\n", pnode->GetId()); + LogDebug(BCLog::NET, "Network not active, %s\n", pnode->DisconnectMsg(fLogIPs)); pnode->fDisconnect = true; } } @@ -1972,25 +1978,37 @@ bool CConnman::InactivityCheck(const CNode& node) const if (!ShouldRunInactivityChecks(node, now)) return false; if (last_recv.count() == 0 || last_send.count() == 0) { - LogDebug(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()); + LogDebug(BCLog::NET, + "socket no message in first %i seconds, %d %d, %s\n", + count_seconds(m_peer_connect_timeout), + last_recv.count() != 0, + last_send.count() != 0, + node.DisconnectMsg(fLogIPs) + ); return true; } if (now > last_send + TIMEOUT_INTERVAL) { - LogDebug(BCLog::NET, "socket sending timeout: %is peer=%d\n", count_seconds(now - last_send), node.GetId()); + LogDebug(BCLog::NET, + "socket sending timeout: %is, %s\n", count_seconds(now - last_send), + node.DisconnectMsg(fLogIPs) + ); return true; } if (now > last_recv + TIMEOUT_INTERVAL) { - LogDebug(BCLog::NET, "socket receive timeout: %is peer=%d\n", count_seconds(now - last_recv), node.GetId()); + LogDebug(BCLog::NET, + "socket receive timeout: %is, %s\n", count_seconds(now - last_recv), + node.DisconnectMsg(fLogIPs) + ); return true; } if (!node.fSuccessfullyConnected) { if (node.m_transport->GetInfo().transport_type == TransportProtocolType::DETECTING) { - LogDebug(BCLog::NET, "V2 handshake timeout peer=%d\n", node.GetId()); + LogDebug(BCLog::NET, "V2 handshake timeout, %s\n", node.DisconnectMsg(fLogIPs)); } else { - LogDebug(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId()); + LogDebug(BCLog::NET, "version handshake timeout, %s\n", node.DisconnectMsg(fLogIPs)); } return true; } @@ -2118,6 +2136,10 @@ void CConnman::SocketHandlerConnected(const std::vector& nodes, { bool notify = false; if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) { + LogDebug(BCLog::NET, + "receiving message bytes failed, %s\n", + pnode->DisconnectMsg(fLogIPs) + ); pnode->CloseSocketDisconnect(); } RecordBytesRecv(nBytes); @@ -2130,7 +2152,7 @@ void CConnman::SocketHandlerConnected(const std::vector& nodes, { // socket closed gracefully if (!pnode->fDisconnect) { - LogDebug(BCLog::NET, "socket closed for peer=%d\n", pnode->GetId()); + LogDebug(BCLog::NET, "socket closed, %s\n", pnode->DisconnectMsg(fLogIPs)); } pnode->CloseSocketDisconnect(); } @@ -2141,7 +2163,7 @@ void CConnman::SocketHandlerConnected(const std::vector& nodes, if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) { if (!pnode->fDisconnect) { - LogDebug(BCLog::NET, "socket recv error for peer=%d: %s\n", pnode->GetId(), NetworkErrorString(nErr)); + LogDebug(BCLog::NET, "socket recv error, %s: %s\n", pnode->DisconnectMsg(fLogIPs), NetworkErrorString(nErr)); } pnode->CloseSocketDisconnect(); } @@ -3411,6 +3433,7 @@ void CConnman::StopNodes() std::vector nodes; WITH_LOCK(m_nodes_mutex, nodes.swap(m_nodes)); for (CNode* pnode : nodes) { + LogDebug(BCLog::NET, "%s\n", pnode->DisconnectMsg(fLogIPs)); pnode->CloseSocketDisconnect(); DeleteNode(pnode); } diff --git a/src/net.h b/src/net.h index fc096ff7b8..77abac8f11 100644 --- a/src/net.h +++ b/src/net.h @@ -947,6 +947,14 @@ public: std::string ConnectionTypeAsString() const { return ::ConnectionTypeAsString(m_conn_type); } + /** + * Helper function to log disconnects. + * + * @param[in] log_ip whether to include the IP address + * @return "disconnecting peer=..." and optionally "peeraddr=..." + */ + std::string DisconnectMsg(bool log_ip) const; + /** A ping-pong round trip has completed successfully. Update latest and minimum ping times. */ void PongReceived(std::chrono::microseconds ping_time) { m_last_ping_time = ping_time; diff --git a/test/functional/p2p_timeouts.py b/test/functional/p2p_timeouts.py index 1fd78e163b..b42d940d7b 100755 --- a/test/functional/p2p_timeouts.py +++ b/test/functional/p2p_timeouts.py @@ -84,15 +84,15 @@ class TimeoutsTest(BitcoinTestFramework): if self.options.v2transport: expected_timeout_logs = [ - "version handshake timeout peer=0", - "version handshake timeout peer=1", - "version handshake timeout peer=2", + "version handshake timeout, disconnecting peer=0", + "version handshake timeout, disconnecting peer=1", + "version handshake timeout, disconnecting peer=2", ] else: expected_timeout_logs = [ - "version handshake timeout peer=0", - "socket no message in first 3 seconds, 1 0 peer=1", - "socket no message in first 3 seconds, 0 0 peer=2", + "version handshake timeout, disconnecting peer=0", + "socket no message in first 3 seconds, 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): diff --git a/test/functional/p2p_v2_misbehaving.py b/test/functional/p2p_v2_misbehaving.py index 0af96a4f8c..ee589010cd 100755 --- a/test/functional/p2p_v2_misbehaving.py +++ b/test/functional/p2p_v2_misbehaving.py @@ -151,7 +151,7 @@ class EncryptedP2PMisbehaving(BitcoinTestFramework): # Ensure that the bytes sent after 4 bytes network magic are actually received. self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4) self.wait_until(lambda: node0.getpeerinfo()[-1]["bytessent"] > 0) - with node0.assert_debug_log(['V2 handshake timeout peer=0']): + with node0.assert_debug_log(['V2 handshake timeout, disconnecting peer=0']): node0.bumpmocktime(4) # `InactivityCheck()` triggers now peer1.wait_for_disconnect(timeout=1) self.log.info('successful disconnection since modified ellswift was sent as response') @@ -162,7 +162,7 @@ class EncryptedP2PMisbehaving(BitcoinTestFramework): expected_debug_message = [ [], # EARLY_KEY_RESPONSE ["V2 transport error: missing garbage terminator, peer=1"], # EXCESS_GARBAGE - ["V2 handshake timeout peer=3"], # WRONG_GARBAGE_TERMINATOR + ["V2 handshake timeout, disconnecting peer=3"], # WRONG_GARBAGE_TERMINATOR ["V2 transport error: packet decryption failure"], # WRONG_GARBAGE ["V2 transport error: packet decryption failure"], # SEND_NO_AAD [], # SEND_NON_EMPTY_VERSION_PACKET