Skip to content

Commit c8b8351

Browse files
author
MarcoFalke
committed
Merge #20724: Cleanup of -debug=net log messages
48c8a9b net_processing: log txrelay flag from version message (Anthony Towns) 98fab37 net: use peer=N instead of from=N in debug log (Anthony Towns) 1230210 net_processing: additional debug logging for ignored messages (Anthony Towns) f7edea3 net: make debug logging conditional on -debug=net (Anthony Towns) a410ae8 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 48c8a9b MarcoFalke: re-ACK 48c8a9b only change is rebase 🚓 practicalswift: re-ACK 48c8a9b Tree-SHA512: 6ac530d883dffc4fd7fe20b1dc5ebb5394374c9b499aa7a253eb4a3a660d8901edd72e5ad21ce4a2bf71df25e8f142087755f9756f3497f564ef453a7e9246c1
2 parents 40dd757 + 48c8a9b commit c8b8351

File tree

3 files changed

+38
-17
lines changed

3 files changed

+38
-17
lines changed

‎src/net.cpp

Lines changed: 11 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -815,7 +815,7 @@ size_t CConnman::SocketSendData(CNode& node) const
815815
// error
816816
int nErr = WSAGetLastError();
817817
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) {
818-
LogPrintf("socket send error %s\n", NetworkErrorString(nErr));
818+
LogPrint(BCLog::NET, "socket send error for peer=%d: %s\n", node.GetId(), NetworkErrorString(nErr));
819819
node.CloseSocketDisconnect();
820820
}
821821
}
@@ -1004,6 +1004,7 @@ bool CConnman::AttemptToEvictConnection()
10041004
LOCK(cs_vNodes);
10051005
for (CNode* pnode : vNodes) {
10061006
if (pnode->GetId() == *node_id_to_evict) {
1007+
LogPrint(BCLog::NET, "selected %s connection for eviction peer=%d; disconnecting\n", pnode->ConnectionTypeAsString(), pnode->GetId());
10071008
pnode->fDisconnect = true;
10081009
return true;
10091010
}
@@ -1052,7 +1053,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) {
10521053
}
10531054

10541055
if (!fNetworkActive) {
1055-
LogPrintf("connection from %s dropped: not accepting new connections\n", addr.ToString());
1056+
LogPrint(BCLog::NET, "connection from %s dropped: not accepting new connections\n", addr.ToString());
10561057
CloseSocket(hSocket);
10571058
return;
10581059
}
@@ -1230,30 +1231,30 @@ bool CConnman::InactivityCheck(const CNode& node) const
12301231
}
12311232

12321233
if (node.nLastRecv == 0 || node.nLastSend == 0) {
1233-
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());
1234+
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());
12341235
return true;
12351236
}
12361237

12371238
if (now > node.nLastSend + TIMEOUT_INTERVAL) {
1238-
LogPrintf("socket sending timeout: %is\n", now - node.nLastSend);
1239+
LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", now - node.nLastSend, node.GetId());
12391240
return true;
12401241
}
12411242

12421243
if (now > node.nLastRecv + TIMEOUT_INTERVAL) {
1243-
LogPrintf("socket receive timeout: %is\n", now - node.nLastRecv);
1244+
LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", now - node.nLastRecv, node.GetId());
12441245
return true;
12451246
}
12461247

12471248
if (node.nPingNonceSent && node.m_ping_start.load() + std::chrono::seconds{TIMEOUT_INTERVAL} < GetTime<std::chrono::microseconds>()) {
12481249
// We use mockable time for ping timeouts. This means that setmocktime
12491250
// may cause pings to time out for peers that have been connected for
12501251
// longer than m_peer_connect_timeout.
1251-
LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - node.m_ping_start.load()));
1252+
LogPrint(BCLog::NET, "ping timeout: %fs peer=%d\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - node.m_ping_start.load()), node.GetId());
12521253
return true;
12531254
}
12541255

12551256
if (!node.fSuccessfullyConnected) {
1256-
LogPrint(BCLog::NET, "version handshake timeout from %d\n", node.GetId());
1257+
LogPrint(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId());
12571258
return true;
12581259
}
12591260

