Skip to content

Commit

Permalink
Merge bitcoin/bitcoin#28521: net, net_processing: additional and cons…
Browse files Browse the repository at this point in the history 
…istent disconnect logging

06443b8 net: clarify if we ever sent or received from peer (Sjors Provoost)
1d01ad4 net: add LogIP() helper, use in net_processing (Sjors Provoost)
937ef9e net_processing: use CNode::DisconnectMsg helper (Sjors Provoost)
ad22442 net: additional disconnection logging (Sjors Provoost)

Pull request description:

  While debugging unexpected disconnections, possibly related to #28331, I found some additional [net] logging to be useful.

  All cases where we disconnect now come with a log message that has the word `disconnecting`:

  * all calls to `CloseSocketDisconnect()` log `disconnecting peer=…`
  * wherever we set `pnode->fDisconnect = true;`
  * for all `InactivityCheck` cases (which in turn sets `fDisconnect`)
  * replaces "dropping" with "disconnecting" in `Network not active, dropping peer=…`

  A few exceptions are listed here: bitcoin/bitcoin#28521 (comment)

  I changed `CloseSocketDisconnect()` to no longer log `disconnecting`, and instead have all the call sites do so.

  This PR introduces two helper functions on `CNode`: `DisconnectMsg` and `LogIP`. The second and third commit use these helpers in `net_processing.cpp` so these disconnect messages are more consistent now (e.g. some didn't log the IP). No new messages are added there though.

  The `LogIP()` helper is rarely used outside of a disconnect event, but it's available for future use.

  Any `LogPrint` this PR touches is replaced with `LogDebug` (superseded by #30750), and every `LogPrintf ` with `LogInfo`.

ACKs for top commit:
  davidgumberg:
    reACK bitcoin/bitcoin@06443b8
  vasild:
    ACK 06443b8
  danielabrozzoni:
    ACK 06443b8
  hodlinator:
    ACK 06443b8

Tree-SHA512: 525f4c11568616e1d48455a3fcab9e923da7432377fe9230468c15403d2e9b7ce712112df8fbd547cfec01dce0d1f26107cfc1b90f78cfc1fe13e08d57b08464
  • Loading branch information
@ryanofsky
ryanofsky committed Dec 27, 2024
2 parents fc7b214 + 06443b8 commit f95fb79
Show file tree
Hide file tree
Showing 9 changed files with 123 additions and 75 deletions.
55 changes: 44 additions & 11 deletions src/net.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -558,7 +558,6 @@ void CNode::CloseSocketDisconnect()
fDisconnect = true;
LOCK(m_sock_mutex);
if (m_sock) {
LogDebug(BCLog::NET, "disconnecting peer=%d\n", id);
m_sock.reset();
}
m_i2p_sam_session.reset();
Expand Down Expand Up @@ -696,6 +695,18 @@ bool CNode::ReceiveMsgBytes(Span<const uint8_t> msg_bytes, bool& complete)
return true;
}

std::string CNode::LogIP(bool log_ip) const
{
return log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : "";
}

std::string CNode::DisconnectMsg(bool log_ip) const
{
return strprintf("disconnecting peer=%d%s",
GetId(),
LogIP(log_ip));
}

V1Transport::V1Transport(const NodeId node_id) noexcept
: m_magic_bytes{Params().MessageStart()}, m_node_id{node_id}
{
Expand Down Expand Up @@ -1635,7 +1646,7 @@ std::pair<size_t, bool> CConnman::SocketSendData(CNode& node) const
// error
int nErr = WSAGetLastError();
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) {
LogDebug(BCLog::NET, "socket send error for peer=%d: %s\n", node.GetId(), NetworkErrorString(nErr));
LogDebug(BCLog::NET, "socket send error, %s: %s\n", node.DisconnectMsg(fLogIPs), NetworkErrorString(nErr));
node.CloseSocketDisconnect();
}
}
Expand Down Expand Up @@ -1879,7 +1890,7 @@ void CConnman::DisconnectNodes()
// Disconnect any connected nodes
for (CNode* pnode : m_nodes) {
if (!pnode->fDisconnect) {
LogDebug(BCLog::NET, "Network not active, dropping peer=%d\n", pnode->GetId());
LogDebug(BCLog::NET, "Network not active, %s\n", pnode->DisconnectMsg(fLogIPs));
pnode->fDisconnect = true;
}
}
Expand Down Expand Up @@ -1971,26 +1982,43 @@ bool CConnman::InactivityCheck(const CNode& node) const

