From ad224429f823a66b431401d44bae21ed254a97e1 Mon Sep 17 00:00:00 2001 From: Sjors Provoost Date: Tue, 23 Jul 2024 10:53:15 +0200 Subject: [PATCH 1/5] 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 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 @@ class CNode 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 @@ def run_test(self): 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 @@ def test_earlykeyresponse(self): # 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 @@ def test_v2disconnection(self): 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/5] 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 e503a68382..f3b54c37dc 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 136cdd024d..ad5a7e4831 100755 --- a/test/functional/feature_maxuploadtarget.py +++ b/test/functional/feature_maxuploadtarget.py @@ -122,7 +122,7 @@ def run_test(self): 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 @@ def run_test(self): # 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 @@ def run_test(self): 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 d5ded926d3..8012137971 100755 --- a/test/functional/p2p_addrv2_relay.py +++ b/test/functional/p2p_addrv2_relay.py @@ -78,7 +78,7 @@ def set_test_params(self): 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 f800e815d8..7848cdaadb 100755 --- a/test/functional/p2p_leak.py +++ b/test/functional/p2p_leak.py @@ -172,7 +172,7 @@ def run_test(self): 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 2c7216b5ca..3f1fca5c78 100755 --- a/test/functional/p2p_sendtxrcncl.py +++ b/test/functional/p2p_sendtxrcncl.py @@ -168,7 +168,7 @@ def run_test(self): 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 @@ def run_test(self): 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/5] 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 50fe391862..fcf17d3f27 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 77abac8f11..99a9d0da4b 100644 --- a/src/net.h +++ b/src/net.h @@ -947,6 +947,14 @@ class CNode 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 f3b54c37dc..a19443c0f5 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/5] 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 fcf17d3f27..c3c472793d 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 b42d940d7b..ce01547887 100755 --- a/test/functional/p2p_timeouts.py +++ b/test/functional/p2p_timeouts.py @@ -91,8 +91,8 @@ def run_test(self): 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): From 5709718b830161b7c2ba0db545ef0cfa98423597 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C5=91rinc?= Date: Wed, 18 Dec 2024 19:37:33 +0100 Subject: [PATCH 5/5] coins: warn on shutdown for big UTXO set flushes Setting a large `-dbcache` size postpones the index writes until the coins cache size exceeds the specified limit. This causes the final flush after manual termination to seemingly hang forever (e.g. tens of minutes for 20 GiB); Now that the `dbcache` upper cap has been lifted, this will become even more apparent, so a warning will be shown when large UTXO sets are flushed (currently >1 GiB), such as: > 2024-12-18T18:25:03Z Flushed fee estimates to fee_estimates.dat. > 2024-12-18T18:25:03Z [warning] Flushing large (1 GiB) UTXO set to disk, it may take several minutes > 2024-12-18T18:25:09Z Shutdown: done Note that the related BCLog::BENCH units were also converted to `KiB` from `kB` to unify the bases. Co-authored-by: Cory Fields --- src/validation.cpp | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index aff8fe7024..1063c327ab 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -88,6 +88,8 @@ using node::CBlockIndexHeightOnlyComparator; using node::CBlockIndexWorkComparator; using node::SnapshotMetadata; +/** Size threshold for warning about slow UTXO set flush to disk. */ +static constexpr size_t WARN_FLUSH_COINS_SIZE = 1 << 30; // 1 GiB /** Time to wait between writing blocks/block index to disk. */ static constexpr std::chrono::hours DATABASE_WRITE_INTERVAL{1}; /** Time to wait between flushing chainstate to disk. */ @@ -2929,8 +2931,9 @@ bool Chainstate::FlushStateToDisk( } // Flush best chain related state. This can only be done if the blocks / block index write was also done. if (fDoFullFlush && !CoinsTip().GetBestBlock().IsNull()) { - LOG_TIME_MILLIS_WITH_CATEGORY(strprintf("write coins cache to disk (%d coins, %.2fkB)", - coins_count, coins_mem_usage / 1000), BCLog::BENCH); + if (coins_mem_usage >= WARN_FLUSH_COINS_SIZE) LogWarning("Flushing large (%d GiB) UTXO set to disk, it may take several minutes", coins_mem_usage >> 30); + LOG_TIME_MILLIS_WITH_CATEGORY(strprintf("write coins cache to disk (%d coins, %.2fKiB)", + coins_count, coins_mem_usage >> 10), BCLog::BENCH); // Typical Coin structures on disk are around 48 bytes in size. // Pushing a new one to the database can cause it to be written