From ad224429f823a66b431401d44bae21ed254a97e1 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Tue, 23 Jul 2024 10:53:15 +0200 Subject: [PATCH 1/4] net: additional disconnection logging Use the word "disconnecting" everywhere for easier grep. --- src/net.cpp | 43 ++++++++++++++++++++------- src/net.h | 8 +++++ test/functional/p2p_timeouts.py | 12 ++++---- test/functional/p2p_v2_misbehaving.py | 4 +-- 4 files changed, 49 insertions(+), 18 deletions(-) diff --git a/src/net.cpp b/src/net.cpp index 0f2e7e23d90..50fe3918625 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 fc096ff7b86..77abac8f111 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 1fd78e163b4..b42d940d7ba 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 0af96a4f8c9..ee589010cdd 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 From 937ef9eb408e377cde4cab4dfcd27120afdedf1b Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Tue, 23 Jul 2024 12:35:59 +0200 Subject: [PATCH 2/4] net_processing: use CNode::DisconnectMsg helper This is not a pure refactor: 1. It slightly changes the log messages, as reflected in the test changes 2. It adds the IP address to all disconnect logging (when fLogIPs is set) --- src/net_processing.cpp | 89 +++++++++++----------- test/functional/feature_maxuploadtarget.py | 6 +- test/functional/p2p_addrv2_relay.py | 2 +- test/functional/p2p_leak.py | 2 +- test/functional/p2p_sendtxrcncl.py | 4 +- 5 files changed, 53 insertions(+), 50 deletions(-) diff --git a/src/net_processing.cpp b/src/net_processing.cpp index e503a683827..f3b54c37dc2 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -2238,7 +2238,7 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv& (((m_chainman.m_best_header != nullptr) && (m_chainman.m_best_header->GetBlockTime() - pindex->GetBlockTime() > HISTORICAL_BLOCK_AGE)) || inv.IsMsgFilteredBlk()) && !pfrom.HasPermission(NetPermissionFlags::Download) // nodes with the download permission may exceed target ) { - LogDebug(BCLog::NET, "historical block serving limit reached, disconnect peer=%d\n", pfrom.GetId()); + LogDebug(BCLog::NET, "historical block serving limit reached, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -2247,7 +2247,7 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv& if (!pfrom.HasPermission(NetPermissionFlags::NoBan) && ( (((peer.m_our_services & NODE_NETWORK_LIMITED) == NODE_NETWORK_LIMITED) && ((peer.m_our_services & NODE_NETWORK) != NODE_NETWORK) && (tip->nHeight - pindex->nHeight > (int)NODE_NETWORK_LIMITED_MIN_BLOCKS + 2 /* add two blocks buffer extension for possible races */) ) )) { - LogDebug(BCLog::NET, "Ignore block request below NODE_NETWORK_LIMITED threshold, disconnect peer=%d\n", pfrom.GetId()); + LogDebug(BCLog::NET, "Ignore block request below NODE_NETWORK_LIMITED threshold, %s\n", pfrom.DisconnectMsg(fLogIPs)); //disconnect node and prevent it from stalling (would otherwise wait for the missing block) pfrom.fDisconnect = true; return; @@ -2270,9 +2270,9 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv& std::vector block_data; if (!m_chainman.m_blockman.ReadRawBlockFromDisk(block_data, block_pos)) { if (WITH_LOCK(m_chainman.GetMutex(), return m_chainman.m_blockman.IsBlockPruned(*pindex))) { - LogDebug(BCLog::NET, "Block was pruned before it could be read, disconnect peer=%s\n", pfrom.GetId()); + LogDebug(BCLog::NET, "Block was pruned before it could be read, %s\n", pfrom.DisconnectMsg(fLogIPs)); } else { - LogError("Cannot load block from disk, disconnect peer=%d\n", pfrom.GetId()); + LogError("Cannot load block from disk, %s\n", pfrom.DisconnectMsg(fLogIPs)); } pfrom.fDisconnect = true; return; @@ -2284,9 +2284,9 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv& std::shared_ptr pblockRead = std::make_shared(); if (!m_chainman.m_blockman.ReadBlockFromDisk(*pblockRead, block_pos)) { if (WITH_LOCK(m_chainman.GetMutex(), return m_chainman.m_blockman.IsBlockPruned(*pindex))) { - LogDebug(BCLog::NET, "Block was pruned before it could be read, disconnect peer=%s\n", pfrom.GetId()); + LogDebug(BCLog::NET, "Block was pruned before it could be read, %s\n", pfrom.DisconnectMsg(fLogIPs)); } else { - LogError("Cannot load block from disk, disconnect peer=%d\n", pfrom.GetId()); + LogError("Cannot load block from disk, %s\n", pfrom.DisconnectMsg(fLogIPs)); } pfrom.fDisconnect = true; return; @@ -2788,7 +2788,7 @@ void PeerManagerImpl::UpdatePeerStateForReceivedHeaders(CNode& pfrom, Peer& peer // the minimum chain work, even if a peer has a chain past our tip, // as an anti-DoS measure. if (pfrom.IsOutboundOrBlockRelayConn()) { - LogPrintf("Disconnecting outbound peer %d -- headers chain has insufficient work\n", pfrom.GetId()); + LogInfo("outbound peer headers chain has insufficient work, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; } } @@ -3111,8 +3111,8 @@ bool PeerManagerImpl::PrepareBlockFilterRequest(CNode& node, Peer& peer, (filter_type == BlockFilterType::BASIC && (peer.m_our_services & NODE_COMPACT_FILTERS)); if (!supported_filter_type) { - LogDebug(BCLog::NET, "peer %d requested unsupported block filter type: %d\n", - node.GetId(), static_cast(filter_type)); + LogDebug(BCLog::NET, "peer requested unsupported block filter type: %d, %s\n", + static_cast(filter_type), node.DisconnectMsg(fLogIPs)); node.fDisconnect = true; return false; } @@ -3123,8 +3123,8 @@ bool PeerManagerImpl::PrepareBlockFilterRequest(CNode& node, Peer& peer, // Check that the stop block exists and the peer would be allowed to fetch it. if (!stop_index || !BlockRequestAllowed(stop_index)) { - LogDebug(BCLog::NET, "peer %d requested invalid block hash: %s\n", - node.GetId(), stop_hash.ToString()); + LogDebug(BCLog::NET, "peer requested invalid block hash: %s, %s\n", + stop_hash.ToString(), node.DisconnectMsg(fLogIPs)); node.fDisconnect = true; return false; } @@ -3132,15 +3132,15 @@ bool PeerManagerImpl::PrepareBlockFilterRequest(CNode& node, Peer& peer, uint32_t stop_height = stop_index->nHeight; if (start_height > stop_height) { - LogDebug(BCLog::NET, "peer %d sent invalid getcfilters/getcfheaders with " - "start height %d and stop height %d\n", - node.GetId(), start_height, stop_height); + LogDebug(BCLog::NET, "peer sent invalid getcfilters/getcfheaders with " + "start height %d and stop height %d, %s\n", + start_height, stop_height, node.DisconnectMsg(fLogIPs)); node.fDisconnect = true; return false; } if (stop_height - start_height >= max_height_diff) { - LogDebug(BCLog::NET, "peer %d requested too many cfilters/cfheaders: %d / %d\n", - node.GetId(), stop_height - start_height + 1, max_height_diff); + LogDebug(BCLog::NET, "peer requested too many cfilters/cfheaders: %d / %d, %s\n", + stop_height - start_height + 1, max_height_diff, node.DisconnectMsg(fLogIPs)); node.fDisconnect = true; return false; } @@ -3407,14 +3407,17 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, } if (pfrom.ExpectServicesFromConn() && !HasAllDesirableServiceFlags(nServices)) { - LogDebug(BCLog::NET, "peer=%d does not offer the expected services (%08x offered, %08x expected); disconnecting\n", pfrom.GetId(), nServices, GetDesirableServiceFlags(nServices)); + LogDebug(BCLog::NET, "peer does not offer the expected services (%08x offered, %08x expected), %s\n", + nServices, + GetDesirableServiceFlags(nServices), + pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } if (nVersion < MIN_PEER_PROTO_VERSION) { // disconnect from peers older than this proto version - LogDebug(BCLog::NET, "peer=%d using obsolete version %i; disconnecting\n", pfrom.GetId(), nVersion); + LogDebug(BCLog::NET, "peer using obsolete version %i, %s\n", nVersion, pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -3591,7 +3594,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // Feeler connections exist only to verify if address is online. if (pfrom.IsFeelerConn()) { - LogDebug(BCLog::NET, "feeler connection completed peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "feeler connection completed, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; } return; @@ -3695,7 +3698,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::WTXIDRELAY) { if (pfrom.fSuccessfullyConnected) { // Disconnect peers that send a wtxidrelay message after VERACK. - LogDebug(BCLog::NET, "wtxidrelay received after verack from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "wtxidrelay received after verack, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -3717,7 +3720,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::SENDADDRV2) { if (pfrom.fSuccessfullyConnected) { // Disconnect peers that send a SENDADDRV2 message after VERACK. - LogDebug(BCLog::NET, "sendaddrv2 received after verack from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "sendaddrv2 received after verack, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -3730,19 +3733,19 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // from switching announcement protocols after the connection is up. if (msg_type == NetMsgType::SENDTXRCNCL) { if (!m_txreconciliation) { - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl from peer=%d ignored, as our node does not have txreconciliation enabled\n", pfrom.GetId()); + LogDebug(BCLog::NET, "sendtxrcncl from peer=%d ignored, as our node does not have txreconciliation enabled\n", pfrom.GetId()); return; } if (pfrom.fSuccessfullyConnected) { - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received after verack from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "sendtxrcncl received after verack, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } // Peer must not offer us reconciliations if we specified no tx relay support in VERSION. if (RejectIncomingTxs(pfrom)) { - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received from peer=%d to which we indicated no tx relay; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "sendtxrcncl received to which we indicated no tx relay, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -3752,7 +3755,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // eliminates them, so that this flag fully represents what we are looking for. const auto* tx_relay = peer->GetTxRelay(); if (!tx_relay || !WITH_LOCK(tx_relay->m_bloom_filter_mutex, return tx_relay->m_relay_txs)) { - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "sendtxrcncl received from peer=%d which indicated no tx relay to us; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "sendtxrcncl received which indicated no tx relay to us, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -3765,16 +3768,16 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, peer_txreconcl_version, remote_salt); switch (result) { case ReconciliationRegisterResult::NOT_FOUND: - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "Ignore unexpected txreconciliation signal from peer=%d\n", pfrom.GetId()); + LogDebug(BCLog::NET, "Ignore unexpected txreconciliation signal from peer=%d\n", pfrom.GetId()); break; case ReconciliationRegisterResult::SUCCESS: break; case ReconciliationRegisterResult::ALREADY_REGISTERED: - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "txreconciliation protocol violation from peer=%d (sendtxrcncl received from already registered peer); disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "txreconciliation protocol violation (sendtxrcncl received from already registered peer), %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; case ReconciliationRegisterResult::PROTOCOL_VIOLATION: - LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "txreconciliation protocol violation from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "txreconciliation protocol violation, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -3877,7 +3880,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // AddrFetch: Require multiple addresses to avoid disconnecting on self-announcements if (pfrom.IsAddrFetchConn() && vAddr.size() > 1) { - LogDebug(BCLog::NET, "addrfetch connection completed peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "addrfetch connection completed, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; } return; @@ -3927,7 +3930,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, } } else if (inv.IsGenTxMsg()) { if (reject_tx_invs) { - LogDebug(BCLog::NET, "transaction (%s) inv sent in violation of protocol, disconnecting peer=%d\n", inv.hash.ToString(), pfrom.GetId()); + LogDebug(BCLog::NET, "transaction (%s) inv sent in violation of protocol, %s\n", inv.hash.ToString(), pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -4004,7 +4007,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, vRecv >> locator >> hashStop; if (locator.vHave.size() > MAX_LOCATOR_SZ) { - LogDebug(BCLog::NET, "getblocks locator size %lld > %d, disconnect peer=%d\n", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.GetId()); + LogDebug(BCLog::NET, "getblocks locator size %lld > %d, %s\n", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -4126,7 +4129,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, vRecv >> locator >> hashStop; if (locator.vHave.size() > MAX_LOCATOR_SZ) { - LogDebug(BCLog::NET, "getheaders locator size %lld > %d, disconnect peer=%d\n", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.GetId()); + LogDebug(BCLog::NET, "getheaders locator size %lld > %d, %s\n", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -4667,7 +4670,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, { if (!pfrom.HasPermission(NetPermissionFlags::NoBan)) { - LogDebug(BCLog::NET, "mempool request with bloom filters disabled, disconnect peer=%d\n", pfrom.GetId()); + LogDebug(BCLog::NET, "mempool request with bloom filters disabled, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; } return; @@ -4677,7 +4680,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, { if (!pfrom.HasPermission(NetPermissionFlags::NoBan)) { - LogDebug(BCLog::NET, "mempool request with bandwidth limit reached, disconnect peer=%d\n", pfrom.GetId()); + LogDebug(BCLog::NET, "mempool request with bandwidth limit reached, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; } return; @@ -4767,7 +4770,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::FILTERLOAD) { if (!(peer->m_our_services & NODE_BLOOM)) { - LogDebug(BCLog::NET, "filterload received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "filterload received despite not offering bloom services, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -4792,7 +4795,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::FILTERADD) { if (!(peer->m_our_services & NODE_BLOOM)) { - LogDebug(BCLog::NET, "filteradd received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "filteradd received despite not offering bloom services, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -4820,7 +4823,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::FILTERCLEAR) { if (!(peer->m_our_services & NODE_BLOOM)) { - LogDebug(BCLog::NET, "filterclear received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId()); + LogDebug(BCLog::NET, "filterclear received despite not offering bloom services, %s\n", pfrom.DisconnectMsg(fLogIPs)); pfrom.fDisconnect = true; return; } @@ -5041,7 +5044,7 @@ void PeerManagerImpl::ConsiderEviction(CNode& pto, Peer& peer, std::chrono::seco // message to give the peer a chance to update us. if (state.m_chain_sync.m_sent_getheaders) { // They've run out of time to catch up! - LogPrintf("Disconnecting outbound peer %d for old chain, best known block = %s\n", pto.GetId(), state.pindexBestKnownBlock != nullptr ? state.pindexBestKnownBlock->GetBlockHash().ToString() : ""); + LogInfo("Outbound peer has old chain, best known block = %s, %s\n", state.pindexBestKnownBlock != nullptr ? state.pindexBestKnownBlock->GetBlockHash().ToString() : "", pto.DisconnectMsg(fLogIPs)); pto.fDisconnect = true; } else { assert(state.m_chain_sync.m_work_header); @@ -5442,7 +5445,7 @@ bool PeerManagerImpl::SendMessages(CNode* pto) const auto current_time{GetTime()}; if (pto->IsAddrFetchConn() && current_time - pto->m_connected > 10 * AVG_ADDRESS_BROADCAST_INTERVAL) { - LogDebug(BCLog::NET, "addrfetch connection timeout; disconnecting peer=%d\n", pto->GetId()); + LogDebug(BCLog::NET, "addrfetch connection timeout, %s\n", pto->DisconnectMsg(fLogIPs)); pto->fDisconnect = true; return true; } @@ -5786,7 +5789,7 @@ bool PeerManagerImpl::SendMessages(CNode* pto) // Stalling only triggers when the block download window cannot move. During normal steady state, // the download window should be much larger than the to-be-downloaded set of blocks, so disconnection // should only happen during initial block download. - LogPrintf("Peer=%d%s is stalling block download, disconnecting\n", pto->GetId(), fLogIPs ? strprintf(" peeraddr=%s", pto->addr.ToStringAddrPort()) : ""); + LogInfo("Peer is stalling block download, %s\n", pto->DisconnectMsg(fLogIPs)); pto->fDisconnect = true; // Increase timeout for the next peer so that we don't disconnect multiple peers if our own // bandwidth is insufficient. @@ -5805,7 +5808,7 @@ bool PeerManagerImpl::SendMessages(CNode* pto) QueuedBlock &queuedBlock = state.vBlocksInFlight.front(); int nOtherPeersWithValidatedDownloads = m_peers_downloading_from - 1; if (current_time > state.m_downloading_since + std::chrono::seconds{consensusParams.nPowTargetSpacing} * (BLOCK_DOWNLOAD_TIMEOUT_BASE + BLOCK_DOWNLOAD_TIMEOUT_PER_PEER * nOtherPeersWithValidatedDownloads)) { - LogPrintf("Timeout downloading block %s from peer=%d%s, disconnecting\n", queuedBlock.pindex->GetBlockHash().ToString(), pto->GetId(), fLogIPs ? strprintf(" peeraddr=%s", pto->addr.ToStringAddrPort()) : ""); + LogInfo("Timeout downloading block %s, %s\n", queuedBlock.pindex->GetBlockHash().ToString(), pto->DisconnectMsg(fLogIPs)); pto->fDisconnect = true; return true; } @@ -5821,11 +5824,11 @@ bool PeerManagerImpl::SendMessages(CNode* pto) // disconnect our sync peer for stalling; we have bigger // problems if we can't get any outbound peers. if (!pto->HasPermission(NetPermissionFlags::NoBan)) { - LogPrintf("Timeout downloading headers from peer=%d%s, disconnecting\n", pto->GetId(), fLogIPs ? strprintf(" peeraddr=%s", pto->addr.ToStringAddrPort()) : ""); + LogInfo("Timeout downloading headers, %s\n", pto->DisconnectMsg(fLogIPs)); pto->fDisconnect = true; return true; } else { - LogPrintf("Timeout downloading headers from noban peer=%d%s, not disconnecting\n", pto->GetId(), fLogIPs ? strprintf(" peeraddr=%s", pto->addr.ToStringAddrPort()) : ""); + LogInfo("Timeout downloading headers from noban peer, not %s\n", pto->DisconnectMsg(fLogIPs)); // Reset the headers sync state so that we have a // chance to try downloading from a different peer. // Note: this will also result in at least one more diff --git a/test/functional/feature_maxuploadtarget.py b/test/functional/feature_maxuploadtarget.py index 136cdd024d5..ad5a7e4831a 100755 --- a/test/functional/feature_maxuploadtarget.py +++ b/test/functional/feature_maxuploadtarget.py @@ -122,7 +122,7 @@ class MaxUploadTest(BitcoinTestFramework): assert_equal(len(self.nodes[0].getpeerinfo()), 3) # At most a couple more tries should succeed (depending on how long # the test has been running so far). - with self.nodes[0].assert_debug_log(expected_msgs=["historical block serving limit reached, disconnect peer"]): + with self.nodes[0].assert_debug_log(expected_msgs=["historical block serving limit reached, disconnecting peer=0"]): for _ in range(3): p2p_conns[0].send_message(getdata_request) p2p_conns[0].wait_for_disconnect() @@ -147,7 +147,7 @@ class MaxUploadTest(BitcoinTestFramework): # But if p2p_conns[1] tries for an old block, it gets disconnected too. getdata_request.inv = [CInv(MSG_BLOCK, big_old_block)] - with self.nodes[0].assert_debug_log(expected_msgs=["historical block serving limit reached, disconnect peer"]): + with self.nodes[0].assert_debug_log(expected_msgs=["historical block serving limit reached, disconnecting peer=1"]): p2p_conns[1].send_message(getdata_request) p2p_conns[1].wait_for_disconnect() assert_equal(len(self.nodes[0].getpeerinfo()), 1) @@ -197,7 +197,7 @@ class MaxUploadTest(BitcoinTestFramework): assert_equal(peer_info[0]['permissions'], ['download']) self.log.info("Peer gets disconnected for a mempool request after limit is reached") - with self.nodes[0].assert_debug_log(expected_msgs=["mempool request with bandwidth limit reached, disconnect peer"]): + with self.nodes[0].assert_debug_log(expected_msgs=["mempool request with bandwidth limit reached, disconnecting peer=0"]): peer.send_message(msg_mempool()) peer.wait_for_disconnect() diff --git a/test/functional/p2p_addrv2_relay.py b/test/functional/p2p_addrv2_relay.py index d5ded926d36..8012137971e 100755 --- a/test/functional/p2p_addrv2_relay.py +++ b/test/functional/p2p_addrv2_relay.py @@ -78,7 +78,7 @@ class AddrTest(BitcoinTestFramework): def run_test(self): self.log.info('Check disconnection when sending sendaddrv2 after verack') conn = self.nodes[0].add_p2p_connection(P2PInterface()) - with self.nodes[0].assert_debug_log(['sendaddrv2 received after verack from peer=0; disconnecting']): + with self.nodes[0].assert_debug_log(['sendaddrv2 received after verack, disconnecting peer=0']): conn.send_message(msg_sendaddrv2()) conn.wait_for_disconnect() diff --git a/test/functional/p2p_leak.py b/test/functional/p2p_leak.py index f800e815d8d..7848cdaadb9 100755 --- a/test/functional/p2p_leak.py +++ b/test/functional/p2p_leak.py @@ -172,7 +172,7 @@ class P2PLeakTest(BitcoinTestFramework): self.log.info('Check that old peers are disconnected') p2p_old_peer = self.nodes[0].add_p2p_connection(P2PInterface(), send_version=False, wait_for_verack=False) - with self.nodes[0].assert_debug_log(["using obsolete version 31799; disconnecting"]): + with self.nodes[0].assert_debug_log(["using obsolete version 31799, disconnecting peer=5"]): p2p_old_peer.send_message(self.create_old_version(31799)) p2p_old_peer.wait_for_disconnect() diff --git a/test/functional/p2p_sendtxrcncl.py b/test/functional/p2p_sendtxrcncl.py index 2c7216b5ca3..3f1fca5c784 100755 --- a/test/functional/p2p_sendtxrcncl.py +++ b/test/functional/p2p_sendtxrcncl.py @@ -168,7 +168,7 @@ class SendTxRcnclTest(BitcoinTestFramework): with self.nodes[0].assert_debug_log(["received: sendtxrcncl"]): peer.send_message(create_sendtxrcncl_msg()) self.log.info('second SENDTXRCNCL triggers a disconnect') - with self.nodes[0].assert_debug_log(["(sendtxrcncl received from already registered peer); disconnecting"]): + with self.nodes[0].assert_debug_log(["(sendtxrcncl received from already registered peer), disconnecting peer=0"]): peer.send_message(create_sendtxrcncl_msg()) peer.wait_for_disconnect() @@ -226,7 +226,7 @@ class SendTxRcnclTest(BitcoinTestFramework): self.log.info('SENDTXRCNCL if block-relay-only triggers a disconnect') peer = self.nodes[0].add_outbound_p2p_connection( PeerNoVerack(), wait_for_verack=False, p2p_idx=0, connection_type="block-relay-only") - with self.nodes[0].assert_debug_log(["we indicated no tx relay; disconnecting"]): + with self.nodes[0].assert_debug_log(["we indicated no tx relay, disconnecting peer=5"]): peer.send_message(create_sendtxrcncl_msg()) peer.wait_for_disconnect() From 1d01ad4d73e0eaae36c31153884e3d394ebc66b7 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Tue, 23 Jul 2024 12:52:38 +0200 Subject: [PATCH 3/4] net: add LogIP() helper, use in net_processing --- src/net.cpp | 7 ++++++- src/net.h | 8 ++++++++ src/net_processing.cpp | 8 ++------ 3 files changed, 16 insertions(+), 7 deletions(-) diff --git a/src/net.cpp b/src/net.cpp index 50fe3918625..fcf17d3f270 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -695,11 +695,16 @@ bool CNode::ReceiveMsgBytes(Span msg_bytes, bool& complete) return true; } +std::string CNode::LogIP(bool log_ip) const +{ + return log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : ""; +} + std::string CNode::DisconnectMsg(bool log_ip) const { return strprintf("disconnecting peer=%d%s", GetId(), - log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : ""); + LogIP(log_ip)); } V1Transport::V1Transport(const NodeId node_id) noexcept diff --git a/src/net.h b/src/net.h index 77abac8f111..99a9d0da4b4 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 optionally log the IP address. + * + * @param[in] log_ip whether to include the IP address + * @return " peeraddr=..." or "" + */ + std::string LogIP(bool log_ip) const; + /** * Helper function to log disconnects. * diff --git a/src/net_processing.cpp b/src/net_processing.cpp index f3b54c37dc2..a19443c0f56 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -3568,15 +3568,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, m_addrman.Good(pfrom.addr); } - std::string remoteAddr; - if (fLogIPs) - remoteAddr = ", peeraddr=" + pfrom.addr.ToStringAddrPort(); - const auto mapped_as{m_connman.GetMappedAS(pfrom.addr)}; LogDebug(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, txrelay=%d, peer=%d%s%s\n", cleanSubVer, pfrom.nVersion, peer->m_starting_height, addrMe.ToStringAddrPort(), fRelay, pfrom.GetId(), - remoteAddr, (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "")); + pfrom.LogIP(fLogIPs), (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "")); peer->m_time_offset = NodeSeconds{std::chrono::seconds{nTime}} - Now(); if (!pfrom.IsInboundConn()) { @@ -3620,7 +3616,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, pfrom.ConnectionTypeAsString(), TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type), pfrom.nVersion.load(), peer->m_starting_height, - pfrom.GetId(), (fLogIPs ? strprintf(", peeraddr=%s", pfrom.addr.ToStringAddrPort()) : ""), + pfrom.GetId(), pfrom.LogIP(fLogIPs), (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "")); } From 06443b8f28bcec4315cec262eb03343dee5465a6 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Tue, 26 Nov 2024 14:01:36 +0100 Subject: [PATCH 4/4] net: clarify if we ever sent or received from peer --- src/net.cpp | 13 +++++++++---- test/functional/p2p_timeouts.py | 4 ++-- 2 files changed, 11 insertions(+), 6 deletions(-) diff --git a/src/net.cpp b/src/net.cpp index fcf17d3f270..c3c472793da 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -1982,12 +1982,17 @@ bool CConnman::InactivityCheck(const CNode& node) const if (!ShouldRunInactivityChecks(node, now)) return false; - if (last_recv.count() == 0 || last_send.count() == 0) { + bool has_received{last_recv.count() != 0}; + bool has_sent{last_send.count() != 0}; + + if (!has_received || !has_sent) { + std::string has_never; + if (!has_received) has_never += ", never received from peer"; + if (!has_sent) has_never += ", never sent to peer"; LogDebug(BCLog::NET, - "socket no message in first %i seconds, %d %d, %s\n", + "socket no message in first %i seconds%s, %s\n", count_seconds(m_peer_connect_timeout), - last_recv.count() != 0, - last_send.count() != 0, + has_never, node.DisconnectMsg(fLogIPs) ); return true; diff --git a/test/functional/p2p_timeouts.py b/test/functional/p2p_timeouts.py index b42d940d7ba..ce01547887d 100755 --- a/test/functional/p2p_timeouts.py +++ b/test/functional/p2p_timeouts.py @@ -91,8 +91,8 @@ class TimeoutsTest(BitcoinTestFramework): else: expected_timeout_logs = [ "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", + "socket no message in first 3 seconds, never sent to peer, disconnecting peer=1", + "socket no message in first 3 seconds, never received from peer, never sent to peer, disconnecting peer=2", ] with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):