foster/bitcoin-bitcoin-core
0
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-02-02 09:46:52 -05:00
Code Issues Activity

Merge #20724: Cleanup of -debug=net log messages

Browse source 
48c8a9b964 net_processing: log txrelay flag from version message (Anthony Towns)
98fab37ca0 net: use peer=N instead of from=N in debug log (Anthony Towns)
12302105bb net_processing: additional debug logging for ignored messages (Anthony Towns)
f7edea3b7c net: make debug logging conditional on -debug=net (Anthony Towns)
a410ae8cb0 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 48c8a9b964
  MarcoFalke:
    re-ACK 48c8a9b964 only change is rebase 🚓
  practicalswift:
    re-ACK 48c8a9b964

Tree-SHA512: 6ac530d883dffc4fd7fe20b1dc5ebb5394374c9b499aa7a253eb4a3a660d8901edd72e5ad21ce4a2bf71df25e8f142087755f9756f3497f564ef453a7e9246c1
This commit is contained in:
MarcoFalke 2021-01-29 07:44:06 +01:00
commit c8b83510f4
No known key found for this signature in database
GPG key ID: D2EA4850E7528B25
3 changed files with 38 additions and 17 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

18
src/net.cpp
View file

@ -815,7 +815,7 @@ size_t CConnman::SocketSendData(CNode& node) const
// error
int nErr = WSAGetLastError();
if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS) {
LogPrintf("socket send error %s\n", NetworkErrorString(nErr));
LogPrint(BCLog::NET, "socket send error for peer=%d: %s\n", node.GetId(), NetworkErrorString(nErr));
node.CloseSocketDisconnect();
}
}
@ -1004,6 +1004,7 @@ bool CConnman::AttemptToEvictConnection()
LOCK(cs_vNodes);
for (CNode* pnode : vNodes) {
if (pnode->GetId() == *node_id_to_evict) {
LogPrint(BCLog::NET, "selected %s connection for eviction peer=%d; disconnecting\n", pnode->ConnectionTypeAsString(), pnode->GetId());
pnode->fDisconnect = true;
return true;
}
@ -1052,7 +1053,7 @@ void CConnman::AcceptConnection(const ListenSocket& hListenSocket) {
}
if (!fNetworkActive) {
LogPrintf("connection from %s dropped: not accepting new connections\n", addr.ToString());
LogPrint(BCLog::NET, "connection from %s dropped: not accepting new connections\n", addr.ToString());
CloseSocket(hSocket);
return;
}
@ -1230,17 +1231,17 @@ bool CConnman::InactivityCheck(const CNode& node) const
}
if (node.nLastRecv == 0 || node.nLastSend == 0) {
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());
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());
return true;
}
if (now > node.nLastSend + TIMEOUT_INTERVAL) {
LogPrintf("socket sending timeout: %is\n", now - node.nLastSend);
LogPrint(BCLog::NET, "socket sending timeout: %is peer=%d\n", now - node.nLastSend, node.GetId());
return true;
}
if (now > node.nLastRecv + TIMEOUT_INTERVAL) {
LogPrintf("socket receive timeout: %is\n", now - node.nLastRecv);
LogPrint(BCLog::NET, "socket receive timeout: %is peer=%d\n", now - node.nLastRecv, node.GetId());
return true;
}
@ -1248,12 +1249,12 @@ bool CConnman::InactivityCheck(const CNode& node) const
// We use mockable time for ping timeouts. This means that setmocktime
// may cause pings to time out for peers that have been connected for
// longer than m_peer_connect_timeout.
LogPrintf("ping timeout: %fs\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - node.m_ping_start.load()));
LogPrint(BCLog::NET, "ping timeout: %fs peer=%d\n", 0.000001 * count_microseconds(GetTime<std::chrono::microseconds>() - node.m_ping_start.load()), node.GetId());
return true;
}
if (!node.fSuccessfullyConnected) {
LogPrint(BCLog::NET, "version handshake timeout from %d\n", node.GetId());
LogPrint(BCLog::NET, "version handshake timeout peer=%d\n", node.GetId());
return true;
}
@ -2693,6 +2694,7 @@ bool CConnman::DisconnectNode(const std::string& strNode)
{
LOCK(cs_vNodes);
if (CNode* pnode = FindNode(strNode)) {
LogPrint(BCLog::NET, "disconnect by address%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", strNode) : ""), pnode->GetId());
pnode->fDisconnect = true;
return true;
}
@ -2705,6 +2707,7 @@ bool CConnman::DisconnectNode(const CSubNet& subnet)
LOCK(cs_vNodes);
for (CNode* pnode : vNodes) {
if (subnet.Match(pnode->addr)) {
LogPrint(BCLog::NET, "disconnect by subnet%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->GetId());
pnode->fDisconnect = true;
disconnected = true;
}
@ -2722,6 +2725,7 @@ bool CConnman::DisconnectNode(NodeId id)
LOCK(cs_vNodes);
for(CNode* pnode : vNodes) {
if (id == pnode->GetId()) {
LogPrint(BCLog::NET, "disconnect by id peer=%d; disconnecting\n", pnode->GetId());
pnode->fDisconnect = true;
return true;
}

31
src/net_processing.cpp
View file

@ -880,13 +880,14 @@ void PeerManagerImpl::PushNodeVersion(CNode& pnode, int64_t nTime)
CAddress(CService(), addr.nServices);
CAddress addrMe = CAddress(CService(), nLocalNodeServices);
const bool tx_relay = !m_ignore_incoming_txs && pnode.m_tx_relay != nullptr;
m_connman.PushMessage(&pnode, CNetMsgMaker(INIT_PROTO_VERSION).Make(NetMsgType::VERSION, PROTOCOL_VERSION, (uint64_t)nLocalNodeServices, nTime, addrYou, addrMe,
nonce, strSubVersion, nNodeStartingHeight, !m_ignore_incoming_txs && pnode.m_tx_relay != nullptr));
nonce, strSubVersion, nNodeStartingHeight, tx_relay));
if (fLogIPs) {
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);
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);
} else {
LogPrint(BCLog::NET, "send version message: version %d, blocks=%d, us=%s, peer=%d\n", PROTOCOL_VERSION, nNodeStartingHeight, addrMe.ToString(), nodeid);
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);
}
}
@ -2642,9 +2643,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
if (fLogIPs)
remoteAddr = ", peeraddr=" + pfrom.addr.ToString();
LogPrint(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, peer=%d%s\n",
LogPrint(BCLog::NET, "receive version message: %s: version %d, blocks=%d, us=%s, txrelay=%d, peer=%d%s\n",
cleanSubVer, pfrom.nVersion,
peer->m_starting_height, addrMe.ToString(), pfrom.GetId(),
peer->m_starting_height, addrMe.ToString(), fRelay, pfrom.GetId(),
remoteAddr);
int64_t nTimeOffset = nTime - GetTime();
@ -2659,6 +2660,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
// Feeler connections exist only to verify if address is online.
if (pfrom.IsFeelerConn()) {
LogPrint(BCLog::NET, "feeler connection completed peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
}
return;
@ -2674,7 +2676,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
const CNetMsgMaker msgMaker(pfrom.GetCommonVersion());
if (msg_type == NetMsgType::VERACK) {
if (pfrom.fSuccessfullyConnected) return;
if (pfrom.fSuccessfullyConnected) {
LogPrint(BCLog::NET, "ignoring redundant verack message from peer=%d\n", pfrom.GetId());
return;
}
if (!pfrom.IsInboundConn()) {
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,
if (pfrom.fSuccessfullyConnected) {
// Disconnect peers that send wtxidrelay message after VERACK; this
// must be negotiated between VERSION and VERACK.
LogPrint(BCLog::NET, "wtxidrelay received after verack from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
@ -2754,7 +2760,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
if (!State(pfrom.GetId())->m_wtxid_relay) {
State(pfrom.GetId())->m_wtxid_relay = true;
g_wtxid_relay_peers++;
} else {
LogPrint(BCLog::NET, "ignoring duplicate wtxidrelay from peer=%d\n", pfrom.GetId());
}
} else {
LogPrint(BCLog::NET, "ignoring wtxidrelay due to old common version=%d from peer=%d\n", pfrom.GetCommonVersion(), pfrom.GetId());
}
return;
}
@ -2763,6 +2773,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
if (pfrom.fSuccessfullyConnected) {
// Disconnect peers that send SENDADDRV2 message after VERACK; this
// must be negotiated between VERSION and VERACK.
LogPrint(BCLog::NET, "sendaddrv2 received after verack from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
@ -2789,6 +2800,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
s >> vAddr;
if (!pfrom.RelayAddrsWithConn()) {
LogPrint(BCLog::NET, "ignoring %s message from %s peer=%d\n", msg_type, pfrom.ConnectionTypeAsString(), pfrom.GetId());
return;
}
if (vAddr.size() > MAX_ADDR_TO_SEND)
@ -2832,8 +2844,10 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
m_connman.AddNewAddresses(vAddrOk, pfrom.addr, 2 * 60 * 60);
if (vAddr.size() < 1000)
pfrom.fGetAddr = false;
if (pfrom.IsAddrFetchConn())
if (pfrom.IsAddrFetchConn()) {
LogPrint(BCLog::NET, "addrfetch connection completed peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
}
return;
}
@ -3840,6 +3854,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
if (msg_type == NetMsgType::FILTERLOAD) {
if (!(pfrom.GetLocalServices() & NODE_BLOOM)) {
LogPrint(BCLog::NET, "filterload received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
@ -3862,6 +3877,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
if (msg_type == NetMsgType::FILTERADD) {
if (!(pfrom.GetLocalServices() & NODE_BLOOM)) {
LogPrint(BCLog::NET, "filteradd received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}
@ -3889,6 +3905,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
if (msg_type == NetMsgType::FILTERCLEAR) {
if (!(pfrom.GetLocalServices() & NODE_BLOOM)) {
LogPrint(BCLog::NET, "filterclear received despite not offering bloom services from peer=%d; disconnecting\n", pfrom.GetId());
pfrom.fDisconnect = true;
return;
}

6
test/functional/p2p_timeouts.py
View file

@ -74,9 +74,9 @@ class TimeoutsTest(BitcoinTestFramework):
no_version_node.send_message(msg_ping())
expected_timeout_logs = [
"version handshake timeout from 0",
"socket no message in first 3 seconds, 1 0 from 1",
"socket no message in first 3 seconds, 0 0 from 2",
"version handshake timeout peer=0",
"socket no message in first 3 seconds, 1 0 peer=1",
"socket no message in first 3 seconds, 0 0 peer=2",
]
with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):