phantom/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-01-24 18:23:26 -03:00
Code Issues Projects Releases Packages Wiki Activity Actions 1

net: additional disconnection logging

Browse source 
Use the word "disconnecting" everywhere for easier grep.
This commit is contained in:
Sjors Provoost 2024-07-23 10:53:15 +02:00
parent f7144b24be
commit ad224429f8
No known key found for this signature in database
GPG key ID: 57FF9BDBCC301009
4 changed files with 49 additions and 18 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

43
src/net.cpp
View file

@ -558,7 +558,6 @@ void CNode::CloseSocketDisconnect()
fDisconnect = true; fDisconnect = true;
LOCK(m_sock_mutex); LOCK(m_sock_mutex);
if (m_sock) { if (m_sock) {
LogDebug(BCLog::NET, "disconnecting peer=%d\n", id);
m_sock.reset(); m_sock.reset();
} }
m_i2p_sam_session.reset(); m_i2p_sam_session.reset();
@ -696,6 +695,13 @@ bool CNode::ReceiveMsgBytes(Span<const uint8_t> msg_bytes, bool& complete)
return true; return true;
} }
std::string CNode::DisconnectMsg(bool log_ip) const
{
return strprintf("disconnecting peer=%d%s",
GetId(),
log_ip ? strprintf(" peeraddr=%s", addr.ToStringAddrPort()) : "");
}
V1Transport::V1Transport(const NodeId node_id) noexcept V1Transport::V1Transport(const NodeId node_id) noexcept
: m_magic_bytes{Params().MessageStart()}, m_node_id{node_id} : m_magic_bytes{Params().MessageStart()}, m_node_id{node_id}
{ {
@ -1635,7 +1641,7 @@ std::pair<size_t, bool> CConnman::SocketSendData(CNode& node) const
// error // error
int nErr = WSAGetLastError(); int nErr = WSAGetLastError();
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) { 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(); node.CloseSocketDisconnect();
} }
} }
@ -1879,7 +1885,7 @@ void CConnman::DisconnectNodes()
// Disconnect any connected nodes // Disconnect any connected nodes
for (CNode* pnode : m_nodes) { for (CNode* pnode : m_nodes) {
if (!pnode->fDisconnect) { 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; pnode->fDisconnect = true;
} }
} }
@ -1972,25 +1978,37 @@ bool CConnman::InactivityCheck(const CNode& node) const
if (!ShouldRunInactivityChecks(node, now)) return false; if (!ShouldRunInactivityChecks(node, now)) return false;
if (last_recv.count() == 0 || last_send.count() == 0) { 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()); LogDebug(BCLog::NET,
"socket no message in first %i seconds, %d %d, %s\n",
count_seconds(m_peer_connect_timeout),
last_recv.count() != 0,
last_send.count() != 0,
node.DisconnectMsg(fLogIPs)
);
return true; return true;
} }
if (now > last_send + TIMEOUT_INTERVAL) { 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; return true;
} }
if (now > last_recv + TIMEOUT_INTERVAL) { 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; return true;
} }
if (!node.fSuccessfullyConnected) { if (!node.fSuccessfullyConnected) {
if (node.m_transport->GetInfo().transport_type == TransportProtocolType::DETECTING) { 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 { } 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; return true;
} }
@ -2118,6 +2136,10 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
{ {
bool notify = false; bool notify = false;
if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) { if (!pnode->ReceiveMsgBytes({pchBuf, (size_t)nBytes}, notify)) {
LogDebug(BCLog::NET,
"receiving message bytes failed, %s\n",
pnode->DisconnectMsg(fLogIPs)
);
pnode->CloseSocketDisconnect(); pnode->CloseSocketDisconnect();
} }
RecordBytesRecv(nBytes); RecordBytesRecv(nBytes);
@ -2130,7 +2152,7 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
{ {
// socket closed gracefully // socket closed gracefully
if (!pnode->fDisconnect) { 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(); pnode->CloseSocketDisconnect();
} }
@ -2141,7 +2163,7 @@ void CConnman::SocketHandlerConnected(const std::vector<CNode*>& nodes,
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS)
{ {
if (!pnode->fDisconnect) { 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(); pnode->CloseSocketDisconnect();
} }
@ -3411,6 +3433,7 @@ void CConnman::StopNodes()
std::vector<CNode*> nodes; std::vector<CNode*> nodes;
WITH_LOCK(m_nodes_mutex, nodes.swap(m_nodes)); WITH_LOCK(m_nodes_mutex, nodes.swap(m_nodes));
for (CNode* pnode : nodes) { for (CNode* pnode : nodes) {
LogDebug(BCLog::NET, "%s\n", pnode->DisconnectMsg(fLogIPs));
pnode->CloseSocketDisconnect(); pnode->CloseSocketDisconnect();
DeleteNode(pnode); DeleteNode(pnode);
} }

8
src/net.h
View file

@ -947,6 +947,14 @@ public:
std::string ConnectionTypeAsString() const { return ::ConnectionTypeAsString(m_conn_type); } std::string ConnectionTypeAsString() const { return ::ConnectionTypeAsString(m_conn_type); }
/**
* 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. */ /** A ping-pong round trip has completed successfully. Update latest and minimum ping times. */
void PongReceived(std::chrono::microseconds ping_time) { void PongReceived(std::chrono::microseconds ping_time) {
m_last_ping_time = ping_time; m_last_ping_time = ping_time;

12
test/functional/p2p_timeouts.py
View file

@ -84,15 +84,15 @@ class TimeoutsTest(BitcoinTestFramework):
if self.options.v2transport: if self.options.v2transport:
expected_timeout_logs = [ expected_timeout_logs = [
"version handshake timeout peer=0", "version handshake timeout, disconnecting peer=0",
"version handshake timeout peer=1", "version handshake timeout, disconnecting peer=1",
"version handshake timeout peer=2", "version handshake timeout, disconnecting peer=2",
] ]
else: else:
expected_timeout_logs = [ expected_timeout_logs = [
"version handshake timeout peer=0", "version handshake timeout, disconnecting peer=0",
"socket no message in first 3 seconds, 1 0 peer=1", "socket no message in first 3 seconds, 1 0, disconnecting peer=1",
"socket no message in first 3 seconds, 0 0 peer=2", "socket no message in first 3 seconds, 0 0, disconnecting peer=2",
] ]
with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs): with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):

4
test/functional/p2p_v2_misbehaving.py
View file

@ -151,7 +151,7 @@ class EncryptedP2PMisbehaving(BitcoinTestFramework):
# Ensure that the bytes sent after 4 bytes network magic are actually received. # Ensure that the bytes sent after 4 bytes network magic are actually received.
self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4) self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
self.wait_until(lambda: node0.getpeerinfo()[-1]["bytessent"] > 0) self.wait_until(lambda: node0.getpeerinfo()[-1]["bytessent"] > 0)
with node0.assert_debug_log(['V2 handshake timeout peer=0']): with node0.assert_debug_log(['V2 handshake timeout, disconnecting peer=0']):
node0.bumpmocktime(4) # `InactivityCheck()` triggers now node0.bumpmocktime(4) # `InactivityCheck()` triggers now
peer1.wait_for_disconnect(timeout=1) peer1.wait_for_disconnect(timeout=1)
self.log.info('successful disconnection since modified ellswift was sent as response') self.log.info('successful disconnection since modified ellswift was sent as response')
@ -162,7 +162,7 @@ class EncryptedP2PMisbehaving(BitcoinTestFramework):
expected_debug_message = [ expected_debug_message = [
[], # EARLY_KEY_RESPONSE [], # EARLY_KEY_RESPONSE
["V2 transport error: missing garbage terminator, peer=1"], # EXCESS_GARBAGE ["V2 transport error: missing garbage terminator, peer=1"], # EXCESS_GARBAGE
["V2 handshake timeout peer=3"], # WRONG_GARBAGE_TERMINATOR ["V2 handshake timeout, disconnecting peer=3"], # WRONG_GARBAGE_TERMINATOR
["V2 transport error: packet decryption failure"], # WRONG_GARBAGE ["V2 transport error: packet decryption failure"], # WRONG_GARBAGE
["V2 transport error: packet decryption failure"], # SEND_NO_AAD ["V2 transport error: packet decryption failure"], # SEND_NO_AAD
[], # SEND_NON_EMPTY_VERSION_PACKET [], # SEND_NON_EMPTY_VERSION_PACKET