diff options
| -rw-r--r-- | src/net.cpp | 18 | ||||
| -rw-r--r-- | src/net_processing.cpp | 31 | ||||
| -rwxr-xr-x | test/functional/p2p_timeouts.py | 6 |
3 files changed, 38 insertions, 17 deletions
diff --git a/src/net.cpp b/src/net.cpp index 4759287c36..76bf7effa4 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -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; } diff --git a/src/net_processing.cpp b/src/net_processing.cpp index cf73b1dae2..a4070f5b63 100644 --- a/src/net_processing.cpp +++ b/src/net_processing.cpp @@ -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; } diff --git a/test/functional/p2p_timeouts.py b/test/functional/p2p_timeouts.py index 47832b04bf..a7e240dcfa 100755 --- a/test/functional/p2p_timeouts.py +++ b/test/functional/p2p_timeouts.py @@ -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): |