diff options
author | MarcoFalke <falke.marco@gmail.com> | 2021-01-29 07:44:06 +0100 |
---|---|---|
committer | MarcoFalke <falke.marco@gmail.com> | 2021-01-29 07:44:22 +0100 |
commit | c8b83510f42c6959c2844b8b81a6590dd3a34e65 (patch) | |
tree | af6aabe71bf8863a7ee7638d0cb0ad9ab19a618b /src | |
parent | 40dd757bf6ce1ae81599af4d204e210583b7c7bc (diff) | |
parent | 48c8a9b96453ca429b38fc5d5181a310ae5a93bf (diff) | |
download | bitcoin-c8b83510f42c6959c2844b8b81a6590dd3a34e65.tar.xz |
Merge #20724: Cleanup of -debug=net log messages
48c8a9b96453ca429b38fc5d5181a310ae5a93bf net_processing: log txrelay flag from version message (Anthony Towns)
98fab37ca0517bfe58296e47266cd5bd112e90bf net: use peer=N instead of from=N in debug log (Anthony Towns)
12302105bb0bf14721e91b7a3a9d1bf83c8d4154 net_processing: additional debug logging for ignored messages (Anthony Towns)
f7edea3b7c873d6c9bcd50cf528349ef84961a75 net: make debug logging conditional on -debug=net (Anthony Towns)
a410ae8cb09f1b809755316566f9e6bccd41c0c4 net, net_processing: log disconnect reasons with -debug=net (Anthony Towns)
Pull request description:
A few changes to -debug=net logging:
* always log when disconnecting a peer
* only log various connection errors when -debug=net is enabled, since errors from random untrusted peers is completely expected
* log when ignoring a message due to violating protocol (primarily to make it easier to debug other implementations)
* use "peer=123" rather than "from 123" to make grepping logs a bit easier
* log the value of the bip-37 `fRelay` field in version messages both when sending and receiving a version message
ACKs for top commit:
jnewbery:
ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf
MarcoFalke:
re-ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf only change is rebase 🚓
practicalswift:
re-ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf
Tree-SHA512: 6ac530d883dffc4fd7fe20b1dc5ebb5394374c9b499aa7a253eb4a3a660d8901edd72e5ad21ce4a2bf71df25e8f142087755f9756f3497f564ef453a7e9246c1
Diffstat (limited to 'src')
-rw-r--r-- | src/net.cpp | 18 | ||||
-rw-r--r-- | src/net_processing.cpp | 31 |
2 files changed, 35 insertions, 14 deletions
diff --git a/src/net.cpp b/src/net.cpp index 4759287c36..76bf7effa4 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -815,7 +815,7 @@ size_t CConnman::SocketSendData(CNode& node) const // error int nErr = WSAGetLastError(); if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) { - LogPrintf("socket send error %s\n", NetworkErrorString(nErr)); + LogPrint(BCLog::NET, "socket send error for peer=%d: %s\n", node.GetId(), NetworkErrorString(nErr)); node.CloseSocketDisconnect(); } } @@ -1004,6 +1004,7 @@ bool CConnman::AttemptToEvictConnection() LOCK(cs_vNodes); for (CNode* pnode : vNodes) { if (pnode->GetId() == *node_id_to_evict) { + LogPrint(BCLog::NET, "selected %s connection for eviction peer=%d; disconnecting\n", pnode->ConnectionTypeAsString(), pnode->GetId()); pnode->fDisconnect = true; return true; } @@ -1052,7 +1053,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) { } if (!fNetworkActive) { - LogPrintf("connection from %s dropped: not accepting new connections\n", addr.ToString()); + LogPrint(BCLog::NET, "connection from %s dropped: not accepting new connections\n", addr.ToString()); CloseSocket(hSocket); return; } @@ -1230,17 +1231,17 @@ bool CConnman::InactivityCheck(const CNode& node) const } if (node.nLastRecv == 0 || node.nLastSend == 0) { - LogPrint(BCLog::NET, "socket no message in first %i seconds, %d %d from %d\n", m_peer_connect_timeout, node.nLastRecv != 0, node.nLastSend != 0, node.GetId()); + LogPrint(BCLog::NET, "socket no message in first %i seconds, %d %d peer=%d\n", m_peer_connect_timeout, node.nLastRecv != 0, node.nLastSend != 0, node.GetId()); return true; } if (now > node.nLastSend + TIMEOUT_INTERVAL) { - LogPrintf("socket sending timeout: %is\n", now - node.nLastSend); + LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", now - node.nLastSend, node.GetId()); return true; } if (now > node.nLastRecv + TIMEOUT_INTERVAL) { - LogPrintf("socket receive timeout: %is\n", now - node.nLastRecv); + LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", now - node.nLastRecv, node.GetId()); return true; } @@ -1248,12 +1249,12 @@ bool CConnman::InactivityCheck(const CNode& node) const // We use mockable time for ping timeouts. This means that setmocktime // may cause pings to time out for peers that have been connected for // longer than m_peer_connect_timeout. - LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - node.m_ping_start.load())); + LogPrint(BCLog::NET, "ping timeout: %fs peer=%d\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - node.m_ping_start.load()), node.GetId()); return true; } if (!node.fSuccessfullyConnected) { - LogPrint(BCLog::NET, "version handshake timeout from %d\n", node.GetId()); + LogPrint(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId()); return true; } @@ -2693,6 +2694,7 @@ bool CConnman::DisconnectNode(const std::string& strNode) { LOCK(cs_vNodes); if (CNode* pnode = FindNode(strNode)) { + LogPrint(BCLog::NET, "disconnect by address%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", strNode) : ""), pnode->GetId()); pnode->fDisconnect = true; return true; } @@ -2705,6 +2707,7 @@ bool CConnman::DisconnectNode(const CSubNet& subnet) LOCK(cs_vNodes); for (CNode* pnode : vNodes) { if (subnet.Match(pnode->addr)) { + LogPrint(BCLog::NET, "disconnect by subnet%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->GetId()); pnode->fDisconnect = true; disconnected = true; } @@ -2722,6 +2725,7 @@ bool CConnman::DisconnectNode(NodeId id) LOCK(cs_vNodes); for(CNode* pnode : vNodes) { if (id == pnode->GetId()) { + LogPrint(BCLog::NET, "disconnect by id peer=%d; disconnecting\n", pnode->GetId()); pnode->fDisconnect = true; return true; } diff --git a/src/net_processing.cpp b/src/net_processing.cpp index cf73b1dae2..a4070f5b63 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -880,13 +880,14 @@ void PeerManagerImpl::PushNodeVersion(CNode& pnode, int64_t nTime) CAddress(CService(), addr.nServices); CAddress addrMe = CAddress(CService(), nLocalNodeServices); + const bool tx_relay = !m_ignore_incoming_txs && pnode.m_tx_relay != nullptr; m_connman.PushMessage(&pnode, CNetMsgMaker(INIT_PROTO_VERSION).Make(NetMsgType::VERSION, PROTOCOL_VERSION, (uint64_t)nLocalNodeServices, nTime, addrYou, addrMe, - nonce, strSubVersion, nNodeStartingHeight, !m_ignore_incoming_txs && pnode.m_tx_relay != nullptr)); + nonce, strSubVersion, nNodeStartingHeight, tx_relay)); if (fLogIPs) { - LogPrint(BCLog::NET, "send version message: version %d, blocks=%d, us=%s, them=%s, peer=%d\n", PROTOCOL_VERSION, nNodeStartingHeight, addrMe.ToString(), addrYou.ToString(), nodeid); + LogPrint(BCLog::NET, "send version message: version %d, blocks=%d, us=%s, them=%s, txrelay=%d, peer=%d\n", PROTOCOL_VERSION, nNodeStartingHeight, addrMe.ToString(), addrYou.ToString(), tx_relay, nodeid); } else { - LogPrint(BCLog::NET, "send version message: version %d, blocks=%d, us=%s, peer=%d\n", PROTOCOL_VERSION, nNodeStartingHeight, addrMe.ToString(), nodeid); + LogPrint(BCLog::NET, "send version message: version %d, blocks=%d, us=%s, txrelay=%d, peer=%d\n", PROTOCOL_VERSION, nNodeStartingHeight, addrMe.ToString(), tx_relay, nodeid); } } @@ -2642,9 +2643,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (fLogIPs) remoteAddr = ", peeraddr=" + pfrom.addr.ToString(); - LogPrint(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, peer=%d%s\n", + LogPrint(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, txrelay=%d, peer=%d%s\n", cleanSubVer, pfrom.nVersion, - peer->m_starting_height, addrMe.ToString(), pfrom.GetId(), + peer->m_starting_height, addrMe.ToString(), fRelay, pfrom.GetId(), remoteAddr); int64_t nTimeOffset = nTime - GetTime(); @@ -2659,6 +2660,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, // Feeler connections exist only to verify if address is online. if (pfrom.IsFeelerConn()) { + LogPrint(BCLog::NET, "feeler connection completed peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; } return; @@ -2674,7 +2676,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, const CNetMsgMaker msgMaker(pfrom.GetCommonVersion()); if (msg_type == NetMsgType::VERACK) { - if (pfrom.fSuccessfullyConnected) return; + if (pfrom.fSuccessfullyConnected) { + LogPrint(BCLog::NET, "ignoring redundant verack message from peer=%d\n", pfrom.GetId()); + return; + } if (!pfrom.IsInboundConn()) { LogPrintf("New outbound peer connected: version: %d, blocks=%d, peer=%d%s (%s)\n", @@ -2746,6 +2751,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (pfrom.fSuccessfullyConnected) { // Disconnect peers that send wtxidrelay message after VERACK; this // must be negotiated between VERSION and VERACK. + LogPrint(BCLog::NET, "wtxidrelay received after verack from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } @@ -2754,7 +2760,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (!State(pfrom.GetId())->m_wtxid_relay) { State(pfrom.GetId())->m_wtxid_relay = true; g_wtxid_relay_peers++; + } else { + LogPrint(BCLog::NET, "ignoring duplicate wtxidrelay from peer=%d\n", pfrom.GetId()); } + } else { + LogPrint(BCLog::NET, "ignoring wtxidrelay due to old common version=%d from peer=%d\n", pfrom.GetCommonVersion(), pfrom.GetId()); } return; } @@ -2763,6 +2773,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (pfrom.fSuccessfullyConnected) { // Disconnect peers that send SENDADDRV2 message after VERACK; this // must be negotiated between VERSION and VERACK. + LogPrint(BCLog::NET, "sendaddrv2 received after verack from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } @@ -2789,6 +2800,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, s >> vAddr; if (!pfrom.RelayAddrsWithConn()) { + LogPrint(BCLog::NET, "ignoring %s message from %s peer=%d\n", msg_type, pfrom.ConnectionTypeAsString(), pfrom.GetId()); return; } if (vAddr.size() > MAX_ADDR_TO_SEND) @@ -2832,8 +2844,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, m_connman.AddNewAddresses(vAddrOk, pfrom.addr, 2 * 60 * 60); if (vAddr.size() < 1000) pfrom.fGetAddr = false; - if (pfrom.IsAddrFetchConn()) + if (pfrom.IsAddrFetchConn()) { + LogPrint(BCLog::NET, "addrfetch connection completed peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; + } return; } @@ -3840,6 +3854,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::FILTERLOAD) { if (!(pfrom.GetLocalServices() & NODE_BLOOM)) { + LogPrint(BCLog::NET, "filterload received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } @@ -3862,6 +3877,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::FILTERADD) { if (!(pfrom.GetLocalServices() & NODE_BLOOM)) { + LogPrint(BCLog::NET, "filteradd received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } @@ -3889,6 +3905,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (msg_type == NetMsgType::FILTERCLEAR) { if (!(pfrom.GetLocalServices() & NODE_BLOOM)) { + LogPrint(BCLog::NET, "filterclear received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId()); pfrom.fDisconnect = true; return; } |