@@ -2693,6 +2694,7 @@ bool CConnman::DisconnectNode(const std::string& strNode)
26932694
{
26942695
LOCK(cs_vNodes);
26952696
if (CNode* pnode = FindNode(strNode)) {
2697+
LogPrint(BCLog::NET, "disconnect by address%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", strNode) : ""), pnode->GetId());
26962698
pnode->fDisconnect = true;
26972699
return true;
26982700
}
@@ -2705,6 +2707,7 @@ bool CConnman::DisconnectNode(const CSubNet& subnet)
27052707
LOCK(cs_vNodes);
27062708
for (CNode* pnode : vNodes) {
27072709
if (subnet.Match(pnode->addr)) {
2710+
LogPrint(BCLog::NET, "disconnect by subnet%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->GetId());
27082711
pnode->fDisconnect = true;
27092712
disconnected = true;
27102713
}
@@ -2722,6 +2725,7 @@ bool CConnman::DisconnectNode(NodeId id)
27222725
LOCK(cs_vNodes);
27232726
for(CNode* pnode : vNodes) {
27242727
if (id == pnode->GetId()) {
2728+
LogPrint(BCLog::NET, "disconnect by id peer=%d; disconnecting\n", pnode->GetId());
27252729
pnode->fDisconnect = true;
27262730
return true;
27272731
}

‎src/net_processing.cpp

Lines changed: 24 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -880,13 +880,14 @@ void PeerManagerImpl::PushNodeVersion(CNode& pnode, int64_t nTime)
880880
CAddress(CService(), addr.nServices);
881881
CAddress addrMe = CAddress(CService(), nLocalNodeServices);
882882

883+
const bool tx_relay = !m_ignore_incoming_txs && pnode.m_tx_relay != nullptr;
883884
m_connman.PushMessage(&pnode, CNetMsgMaker(INIT_PROTO_VERSION).Make(NetMsgType::VERSION, PROTOCOL_VERSION, (uint64_t)nLocalNodeServices, nTime, addrYou, addrMe,
884-
nonce, strSubVersion, nNodeStartingHeight, !m_ignore_incoming_txs && pnode.m_tx_relay != nullptr));
885+
nonce, strSubVersion, nNodeStartingHeight, tx_relay));
885886

886887
if (fLogIPs) {
887-
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);
888+
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);
888889
} else {
889-
LogPrint(BCLog::NET, "send version message: version %d, blocks=%d, us=%s, peer=%d\n", PROTOCOL_VERSION, nNodeStartingHeight, addrMe.ToString(), nodeid);
890+
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);
890891
}
891892
}
892893

@@ -2642,9 +2643,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
26422643
if (fLogIPs)
26432644
remoteAddr = ", peeraddr=" + pfrom.addr.ToString();
26442645