if (!ShouldRunInactivityChecks(node, now)) return false;

if (last_recv.count() == 0 || last_send.count() == 0) {
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());
bool has_received{last_recv.count() != 0};
bool has_sent{last_send.count() != 0};

if (!has_received || !has_sent) {
std::string has_never;
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",
count_seconds(m_peer_connect_timeout),
has_never,
node.DisconnectMsg(fLogIPs)
);
return true;
}

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

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

if (!node.fSuccessfullyConnected) {
if (node.m_transport->GetInfo().transport_type == TransportProtocolType::DETECTING) {
LogDebug(BCLog::NET, "V2 handshake timeout peer=%d\n", node.GetId());
LogDebug(BCLog::NET, "V2 handshake timeout, %s\n", node.DisconnectMsg(fLogIPs));
} else {
LogDebug(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId());
LogDebug(BCLog::NET, "version handshake timeout, %s\n", node.DisconnectMsg(fLogIPs));
}
return true;
}
Expand Down Expand Up @@ -2118,6 +2146,10 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
{
bool notify = false;
if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) {
LogDebug(BCLog::NET,
"receiving message bytes failed, %s\n",
pnode->DisconnectMsg(fLogIPs)
);
pnode->CloseSocketDisconnect();
}
RecordBytesRecv(nBytes);
Expand All @@ -2130,7 +2162,7 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
{
// socket closed gracefully
if (!pnode->fDisconnect) {
LogDebug(BCLog::NET, "socket closed for peer=%d\n", pnode->GetId());
LogDebug(BCLog::NET, "socket closed, %s\n", pnode->DisconnectMsg(fLogIPs));
}
pnode->CloseSocketDisconnect();
}
Expand All @@ -2141,7 +2173,7 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS)
{
if (!pnode->fDisconnect) {
LogDebug(BCLog::NET, "socket recv error for peer=%d: %s\n", pnode->GetId(), NetworkErrorString(nErr));
LogDebug(BCLog::NET, "socket recv error, %s: %s\n", pnode->DisconnectMsg(fLogIPs), NetworkErrorString(nErr));
}
pnode->CloseSocketDisconnect();
}
Expand Down Expand Up @@ -3411,6 +3443,7 @@ void CConnman::StopNodes()
std::vector<CNode*> nodes;
WITH_LOCK(m_nodes_mutex, nodes.swap(m_nodes));
for (CNode* pnode : nodes) {
LogDebug(BCLog::NET, "%s\n", pnode->DisconnectMsg(fLogIPs));
pnode->CloseSocketDisconnect();
DeleteNode(pnode);
}
Expand Down
16 changes: 16 additions & 0 deletions src/net.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -947,6 +947,22 @@ class CNode

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

/**
* Helper function to optionally log the IP address.
*
* @param[in] log_ip whether to include the IP address
* @return " peeraddr=..." or ""
*/
std::string LogIP(bool log_ip) const;

/**
* Helper function to log disconnects.
*
* @param[in] log_ip whether to include the IP address
* @return "disconnecting peer=..." and optionally "peeraddr=..."
*/
std::string DisconnectMsg(bool log_ip) const;

/** A ping-pong round trip has completed successfully. Update latest and minimum ping times. */
void PongReceived(std::chrono::microseconds ping_time) {
m_last_ping_time = ping_time;
Expand Down
Loading

0 comments on commit f95fb79

Please sign in to comment.