From 22335474d768f99067856173ff2764b6db753f67 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?L=C5=91rinc?= Date: Fri, 16 Jan 2026 22:39:13 +0100 Subject: [PATCH] net: format peer+addr logs with `LogPeer` Use `LogPeer` for peer id plus optional `peeraddr`, separated with a comma. Co-authored-by: Luke Dashjr Co-authored-by: Vasil Dimov --- src/net.cpp | 57 +++++++------ src/net.h | 12 ++- src/net_processing.cpp | 133 ++++++++++++++--------------- test/functional/feature_logging.py | 2 +- 4 files changed, 102 insertions(+), 102 deletions(-) diff --git a/src/net.cpp b/src/net.cpp index f986f6c576b..bc8273b9096 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -555,7 +555,7 @@ void CNode::CloseSocketDisconnect() fDisconnect = true; LOCK(m_sock_mutex); if (m_sock) { - LogDebug(BCLog::NET, "Resetting socket for peer=%d%s", GetId(), LogIP(fLogIPs)); + LogDebug(BCLog::NET, "Resetting socket for %s", LogPeer()); m_sock.reset(); TRACEPOINT(net, closed_connection, @@ -700,16 +700,19 @@ bool CNode::ReceiveMsgBytes(std::span msg_bytes, bool& complete) return true; } -std::string CNode::LogIP(bool log_ip) const +std::string CNode::LogPeer() const { - return log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : ""; + auto peer_info{strprintf("peer=%d", GetId())}; + if (fLogIPs) { + return strprintf("%s, peeraddr=%s", peer_info, addr.ToStringAddrPort()); + } else { + return peer_info; + } } -std::string CNode::DisconnectMsg(bool log_ip) const +std::string CNode::DisconnectMsg() const { - return strprintf("disconnecting peer=%d%s", - GetId(), - LogIP(log_ip)); + return strprintf("disconnecting %s", LogPeer()); } V1Transport::V1Transport(const NodeId node_id) noexcept @@ -1655,7 +1658,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, %s: %s\n", node.DisconnectMsg(fLogIPs), NetworkErrorString(nErr)); + LogDebug(BCLog::NET, "socket send error, %s: %s", node.DisconnectMsg(), NetworkErrorString(nErr)); node.CloseSocketDisconnect(); } } @@ -1715,7 +1718,7 @@ bool CConnman::AttemptToEvictConnection() LOCK(m_nodes_mutex); for (CNode* pnode : m_nodes) { if (pnode->GetId() == *node_id_to_evict) { - LogDebug(BCLog::NET, "selected %s connection for eviction, %s", pnode->ConnectionTypeAsString(), pnode->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "selected %s connection for eviction, %s", pnode->ConnectionTypeAsString(), pnode->DisconnectMsg()); TRACEPOINT(net, evicted_inbound_connection, pnode->GetId(), pnode->m_addr_name.c_str(), @@ -1922,7 +1925,7 @@ void CConnman::DisconnectNodes() // Disconnect any connected nodes for (CNode* pnode : m_nodes) { if (!pnode->fDisconnect) { - LogDebug(BCLog::NET, "Network not active, %s\n", pnode->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "Network not active, %s", pnode->DisconnectMsg()); pnode->fDisconnect = true; } } @@ -2021,35 +2024,35 @@ bool CConnman::InactivityCheck(const CNode& node, std::chrono::microseconds now) 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%s, %s\n", + "socket no message in first %i seconds%s, %s", count_seconds(m_peer_connect_timeout), has_never, - node.DisconnectMsg(fLogIPs) + node.DisconnectMsg() ); return true; } if (now > last_send + TIMEOUT_INTERVAL) { LogDebug(BCLog::NET, - "socket sending timeout: %is, %s\n", Ticks(now - last_send), - node.DisconnectMsg(fLogIPs) + "socket sending timeout: %is, %s", Ticks(now - last_send), + node.DisconnectMsg() ); return true; } if (now > last_recv + TIMEOUT_INTERVAL) { LogDebug(BCLog::NET, - "socket receive timeout: %is, %s\n", Ticks(now - last_recv), - node.DisconnectMsg(fLogIPs) + "socket receive timeout: %is, %s", Ticks(now - last_recv), + node.DisconnectMsg() ); return true; } if (!node.fSuccessfullyConnected) { if (node.m_transport->GetInfo().transport_type == TransportProtocolType::DETECTING) { - LogDebug(BCLog::NET, "V2 handshake timeout, %s\n", node.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "V2 handshake timeout, %s", node.DisconnectMsg()); } else { - LogDebug(BCLog::NET, "version handshake timeout, %s\n", node.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "version handshake timeout, %s", node.DisconnectMsg()); } return true; } @@ -2181,8 +2184,8 @@ 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) + "receiving message bytes failed, %s", + pnode->DisconnectMsg() ); pnode->CloseSocketDisconnect(); } @@ -2196,7 +2199,7 @@ void CConnman::SocketHandlerConnected(const std::vector& nodes, { // socket closed gracefully if (!pnode->fDisconnect) { - LogDebug(BCLog::NET, "socket closed, %s\n", pnode->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "socket closed, %s", pnode->DisconnectMsg()); } pnode->CloseSocketDisconnect(); } @@ -2207,7 +2210,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, %s: %s\n", pnode->DisconnectMsg(fLogIPs), NetworkErrorString(nErr)); + LogDebug(BCLog::NET, "socket recv error, %s: %s", pnode->DisconnectMsg(), NetworkErrorString(nErr)); } pnode->CloseSocketDisconnect(); } @@ -3651,7 +3654,7 @@ void CConnman::StopNodes() std::vector nodes; WITH_LOCK(m_nodes_mutex, nodes.swap(m_nodes)); for (CNode* pnode : nodes) { - LogDebug(BCLog::NET, "Stopping node, %s", pnode->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "Stopping node, %s", pnode->DisconnectMsg()); pnode->CloseSocketDisconnect(); DeleteNode(pnode); } @@ -3811,7 +3814,7 @@ bool CConnman::DisconnectNode(std::string_view strNode) auto it = std::ranges::find_if(m_nodes, [&strNode](CNode* node) { return node->m_addr_name == strNode; }); if (it != m_nodes.end()) { CNode* node{*it}; - LogDebug(BCLog::NET, "disconnect by address%s match, %s", (fLogIPs ? strprintf("=%s", strNode) : ""), node->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "disconnect by address%s match, %s", (fLogIPs ? strprintf("=%s", strNode) : ""), node->DisconnectMsg()); node->fDisconnect = true; return true; } @@ -3824,7 +3827,7 @@ bool CConnman::DisconnectNode(const CSubNet& subnet) LOCK(m_nodes_mutex); for (CNode* pnode : m_nodes) { if (subnet.Match(pnode->addr)) { - LogDebug(BCLog::NET, "disconnect by subnet%s match, %s", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "disconnect by subnet%s match, %s", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->DisconnectMsg()); pnode->fDisconnect = true; disconnected = true; } @@ -3842,7 +3845,7 @@ bool CConnman::DisconnectNode(NodeId id) LOCK(m_nodes_mutex); for(CNode* pnode : m_nodes) { if (id == pnode->GetId()) { - LogDebug(BCLog::NET, "disconnect by id, %s", pnode->DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "disconnect by id, %s", pnode->DisconnectMsg()); pnode->fDisconnect = true; return true; } @@ -4059,7 +4062,7 @@ void CConnman::PushMessage(CNode* pnode, CSerializedNetMsg&& msg) AssertLockNotHeld(m_total_bytes_sent_mutex); if (pnode->IsPrivateBroadcastConn() && !IsOutboundMessageAllowedInPrivateBroadcast(msg.m_type)) { - LogDebug(BCLog::PRIVBROADCAST, "Omitting send of message '%s', peer=%d%s", msg.m_type, pnode->GetId(), pnode->LogIP(fLogIPs)); + LogDebug(BCLog::PRIVBROADCAST, "Omitting send of message '%s', %s", msg.m_type, pnode->LogPeer()); return; } diff --git a/src/net.h b/src/net.h index b209df61436..d4de261e7b3 100644 --- a/src/net.h +++ b/src/net.h @@ -968,20 +968,18 @@ public: std::string ConnectionTypeAsString() const { return ::ConnectionTypeAsString(m_conn_type); } /** - * Helper function to optionally log the IP address. + * Helper function to log the peer id, optionally including IP address. * - * @param[in] log_ip whether to include the IP address - * @return " peeraddr=..." or "" + * @return "peer=..." and optionally ", peeraddr=..." */ - std::string LogIP(bool log_ip) const; + std::string LogPeer() const; /** * Helper function to log disconnects. * - * @param[in] log_ip whether to include the IP address - * @return "disconnecting peer=..." and optionally "peeraddr=..." + * @return "disconnecting peer=..." and optionally ", peeraddr=..." */ - std::string DisconnectMsg(bool log_ip) const; + std::string DisconnectMsg() const; /** A ping-pong round trip has completed successfully. Update latest and minimum ping times. */ void PongReceived(std::chrono::microseconds ping_time) { diff --git a/src/net_processing.cpp b/src/net_processing.cpp index f45f63cfa7e..b98dcbc6f39 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -2350,7 +2350,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, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "historical block serving limit reached, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -2359,7 +2359,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, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "Ignore block request below NODE_NETWORK_LIMITED threshold, %s", pfrom.DisconnectMsg()); //disconnect node and prevent it from stalling (would otherwise wait for the missing block) pfrom.fDisconnect = true; return; @@ -2383,9 +2383,9 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv& MakeAndPushMessage(pfrom, NetMsgType::BLOCK, std::span{*block_data}); } else { if (WITH_LOCK(m_chainman.GetMutex(), return m_chainman.m_blockman.IsBlockPruned(*pindex))) { - LogDebug(BCLog::NET, "Block was pruned before it could be read, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "Block was pruned before it could be read, %s", pfrom.DisconnectMsg()); } else { - LogError("Cannot load block from disk, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogError("Cannot load block from disk, %s", pfrom.DisconnectMsg()); } pfrom.fDisconnect = true; return; @@ -2396,9 +2396,9 @@ void PeerManagerImpl::ProcessGetBlockData(CNode& pfrom, Peer& peer, const CInv& std::shared_ptr pblockRead = std::make_shared(); if (!m_chainman.m_blockman.ReadBlock(*pblockRead, block_pos, inv.hash)) { if (WITH_LOCK(m_chainman.GetMutex(), return m_chainman.m_blockman.IsBlockPruned(*pindex))) { - LogDebug(BCLog::NET, "Block was pruned before it could be read, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "Block was pruned before it could be read, %s", pfrom.DisconnectMsg()); } else { - LogError("Cannot load block from disk, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogError("Cannot load block from disk, %s", pfrom.DisconnectMsg()); } pfrom.fDisconnect = true; return; @@ -2910,7 +2910,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()) { - LogInfo("outbound peer headers chain has insufficient work, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogInfo("outbound peer headers chain has insufficient work, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; } } @@ -3245,8 +3245,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 requested unsupported block filter type: %d, %s\n", - static_cast(filter_type), node.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "peer requested unsupported block filter type: %d, %s", + static_cast(filter_type), node.DisconnectMsg()); node.fDisconnect = true; return false; } @@ -3257,8 +3257,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 requested invalid block hash: %s, %s\n", - stop_hash.ToString(), node.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "peer requested invalid block hash: %s, %s", + stop_hash.ToString(), node.DisconnectMsg()); node.fDisconnect = true; return false; } @@ -3267,14 +3267,14 @@ bool PeerManagerImpl::PrepareBlockFilterRequest(CNode& node, Peer& peer, uint32_t stop_height = stop_index->nHeight; if (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)); + "start height %d and stop height %d, %s", + start_height, stop_height, node.DisconnectMsg()); node.fDisconnect = true; return false; } if (stop_height - start_height >= 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)); + LogDebug(BCLog::NET, "peer requested too many cfilters/cfheaders: %d / %d, %s", + stop_height - start_height + 1, max_height_diff, node.DisconnectMsg()); node.fDisconnect = true; return false; } @@ -3513,12 +3513,11 @@ void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index, const CNode& peer // Having this log by default when not in IBD ensures broad availability of // this data in case investigation is merited. const auto msg = strprintf( - "Saw new %sheader hash=%s height=%d peer=%d%s", + "Saw new %sheader hash=%s height=%d %s", via_compact_block ? "cmpctblock " : "", index.GetBlockHash().ToString(), index.nHeight, - peer.GetId(), - peer.LogIP(fLogIPs) + peer.LogPeer() ); if (m_chainman.IsInitialBlockDownload()) { LogDebug(BCLog::VALIDATION, "%s", msg); @@ -3533,15 +3532,15 @@ void PeerManagerImpl::PushPrivateBroadcastTx(CNode& node) const auto opt_tx{m_tx_for_private_broadcast.PickTxForSend(node.GetId())}; if (!opt_tx) { - LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: no more transactions for private broadcast (connected in vain), peer=%d%s", node.GetId(), node.LogIP(fLogIPs)); + LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: no more transactions for private broadcast (connected in vain), %s", node.LogPeer()); node.fDisconnect = true; return; } const CTransactionRef& tx{*opt_tx}; - LogDebug(BCLog::PRIVBROADCAST, "P2P handshake completed, sending INV for txid=%s%s, peer=%d%s", + LogDebug(BCLog::PRIVBROADCAST, "P2P handshake completed, sending INV for txid=%s%s, %s", tx->GetHash().ToString(), tx->HasWitness() ? strprintf(", wtxid=%s", tx->GetWitnessHash().ToString()) : "", - node.GetId(), node.LogIP(fLogIPs)); + node.LogPeer()); MakeAndPushMessage(node, NetMsgType::INV, std::vector{{CInv{MSG_TX, tx->GetHash().ToUint256()}}}); } @@ -3585,17 +3584,17 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string } if (pfrom.ExpectServicesFromConn() && !HasAllDesirableServiceFlags(nServices)) { - LogDebug(BCLog::NET, "peer does not offer the expected services (%08x offered, %08x expected), %s\n", + LogDebug(BCLog::NET, "peer does not offer the expected services (%08x offered, %08x expected), %s", nServices, GetDesirableServiceFlags(nServices), - pfrom.DisconnectMsg(fLogIPs)); + pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } if (nVersion < MIN_PEER_PROTO_VERSION) { // disconnect from peers older than this proto version - LogDebug(BCLog::NET, "peer using obsolete version %i, %s\n", nVersion, pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "peer using obsolete version %i, %s", nVersion, pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -3669,17 +3668,17 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string } 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", + LogDebug(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, txrelay=%d, %s%s", cleanSubVer.empty() ? "" : cleanSubVer, pfrom.nVersion, - peer.m_starting_height, addrMe.ToStringAddrPort(), fRelay, pfrom.GetId(), - pfrom.LogIP(fLogIPs), (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "")); + peer.m_starting_height, addrMe.ToStringAddrPort(), fRelay, pfrom.LogPeer(), + (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "")); if (pfrom.IsPrivateBroadcastConn()) { if (fRelay) { MakeAndPushMessage(pfrom, NetMsgType::VERACK); } else { - LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: does not support transaction relay (connected in vain), peer=%d%s", - pfrom.GetId(), pfrom.LogIP(fLogIPs)); + LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: does not support transaction relay (connected in vain), %s", + pfrom.LogPeer()); pfrom.fDisconnect = true; } return; @@ -3779,7 +3778,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string // Feeler connections exist only to verify if address is online. if (pfrom.IsFeelerConn()) { - LogDebug(BCLog::NET, "feeler connection completed, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "feeler connection completed, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; } return; @@ -3799,11 +3798,11 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string auto new_peer_msg = [&]() { const auto mapped_as{m_connman.GetMappedAS(pfrom.addr)}; - return strprintf("New %s peer connected: transport: %s, version: %d, blocks=%d, peer=%d%s%s", + return strprintf("New %s peer connected: transport: %s, version: %d, blocks=%d, %s%s", pfrom.ConnectionTypeAsString(), TransportTypeAsString(pfrom.m_transport->GetInfo().transport_type), pfrom.nVersion.load(), peer.m_starting_height, - pfrom.GetId(), pfrom.LogIP(fLogIPs), + pfrom.LogPeer(), (mapped_as ? strprintf(", mapped_as=%d", mapped_as) : "")); }; @@ -3900,7 +3899,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (msg_type == NetMsgType::WTXIDRELAY) { if (pfrom.fSuccessfullyConnected) { // Disconnect peers that send a wtxidrelay message after VERACK. - LogDebug(BCLog::NET, "wtxidrelay received after verack, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "wtxidrelay received after verack, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -3922,7 +3921,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (msg_type == NetMsgType::SENDADDRV2) { if (pfrom.fSuccessfullyConnected) { // Disconnect peers that send a SENDADDRV2 message after VERACK. - LogDebug(BCLog::NET, "sendaddrv2 received after verack, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "sendaddrv2 received after verack, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -3940,14 +3939,14 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string } if (pfrom.fSuccessfullyConnected) { - LogDebug(BCLog::NET, "sendtxrcncl received after verack, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "sendtxrcncl received after verack, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } // Peer must not offer us reconciliations if we specified no tx relay support in VERSION. if (RejectIncomingTxs(pfrom)) { - LogDebug(BCLog::NET, "sendtxrcncl received to which we indicated no tx relay, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "sendtxrcncl received to which we indicated no tx relay, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -3957,7 +3956,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string // 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)) { - LogDebug(BCLog::NET, "sendtxrcncl received which indicated no tx relay to us, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "sendtxrcncl received which indicated no tx relay to us, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -3975,11 +3974,11 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string case ReconciliationRegisterResult::SUCCESS: break; case ReconciliationRegisterResult::ALREADY_REGISTERED: - LogDebug(BCLog::NET, "txreconciliation protocol violation (sendtxrcncl received from already registered peer), %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "txreconciliation protocol violation (sendtxrcncl received from already registered peer), %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; case ReconciliationRegisterResult::PROTOCOL_VIOLATION: - LogDebug(BCLog::NET, "txreconciliation protocol violation, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "txreconciliation protocol violation, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -3993,7 +3992,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (pfrom.IsPrivateBroadcastConn()) { if (msg_type != NetMsgType::PONG && msg_type != NetMsgType::GETDATA) { - LogDebug(BCLog::PRIVBROADCAST, "Ignoring incoming message '%s', peer=%d%s", msg_type, pfrom.GetId(), pfrom.LogIP(fLogIPs)); + LogDebug(BCLog::PRIVBROADCAST, "Ignoring incoming message '%s', %s", msg_type, pfrom.LogPeer()); return; } } @@ -4089,7 +4088,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string // AddrFetch: Require multiple addresses to avoid disconnecting on self-announcements if (pfrom.IsAddrFetchConn() && vAddr.size() > 1) { - LogDebug(BCLog::NET, "addrfetch connection completed, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "addrfetch connection completed, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; } return; @@ -4139,7 +4138,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string } } else if (inv.IsGenTxMsg()) { if (reject_tx_invs) { - LogDebug(BCLog::NET, "transaction (%s) inv sent in violation of protocol, %s\n", inv.hash.ToString(), pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "transaction (%s) inv sent in violation of protocol, %s", inv.hash.ToString(), pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -4204,8 +4203,8 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (pfrom.IsPrivateBroadcastConn()) { const auto pushed_tx_opt{m_tx_for_private_broadcast.GetTxForNode(pfrom.GetId())}; if (!pushed_tx_opt) { - LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: got GETDATA without sending an INV, peer=%d%s", - pfrom.GetId(), fLogIPs ? strprintf(", peeraddr=%s", pfrom.addr.ToStringAddrPort()) : ""); + LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: got GETDATA without sending an INV, %s", + pfrom.LogPeer()); pfrom.fDisconnect = true; return; } @@ -4221,8 +4220,8 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string peer.m_ping_queued = true; // Ensure a ping will be sent: mimic a request via RPC. MaybeSendPing(pfrom, peer, GetTime()); } else { - LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: got an unexpected GETDATA message, peer=%d%s", - pfrom.GetId(), fLogIPs ? strprintf(", peeraddr=%s", pfrom.addr.ToStringAddrPort()) : ""); + LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: got an unexpected GETDATA message, %s", + pfrom.LogPeer()); pfrom.fDisconnect = true; } return; @@ -4243,7 +4242,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string vRecv >> locator >> hashStop; if (locator.vHave.size() > MAX_LOCATOR_SZ) { - LogDebug(BCLog::NET, "getblocks locator size %lld > %d, %s\n", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "getblocks locator size %lld > %d, %s", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -4370,7 +4369,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string vRecv >> locator >> hashStop; if (locator.vHave.size() > MAX_LOCATOR_SZ) { - LogDebug(BCLog::NET, "getheaders locator size %lld > %d, %s\n", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "getheaders locator size %lld > %d, %s", locator.vHave.size(), MAX_LOCATOR_SZ, pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -4445,7 +4444,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (msg_type == NetMsgType::TX) { if (RejectIncomingTxs(pfrom)) { - LogDebug(BCLog::NET, "transaction sent in violation of protocol, %s", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "transaction sent in violation of protocol, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -4466,8 +4465,8 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (const auto num_broadcasted{m_tx_for_private_broadcast.Remove(ptx)}) { LogDebug(BCLog::PRIVBROADCAST, "Received our privately broadcast transaction (txid=%s) from the " - "network from peer=%d%s; stopping private broadcast attempts", - txid.ToString(), pfrom.GetId(), pfrom.LogIP(fLogIPs)); + "network from %s; stopping private broadcast attempts", + txid.ToString(), pfrom.LogPeer()); if (NUM_PRIVATE_BROADCAST_PER_TX > num_broadcasted.value()) { // Not all of the initial NUM_PRIVATE_BROADCAST_PER_TX connections were needed. // Tell CConnman it does not need to start the remaining ones. @@ -4917,7 +4916,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string { if (!pfrom.HasPermission(NetPermissionFlags::NoBan)) { - LogDebug(BCLog::NET, "mempool request with bloom filters disabled, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "mempool request with bloom filters disabled, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; } return; @@ -4927,7 +4926,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string { if (!pfrom.HasPermission(NetPermissionFlags::NoBan)) { - LogDebug(BCLog::NET, "mempool request with bandwidth limit reached, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "mempool request with bandwidth limit reached, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; } return; @@ -4981,8 +4980,8 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string pfrom.PongReceived(ping_time); if (pfrom.IsPrivateBroadcastConn()) { m_tx_for_private_broadcast.NodeConfirmedReception(pfrom.GetId()); - LogDebug(BCLog::PRIVBROADCAST, "Got a PONG (the transaction will probably reach the network), marking for disconnect, peer=%d%s", - pfrom.GetId(), pfrom.LogIP(fLogIPs)); + LogDebug(BCLog::PRIVBROADCAST, "Got a PONG (the transaction will probably reach the network), marking for disconnect, %s", + pfrom.LogPeer()); pfrom.fDisconnect = true; } } else { @@ -5023,7 +5022,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (msg_type == NetMsgType::FILTERLOAD) { if (!(peer.m_our_services & NODE_BLOOM)) { - LogDebug(BCLog::NET, "filterload received despite not offering bloom services, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "filterload received despite not offering bloom services, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -5048,7 +5047,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (msg_type == NetMsgType::FILTERADD) { if (!(peer.m_our_services & NODE_BLOOM)) { - LogDebug(BCLog::NET, "filteradd received despite not offering bloom services, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "filteradd received despite not offering bloom services, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -5076,7 +5075,7 @@ void PeerManagerImpl::ProcessMessage(Peer& peer, CNode& pfrom, const std::string if (msg_type == NetMsgType::FILTERCLEAR) { if (!(peer.m_our_services & NODE_BLOOM)) { - LogDebug(BCLog::NET, "filterclear received despite not offering bloom services, %s\n", pfrom.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "filterclear received despite not offering bloom services, %s", pfrom.DisconnectMsg()); pfrom.fDisconnect = true; return; } @@ -5298,7 +5297,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! - LogInfo("Outbound peer has old chain, best known block = %s, %s\n", state.pindexBestKnownBlock != nullptr ? state.pindexBestKnownBlock->GetBlockHash().ToString() : "", pto.DisconnectMsg(fLogIPs)); + LogInfo("Outbound peer has old chain, best known block = %s, %s", state.pindexBestKnownBlock != nullptr ? state.pindexBestKnownBlock->GetBlockHash().ToString() : "", pto.DisconnectMsg()); pto.fDisconnect = true; } else { assert(state.m_chain_sync.m_work_header); @@ -5465,7 +5464,7 @@ void PeerManagerImpl::MaybeSendPing(CNode& node_to, Peer& peer, std::chrono::mic { // The ping timeout is using mocktime. To disable the check during // testing, increase -peertimeout. - LogDebug(BCLog::NET, "ping timeout: %fs, %s", 0.000001 * count_microseconds(now - peer.m_ping_start.load()), node_to.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "ping timeout: %fs, %s", 0.000001 * count_microseconds(now - peer.m_ping_start.load()), node_to.DisconnectMsg()); node_to.fDisconnect = true; return; } @@ -5714,15 +5713,15 @@ bool PeerManagerImpl::SendMessages(CNode& node) // not sent. This here is just an optimization. if (node.IsPrivateBroadcastConn()) { if (node.m_connected + PRIVATE_BROADCAST_MAX_CONNECTION_LIFETIME < current_time) { - LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: did not complete the transaction send within %d seconds, peer=%d%s", - count_seconds(PRIVATE_BROADCAST_MAX_CONNECTION_LIFETIME), node.GetId(), node.LogIP(fLogIPs)); + LogDebug(BCLog::PRIVBROADCAST, "Disconnecting: did not complete the transaction send within %d seconds, %s", + count_seconds(PRIVATE_BROADCAST_MAX_CONNECTION_LIFETIME), node.LogPeer()); node.fDisconnect = true; } return true; } if (node.IsAddrFetchConn() && current_time - node.m_connected > 10 * AVG_ADDRESS_BROADCAST_INTERVAL) { - LogDebug(BCLog::NET, "addrfetch connection timeout, %s\n", node.DisconnectMsg(fLogIPs)); + LogDebug(BCLog::NET, "addrfetch connection timeout, %s", node.DisconnectMsg()); node.fDisconnect = true; return true; } @@ -6070,7 +6069,7 @@ bool PeerManagerImpl::SendMessages(CNode& node) // 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. - LogInfo("Peer is stalling block download, %s\n", node.DisconnectMsg(fLogIPs)); + LogInfo("Peer is stalling block download, %s", node.DisconnectMsg()); node.fDisconnect = true; // Increase timeout for the next peer so that we don't disconnect multiple peers if our own // bandwidth is insufficient. @@ -6089,7 +6088,7 @@ bool PeerManagerImpl::SendMessages(CNode& node) 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)) { - LogInfo("Timeout downloading block %s, %s\n", queuedBlock.pindex->GetBlockHash().ToString(), node.DisconnectMsg(fLogIPs)); + LogInfo("Timeout downloading block %s, %s", queuedBlock.pindex->GetBlockHash().ToString(), node.DisconnectMsg()); node.fDisconnect = true; return true; } @@ -6105,11 +6104,11 @@ bool PeerManagerImpl::SendMessages(CNode& node) // disconnect our sync peer for stalling; we have bigger // problems if we can't get any outbound peers. if (!node.HasPermission(NetPermissionFlags::NoBan)) { - LogInfo("Timeout downloading headers, %s\n", node.DisconnectMsg(fLogIPs)); + LogInfo("Timeout downloading headers, %s", node.DisconnectMsg()); node.fDisconnect = true; return true; } else { - LogInfo("Timeout downloading headers from noban peer, not %s\n", node.DisconnectMsg(fLogIPs)); + LogInfo("Timeout downloading headers from noban peer, not %s", node.DisconnectMsg()); // 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_logging.py b/test/functional/feature_logging.py index 5a4ef515fb0..07420733e00 100755 --- a/test/functional/feature_logging.py +++ b/test/functional/feature_logging.py @@ -118,7 +118,7 @@ class LoggingTest(BitcoinTestFramework): self.log.info("Test -logips formatting in net logs") self.restart_node(0, ['-debug=net', '-logips=1']) - with self.nodes[0].assert_debug_log(["peer=0 peeraddr="]): + with self.nodes[0].assert_debug_log(["peer=0, peeraddr="]): p2p = self.nodes[0].add_p2p_connection(P2PInterface()) p2p.wait_for_verack() self.nodes[0].disconnect_p2ps()