Skip to content

Commit ad22442

Browse files
SjorsSjors
committed
net: additional disconnection logging
Use the word "disconnecting" everywhere for easier grep.
1 parent f7144b2 commit ad22442

File tree

4 files changed

+49
-18
lines changed

4 files changed

+49
-18
lines changed

‎src/net.cpp‎

Lines changed: 33 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -558,7 +558,6 @@ void CNode::CloseSocketDisconnect()
558558
fDisconnect = true;
559559
LOCK(m_sock_mutex);
560560
if (m_sock) {
561-
LogDebug(BCLog::NET, "disconnecting peer=%d\n", id);
562561
m_sock.reset();
563562
}
564563
m_i2p_sam_session.reset();
@@ -696,6 +695,13 @@ bool CNode::ReceiveMsgBytes(Span<const uint8_t> msg_bytes, bool& complete)
696695
return true;
697696
}
698697

698+
std::string CNode::DisconnectMsg(bool log_ip) const
699+
{
700+
return strprintf("disconnecting peer=%d%s",
701+
GetId(),
702+
log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : "");
703+
}
704+
699705
V1Transport::V1Transport(const NodeId node_id) noexcept
700706
: m_magic_bytes{Params().MessageStart()}, m_node_id{node_id}
701707
{
@@ -1635,7 +1641,7 @@ std::pair<size_t, bool> CConnman::SocketSendData(CNode& node) const
16351641
// error
16361642
int nErr = WSAGetLastError();
16371643
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) {
1638-
LogDebug(BCLog::NET, "socket send error for peer=%d: %s\n", node.GetId(), NetworkErrorString(nErr));
1644+
LogDebug(BCLog::NET, "socket send error, %s: %s\n", node.DisconnectMsg(fLogIPs), NetworkErrorString(nErr));
16391645
node.CloseSocketDisconnect();
16401646
}
16411647
}
@@ -1879,7 +1885,7 @@ void CConnman::DisconnectNodes()
18791885
// Disconnect any connected nodes
18801886
for (CNode* pnode : m_nodes) {
18811887
if (!pnode->fDisconnect) {
1882-
LogDebug(BCLog::NET, "Network not active, dropping peer=%d\n", pnode->GetId());
1888+
LogDebug(BCLog::NET, "Network not active, %s\n", pnode->DisconnectMsg(fLogIPs));
18831889
pnode->fDisconnect = true;
18841890
}
18851891
}
@@ -1972,25 +1978,37 @@ bool CConnman::InactivityCheck(const CNode& node) const
19721978
if (!ShouldRunInactivityChecks(node, now)) return false;
19731979

19741980
if (last_recv.count() == 0 || last_send.count() == 0) {
1975-
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());
1981+
LogDebug(BCLog::NET,
1982+
"socket no message in first %i seconds, %d %d, %s\n",
1983+
count_seconds(m_peer_connect_timeout),
1984+
last_recv.count() != 0,
1985+
last_send.count() != 0,
1986+
node.DisconnectMsg(fLogIPs)
1987+
);
19761988
return true;
19771989
}
19781990

19791991
if (now > last_send + TIMEOUT_INTERVAL) {
1980-
LogDebug(BCLog::NET, "socket sending timeout: %is peer=%d\n", count_seconds(now - last_send), node.GetId());
1992+
LogDebug(BCLog::NET,
1993+
"socket sending timeout: %is, %s\n", count_seconds(now - last_send),
1994+
node.DisconnectMsg(fLogIPs)
1995+
);
19811996
return true;
19821997
}
19831998

19841999
if (now > last_recv + TIMEOUT_INTERVAL) {
1985-
LogDebug(BCLog::NET, "socket receive timeout: %is peer=%d\n", count_seconds(now - last_recv), node.GetId());
2000+
LogDebug(BCLog::NET,
2001+
"socket receive timeout: %is, %s\n", count_seconds(now - last_recv),
2002+
node.DisconnectMsg(fLogIPs)
2003+
);
19862004
return true;
19872005
}
19882006

