Skip to content

Commit

Permalink
net: additional disconnection logging
Browse files Browse the repository at this point in the history
Use the word "disconnecting" everywhere for easier grep.
  • Loading branch information
Sjors committed Dec 1, 2023
1 parent 498994b commit 27abe6e
Show file tree
Hide file tree
Showing 2 changed files with 36 additions and 8 deletions.
38 changes: 33 additions & 5 deletions src/net.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -1886,7 +1886,11 @@ void CConnman::DisconnectNodes()
// Disconnect any connected nodes
for (CNode* pnode : m_nodes) {
if (!pnode->fDisconnect) {
LogPrint(BCLog::NET, "Network not active, dropping peer=%d\n", pnode->GetId());
LogPrint(BCLog::NET,
"Network not active, disconnecting peer=%d%s\n",
pnode->GetId(),
fLogIPs ? strprintf(" peeraddr=%s", pnode->addr.ToStringAddrPort()) : ""
);
pnode->fDisconnect = true;
}
}
Expand Down Expand Up @@ -1979,22 +1983,41 @@ bool CConnman::InactivityCheck(const CNode& node) const
if (!ShouldRunInactivityChecks(node, now)) return false;

if (last_recv.count() == 0 || last_send.count() == 0) {
LogPrint(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());
LogPrint(BCLog::NET,
"socket no message in first %i seconds, %d %d disconnecting peer=%d%s\n",
count_seconds(m_peer_connect_timeout),
last_recv.count() != 0,
last_send.count() != 0,
node.GetId(),
fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : ""
);
return true;
}

if (now > last_send + TIMEOUT_INTERVAL) {
LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", count_seconds(now - last_send), node.GetId());
LogPrint(BCLog::NET,
"socket sending timeout: %is, disconnecting peer=%d%s\n", count_seconds(now - last_send),
node.GetId(),
fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : ""
);
return true;
}

if (now > last_recv + TIMEOUT_INTERVAL) {
LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", count_seconds(now - last_recv), node.GetId());
LogPrint(BCLog::NET,
"socket receive timeout: %is, disconnecting peer=%d%s\n", count_seconds(now - last_recv),
node.GetId(),
fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : ""
);
return true;
}

if (!node.fSuccessfullyConnected) {
LogPrint(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId());
LogPrint(BCLog::NET,
"version handshake timeout, disconnecting peer=%d%s\n",
node.GetId(),
fLogIPs ? strprintf(" peeraddr=%s", node.addr.ToStringAddrPort()) : ""
);
return true;
}

Expand Down Expand Up @@ -2121,6 +2144,11 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
{
bool notify = false;
if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) {
LogPrint(BCLog::NET,
"receiving message bytes failed for peer=%d%s\n",
pnode->GetId(),
fLogIPs ? strprintf(" peeraddr=%s", pnode->addr.ToStringAddrPort()) : ""
);
pnode->CloseSocketDisconnect();
}
RecordBytesRecv(nBytes);
Expand Down
6 changes: 3 additions & 3 deletions test/functional/p2p_timeouts.py
Original file line number Diff line number Diff line change
Expand Up @@ -87,9 +87,9 @@ def run_test(self):
no_version_node.send_message(msg_ping())

expected_timeout_logs = [
"version handshake timeout peer=0",
f"socket no message in first 3 seconds, {'0' if self.options.v2transport else '1'} 0 peer=1",
"socket no message in first 3 seconds, 0 0 peer=2",
"version handshake timeout, disconnecting peer=0",
f"socket no message in first 3 seconds, {'0' if self.options.v2transport else '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):
Expand Down

0 comments on commit 27abe6e

Please sign in to comment.