2645-
LogPrint(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, peer=%d%s\n",
2646+
LogPrint(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, txrelay=%d, peer=%d%s\n",
26462647
cleanSubVer, pfrom.nVersion,
2647-
peer->m_starting_height, addrMe.ToString(), pfrom.GetId(),
2648+
peer->m_starting_height, addrMe.ToString(), fRelay, pfrom.GetId(),
26482649
remoteAddr);
26492650

26502651
int64_t nTimeOffset = nTime - GetTime();
@@ -2659,6 +2660,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
26592660

26602661
// Feeler connections exist only to verify if address is online.
26612662
if (pfrom.IsFeelerConn()) {
2663+
LogPrint(BCLog::NET, "feeler connection completed peer=%d; disconnecting\n", pfrom.GetId());
26622664
pfrom.fDisconnect = true;
26632665
}
26642666
return;
@@ -2674,7 +2676,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
26742676
const CNetMsgMaker msgMaker(pfrom.GetCommonVersion());
26752677

26762678
if (msg_type == NetMsgType::VERACK) {
2677-
if (pfrom.fSuccessfullyConnected) return;
2679+
if (pfrom.fSuccessfullyConnected) {
2680+
LogPrint(BCLog::NET, "ignoring redundant verack message from peer=%d\n", pfrom.GetId());
2681+
return;
2682+
}
26782683

26792684
if (!pfrom.IsInboundConn()) {
26802685
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,
27462751
if (pfrom.fSuccessfullyConnected) {
27472752
// Disconnect peers that send wtxidrelay message after VERACK; this
27482753
// must be negotiated between VERSION and VERACK.
2754+
LogPrint(BCLog::NET, "wtxidrelay received after verack from peer=%d; disconnecting\n", pfrom.GetId());
27492755
pfrom.fDisconnect = true;
27502756
return;
27512757
}
@@ -2754,7 +2760,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
27542760
if (!State(pfrom.GetId())->m_wtxid_relay) {
27552761
State(pfrom.GetId())->m_wtxid_relay = true;
27562762
g_wtxid_relay_peers++;
2763+
} else {
2764+
LogPrint(BCLog::NET, "ignoring duplicate wtxidrelay from peer=%d\n", pfrom.GetId());
27572765
}
2766+
} else {
2767+
LogPrint(BCLog::NET, "ignoring wtxidrelay due to old common version=%d from peer=%d\n", pfrom.GetCommonVersion(), pfrom.GetId());
27582768
}
27592769
return;
27602770
}
@@ -2763,6 +2773,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
27632773
if (pfrom.fSuccessfullyConnected) {
27642774
// Disconnect peers that send SENDADDRV2 message after VERACK; this
27652775
// must be negotiated between VERSION and VERACK.
2776+
LogPrint(BCLog::NET, "sendaddrv2 received after verack from peer=%d; disconnecting\n", pfrom.GetId());
27662777
pfrom.fDisconnect = true;
27672778
return;
27682779
}
@@ -2789,6 +2800,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
27892800
s >> vAddr;
27902801

27912802
if (!pfrom.RelayAddrsWithConn()) {
2803+
LogPrint(BCLog::NET, "ignoring %s message from %s peer=%d\n", msg_type, pfrom.ConnectionTypeAsString(), pfrom.GetId());
27922804
return;
27932805
}
27942806
if (vAddr.size() > MAX_ADDR_TO_SEND)
@@ -2832,8 +2844,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
28322844
m_connman.AddNewAddresses(vAddrOk, pfrom.addr, 2 * 60 * 60);
28332845
if (vAddr.size() < 1000)
28342846
pfrom.fGetAddr = false;
2835-
if (pfrom.IsAddrFetchConn())
2847+
if (pfrom.IsAddrFetchConn()) {
2848+
LogPrint(BCLog::NET, "addrfetch connection completed peer=%d; disconnecting\n", pfrom.GetId());
28362849
pfrom.fDisconnect = true;
2850+
}
28372851
return;
28382852
}
28392853

@@ -3840,6 +3854,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
38403854

38413855
if (msg_type == NetMsgType::FILTERLOAD) {
38423856
if (!(pfrom.GetLocalServices() & NODE_BLOOM)) {
3857+
LogPrint(BCLog::NET, "filterload received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId());
38433858
pfrom.fDisconnect = true;
38443859
return;
38453860
}
@@ -3862,6 +3877,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
38623877

38633878
if (msg_type == NetMsgType::FILTERADD) {
38643879
if (!(pfrom.GetLocalServices() & NODE_BLOOM)) {
3880+
LogPrint(BCLog::NET, "filteradd received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId());
38653881
pfrom.fDisconnect = true;
38663882
return;
38673883
}
@@ -3889,6 +3905,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
38893905

38903906
if (msg_type == NetMsgType::FILTERCLEAR) {
38913907
if (!(pfrom.GetLocalServices() & NODE_BLOOM)) {
3908+
LogPrint(BCLog::NET, "filterclear received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId());
38923909
pfrom.fDisconnect = true;
38933910
return;
38943911
}

‎test/functional/p2p_timeouts.py

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -74,9 +74,9 @@ def run_test(self):
7474
no_version_node.send_message(msg_ping())
7575

7676
expected_timeout_logs = [
77-
"version handshake timeout from 0",
78-
"socket no message in first 3 seconds, 1 0 from 1",
79-
"socket no message in first 3 seconds, 0 0 from 2",
77+
"version handshake timeout peer=0",
78+
"socket no message in first 3 seconds, 1 0 peer=1",
79+
"socket no message in first 3 seconds, 0 0 peer=2",
8080
]
8181

8282
with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):

0 commit comments

Comments
 (0)