19892007
if (!node.fSuccessfullyConnected) {
19902008
if (node.m_transport->GetInfo().transport_type == TransportProtocolType::DETECTING) {
1991-
LogDebug(BCLog::NET, "V2 handshake timeout peer=%d\n", node.GetId());
2009+
LogDebug(BCLog::NET, "V2 handshake timeout, %s\n", node.DisconnectMsg(fLogIPs));
19922010
} else {
1993-
LogDebug(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId());
2011+
LogDebug(BCLog::NET, "version handshake timeout, %s\n", node.DisconnectMsg(fLogIPs));
19942012
}
19952013
return true;
19962014
}
@@ -2118,6 +2136,10 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
21182136
{
21192137
bool notify = false;
21202138
if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) {
2139+
LogDebug(BCLog::NET,
2140+
"receiving message bytes failed, %s\n",
2141+
pnode->DisconnectMsg(fLogIPs)
2142+
);
21212143
pnode->CloseSocketDisconnect();
21222144
}
21232145
RecordBytesRecv(nBytes);
@@ -2130,7 +2152,7 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
21302152
{
21312153
// socket closed gracefully
21322154
if (!pnode->fDisconnect) {
2133-
LogDebug(BCLog::NET, "socket closed for peer=%d\n", pnode->GetId());
2155+
LogDebug(BCLog::NET, "socket closed, %s\n", pnode->DisconnectMsg(fLogIPs));
21342156
}
21352157
pnode->CloseSocketDisconnect();
21362158
}
@@ -2141,7 +2163,7 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
21412163
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS)
21422164
{
21432165
if (!pnode->fDisconnect) {
2144-
LogDebug(BCLog::NET, "socket recv error for peer=%d: %s\n", pnode->GetId(), NetworkErrorString(nErr));
2166+
LogDebug(BCLog::NET, "socket recv error, %s: %s\n", pnode->DisconnectMsg(fLogIPs), NetworkErrorString(nErr));
21452167
}
21462168
pnode->CloseSocketDisconnect();
21472169
}
@@ -3411,6 +3433,7 @@ void CConnman::StopNodes()
34113433
std::vector<CNode*> nodes;
34123434
WITH_LOCK(m_nodes_mutex, nodes.swap(m_nodes));
34133435
for (CNode* pnode : nodes) {
3436+
LogDebug(BCLog::NET, "%s\n", pnode->DisconnectMsg(fLogIPs));
34143437
pnode->CloseSocketDisconnect();
34153438
DeleteNode(pnode);
34163439
}

‎src/net.h‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -947,6 +947,14 @@ class CNode
947947

948948
std::string ConnectionTypeAsString() const { return ::ConnectionTypeAsString(m_conn_type); }
949949

950+
/**
951+
* Helper function to log disconnects.
952+
*
953+
* @param[in] log_ip whether to include the IP address
954+
* @return "disconnecting peer=..." and optionally "peeraddr=..."
955+
*/
956+
std::string DisconnectMsg(bool log_ip) const;
957+
950958
/** A ping-pong round trip has completed successfully. Update latest and minimum ping times. */
951959
void PongReceived(std::chrono::microseconds ping_time) {
952960
m_last_ping_time = ping_time;

‎test/functional/p2p_timeouts.py‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -84,15 +84,15 @@ def run_test(self):
8484

8585
if self.options.v2transport:
8686
expected_timeout_logs = [
87-
"version handshake timeout peer=0",
88-
"version handshake timeout peer=1",
89-
"version handshake timeout peer=2",
87+
"version handshake timeout, disconnecting peer=0",
88+
"version handshake timeout, disconnecting peer=1",
89+
"version handshake timeout, disconnecting peer=2",
9090
]
9191
else:
9292
expected_timeout_logs = [
93-
"version handshake timeout peer=0",
94-
"socket no message in first 3 seconds, 1 0 peer=1",
95-
"socket no message in first 3 seconds, 0 0 peer=2",
93+
"version handshake timeout, disconnecting peer=0",
94+
"socket no message in first 3 seconds, 1 0, disconnecting peer=1",
95+
"socket no message in first 3 seconds, 0 0, disconnecting peer=2",
9696
]
9797

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

‎test/functional/p2p_v2_misbehaving.py‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -151,7 +151,7 @@ def test_earlykeyresponse(self):
151151
# Ensure that the bytes sent after 4 bytes network magic are actually received.
152152
self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
153153
self.wait_until(lambda: node0.getpeerinfo()[-1]["bytessent"] > 0)
154-
with node0.assert_debug_log(['V2 handshake timeout peer=0']):
154+
with node0.assert_debug_log(['V2 handshake timeout, disconnecting peer=0']):
155155
node0.bumpmocktime(4) # `InactivityCheck()` triggers now
156156
peer1.wait_for_disconnect(timeout=1)
157157
self.log.info('successful disconnection since modified ellswift was sent as response')
@@ -162,7 +162,7 @@ def test_v2disconnection(self):
162162
expected_debug_message = [
163163
[], # EARLY_KEY_RESPONSE
164164
["V2 transport error: missing garbage terminator, peer=1"], # EXCESS_GARBAGE
165-
["V2 handshake timeout peer=3"], # WRONG_GARBAGE_TERMINATOR
165+
["V2 handshake timeout, disconnecting peer=3"], # WRONG_GARBAGE_TERMINATOR
166166
["V2 transport error: packet decryption failure"], # WRONG_GARBAGE
167167
["V2 transport error: packet decryption failure"], # SEND_NO_AAD
168168
[], # SEND_NON_EMPTY_VERSION_PACKET

0 commit comments

Comments
 (0)