Merge bitcoin/bitcoin#25832: tracing: network connection tracepoints

fanquake · fanquake · commit a43f08c4ae32 · 2025-02-05T15:30:52.000Z
e3622a9 tracing: document that peer addrs can be >68 chars (0xb10c) b19b526 tracing: log_p2p_connections.bt example (0xb10c) caa5486 tracing: connection closed tracepoint (0xb10c) b2ad6ed tracing: add misbehaving conn tracepoint (0xb10c) 68c1ef4 tracing: add inbound connection eviction tracepoint (0xb10c) 4d61d52 tracing: add outbound connection tracepoint (0xb10c) 85b2603 tracing: add inbound connection tracepoint (0xb10c) Pull request description: This adds five new tracepoints with documentation and tests for network connections: - established connections with `net:inbound_connection` and `net:outbound_connection` - closed connections (both closed by us or by the peer) with `net:closed_connnection` - inbound connections that we choose to evict with `net:evicted_inbound_connection` - connections that are misbehaving and punished with `net:misbehaving_connection` I've been using these tracepoints for a few months now to monitor connection lifetimes, re-connection frequency by IP and netgroup, misbehavior, peer discouragement, and eviction and more. Together with the two existing P2P message tracepoints they allow for a good overview of local P2P network activity. Also sort-of addresses bitcoin/bitcoin#22006 (comment). I've been back and forth on which arguments to include. For example, `net:evicted_connection` could also include some of the eviction metrics like e.g. `last_block_time`, `min_ping_time`, ... but I've left them out for now. If wanted, this can be added here or in a follow-up. I've tried to minimize a potential performance impact by measuring executed instructions with `gdb` where possible (method described [here](bitcoin/bitcoin#23724 (comment))). I don't think a few hundred extra instructions are too crucial, as connection opens/closes aren't too frequent (compared to e.g. P2P messages). Note: e.g. `CreateNodeFromAcceptedSocket()` usually executes between 80k and 90k instructions for each new inbound connection. | tracepoint | instructions | |----------------------------|--------------------------------------------------------| | net:inbound_connection | 390 ins | | net:outbound_connection | between 700 and 1000 ins | | net:closed_connnection | 473 ins | | net:evicted_inbound_connection | not measured; likely similar to net:closed_connnection | | net:misbehaving_connection | not measured | Also added a bpftrace (tested with v0.14.1) `log_p2p_connections.bt` example script that produces output similar to: ``` Attaching 6 probes... Logging opened, closed, misbehaving, and evicted P2P connections OUTBOUND conn to 127.0.0.1:15287: id=0, type=block-relay-only, network=0, total_out=1 INBOUND conn from 127.0.0.1:45324: id=1, type=inbound, network=0, total_in=1 MISBEHAVING conn id=1, message='getdata message size = 50001' CLOSED conn to 127.0.0.1:15287: id=0, type=block-relay-only, network=0, established=1231006505 EVICTED conn to 127.0.0.1:45324: id=1, type=inbound, network=0, established=1612312312 ``` ACKs for top commit: laanwj: re-ACK e3622a9 vasild: ACK e3622a9 sipa: utACK e3622a9 Tree-SHA512: 1032dcac6fe0ced981715606f82c2db47016407d3accb8f216c978f010da9bc20453e24a167dcc95287f4783b48562ffb90f645bf230990e3df1b9b9a6d4e5d0
diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md
@@ -335,4 +335,25 @@ $ python3 contrib/tracing/mempool_monitor.py $(pidof bitcoind)
  │ 13:10:32Z added c78e87be86c828137a6e7e00a177c03b52202ce4c39029b99904c2a094b9da87 with feerate 11.00 sat/vB (1562 sat, 142 vbytes)                                            │
  │                                                                                                                                                                              │
  └──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
+
+### log_p2p_connections.bt
+
+A `bpftrace` script to log information about opened, closed, misbehaving, and
+evicted P2P connections. Uses the `net:*_connection` tracepoints.
+
+```bash
+$ bpftrace contrib/tracing/log_p2p_connections.bt
+```
+
+This should produce an output similar to the following.
+
+```bash
+Attaching 6 probes...
+Logging opened, closed, misbehaving, and evicted P2P connections
+OUTBOUND conn to 127.0.0.1:15287: id=0, type=block-relay-only, network=0, total_out=1
+INBOUND conn from 127.0.0.1:45324: id=1, type=inbound, network=0, total_in=1
+MISBEHAVING conn id=1, score_before=0, score_increase=20, message='getdata message size = 50001', threshold_exceeded=false
+CLOSED conn to 127.0.0.1:15287: id=0, type=block-relay-only, network=0, established=1231006505
+EVICTED conn to 127.0.0.1:45324: id=1, type=inbound, network=0, established=1612312312
+...
 ```
diff --git a/contrib/tracing/log_p2p_connections.bt b/contrib/tracing/log_p2p_connections.bt
@@ -0,0 +1,51 @@
+#!/usr/bin/env bpftrace
+
+BEGIN
+{
+  printf("Logging opened, closed, misbehaving, and evicted P2P connections\n")
+}
+
+usdt:./build/src/bitcoind:net:inbound_connection
+{
+  $id = (int64) arg0;
+  $addr = str(arg1);
+  $conn_type = str(arg2);
+  $network = (int32) arg3;
+  $existing = (uint64) arg4;
+  printf("INBOUND conn from %s: id=%ld, type=%s, network=%d, total=%d\n", $addr, $id, $conn_type, $network, $existing);
+}
+
+usdt:./build/src/bitcoind:net:outbound_connection
+{
+  $id = (int64) arg0;
+  $addr = str(arg1);
+  $conn_type = str(arg2);
+  $network = (int32) arg3;
+  $existing = (uint64) arg4;
+  printf("OUTBOUND conn to %s: id=%ld, type=%s, network=%d, total=%d\n", $addr, $id, $conn_type, $network, $existing);
+}
+
+usdt:./build/src/bitcoind:net:closed_connection
+{
+  $id = (int64) arg0;
+  $addr = str(arg1);
+  $conn_type = str(arg2);
+  $network = (int32) arg3;
+  printf("CLOSED conn to %s: id=%ld, type=%s, network=%d, established=%ld\n", $addr, $id, $conn_type, $network, arg4);
+}
+
+usdt:./build/src/bitcoind:net:evicted_inbound_connection
+{
+  $id = (int64) arg0;
+  $addr = str(arg1);
+  $conn_type = str(arg2);
+  $network = (int32) arg3;
+  printf("EVICTED conn to %s: id=%ld, type=%s, network=%d, established=%ld\n", $addr, $id, $conn_type, $network, arg4);
+}
+
+usdt:./build/src/bitcoind:net:misbehaving_connection
+{
+  $id = (int64) arg0;
+  $message = str(arg1);
+  printf("MISBEHAVING conn id=%ld, message='%s'\n", $id, $message);
+}
diff --git a/doc/tracing.md b/doc/tracing.md
@@ -55,14 +55,17 @@ The currently available tracepoints are listed here.
 
 ### Context `net`
 
+[^address-length]: An Onion v3 address with a `:` and a five digit port has 68
+  chars. However, addresses of peers added with host names might be longer.
+
 #### Tracepoint `net:inbound_message`
 
 Is called when a message is received from a peer over the P2P network. Passes
 information about our peer, the connection and the message as arguments.
 
 Arguments passed:
 1. Peer ID as `int64`
-2. Peer Address and Port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (max. length 68 characters)
+2. Peer Address and Port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (normally up to 68 characters[^address-length])
 3. Connection Type (inbound, feeler, outbound-full-relay, ...) as `pointer to C-style String` (max. length 20 characters)
 4. Message Type (inv, ping, getdata, addrv2, ...) as `pointer to C-style String` (max. length 20 characters)
 5. Message Size in bytes as `uint64`
@@ -81,7 +84,7 @@ information about our peer, the connection and the message as arguments.
 
 Arguments passed:
 1. Peer ID as `int64`
-2. Peer Address and Port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (max. length 68 characters)
+2. Peer Address and Port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (normally up to 68 characters[^address-length])
 3. Connection Type (inbound, feeler, outbound-full-relay, ...) as `pointer to C-style String` (max. length 20 characters)
 4. Message Type (inv, ping, getdata, addrv2, ...) as `pointer to C-style String` (max. length 20 characters)
 5. Message Size in bytes as `uint64`
@@ -93,6 +96,62 @@ to user-space in full. Messages longer than a 32kb might be cut off. This can
 be detected in tracing scripts by comparing the message size to the length of
 the passed message.
 
+#### Tracepoint `net:inbound_connection`
+
+Is called when a new inbound connection is opened to us. Passes information about
+the peer and the number of inbound connections including the newly opened connection.
+
+Arguments passed:
+1. Peer ID as `int64`
+2. Peer address and port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (normally up to 68 characters[^address-length])
+3. Connection Type (inbound, feeler, outbound-full-relay, ...) as `pointer to C-style String` (max. length 20 characters)
+4. Network the peer connects from as `uint32` (1 = IPv4, 2 = IPv6, 3 = Onion, 4 = I2P, 5 = CJDNS). See `Network` enum in `netaddress.h`.
+5. Number of existing inbound connections as `uint64` including the newly opened inbound connection.
+
+#### Tracepoint `net:outbound_connection`
+
+Is called when a new outbound connection is opened by us. Passes information about
+the peer and the number of outbound connections including the newly opened connection.
+
+Arguments passed:
+1. Peer ID as `int64`
+2. Peer address and port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (normally up to 68 characters[^address-length])
+3. Connection Type (inbound, feeler, outbound-full-relay, ...) as `pointer to C-style String` (max. length 20 characters)
+4. Network of the peer as `uint32` (1 = IPv4, 2 = IPv6, 3 = Onion, 4 = I2P, 5 = CJDNS). See `Network` enum in `netaddress.h`.
+5. Number of existing outbound connections as `uint64` including the newly opened outbound connection.
+
+#### Tracepoint `net:evicted_inbound_connection`
+
+Is called when a inbound connection is evicted by us. Passes information about the evicted peer and the time at connection establishment.
+
+Arguments passed:
+1. Peer ID as `int64`
+2. Peer address and port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (normally up to 68 characters[^address-length])
+3. Connection Type (inbound, feeler, outbound-full-relay, ...) as `pointer to C-style String` (max. length 20 characters)
+4. Network the peer connects from as `uint32` (1 = IPv4, 2 = IPv6, 3 = Onion, 4 = I2P, 5 = CJDNS). See `Network` enum in `netaddress.h`.
+5. Connection established UNIX epoch timestamp in seconds as `uint64`.
+
+#### Tracepoint `net:misbehaving_connection`
+
+Is called when a connection is misbehaving. Passes the peer id and a
+reason for the peers misbehavior.
+
+Arguments passed:
+1. Peer ID as `int64`.
+2. Reason why the peer is misbehaving as `pointer to C-style String` (max. length 128 characters).
+
+#### Tracepoint `net:closed_connection`
+
+Is called when a connection is closed. Passes information about the closed peer
+and the time at connection establishment.
+
+Arguments passed:
+1. Peer ID as `int64`
+2. Peer address and port (IPv4, IPv6, Tor v3, I2P, ...) as `pointer to C-style String` (normally up to 68 characters[^address-length])
+3. Connection Type (inbound, feeler, outbound-full-relay, ...) as `pointer to C-style String` (max. length 20 characters)
+4. Network the peer connects from as `uint32` (1 = IPv4, 2 = IPv6, 3 = Onion, 4 = I2P, 5 = CJDNS). See `Network` enum in `netaddress.h`.
+5. Connection established UNIX epoch timestamp in seconds as `uint64`.
+
 ### Context `validation`
 
 #### Tracepoint `validation:block_connected`
diff --git a/src/net.cpp b/src/net.cpp
@@ -53,6 +53,10 @@
 #include <optional>
 #include <unordered_map>
 
+TRACEPOINT_SEMAPHORE(net, closed_connection);
+TRACEPOINT_SEMAPHORE(net, evicted_inbound_connection);
+TRACEPOINT_SEMAPHORE(net, inbound_connection);
+TRACEPOINT_SEMAPHORE(net, outbound_connection);
 TRACEPOINT_SEMAPHORE(net, outbound_message);
 
 /** Maximum number of block-relay-only anchor connections */
@@ -560,6 +564,13 @@ void CNode::CloseSocketDisconnect()
     if (m_sock) {
         LogDebug(BCLog::NET, "Resetting socket for peer=%d%s", GetId(), LogIP(fLogIPs));
         m_sock.reset();
+
+        TRACEPOINT(net, closed_connection,
+            GetId(),
+            m_addr_name.c_str(),
+            ConnectionTypeAsString().c_str(),
+            ConnectedThroughNetwork(),
+            Ticks<std::chrono::seconds>(m_connected));
     }
     m_i2p_sam_session.reset();
 }
@@ -1708,6 +1719,12 @@ bool CConnman::AttemptToEvictConnection()
     for (CNode* pnode : m_nodes) {
         if (pnode->GetId() == *node_id_to_evict) {
             LogDebug(BCLog::NET, "selected %s connection for eviction, %s", pnode->ConnectionTypeAsString(), pnode->DisconnectMsg(fLogIPs));
+            TRACEPOINT(net, evicted_inbound_connection,
+                pnode->GetId(),
+                pnode->m_addr_name.c_str(),
+                pnode->ConnectionTypeAsString().c_str(),
+                pnode->ConnectedThroughNetwork(),
+                Ticks<std::chrono::seconds>(pnode->m_connected));
             pnode->fDisconnect = true;
             return true;
         }
@@ -1833,6 +1850,12 @@ void CConnman::CreateNodeFromAcceptedSocket(std::unique_ptr<Sock>&& sock,
         m_nodes.push_back(pnode);
     }
     LogDebug(BCLog::NET, "connection from %s accepted\n", addr.ToStringAddrPort());
+    TRACEPOINT(net, inbound_connection,
+        pnode->GetId(),
+        pnode->m_addr_name.c_str(),
+        pnode->ConnectionTypeAsString().c_str(),
+        pnode->ConnectedThroughNetwork(),
+        GetNodeCount(ConnectionDirection::In));
 
     // We received a new connection, harvest entropy from the time (and our peer count)
     RandAddEvent((uint32_t)id);
@@ -2995,6 +3018,13 @@ void CConnman::OpenNetworkConnection(const CAddress& addrConnect, bool fCountFai
         // update connection count by network
         if (pnode->IsManualOrFullOutboundConn()) ++m_network_conn_counts[pnode->addr.GetNetwork()];
     }
+
+    TRACEPOINT(net, outbound_connection,
+        pnode->GetId(),
+        pnode->m_addr_name.c_str(),
+        pnode->ConnectionTypeAsString().c_str(),
+        pnode->ConnectedThroughNetwork(),
+        GetNodeCount(ConnectionDirection::Out));
 }
 
 Mutex NetEventsInterface::g_msgproc_mutex;
diff --git a/src/net_processing.cpp b/src/net_processing.cpp
@@ -58,6 +58,7 @@
 using namespace util::hex_literals;
 
 TRACEPOINT_SEMAPHORE(net, inbound_message);
+TRACEPOINT_SEMAPHORE(net, misbehaving_connection);
 
 /** Headers download timeout.
  *  Timeout = base + per_header * (expected number of headers) */
@@ -1752,6 +1753,10 @@ void PeerManagerImpl::Misbehaving(Peer& peer, const std::string& message)
     const std::string message_prefixed = message.empty() ? "" : (": " + message);
     peer.m_should_discourage = true;
     LogDebug(BCLog::NET, "Misbehaving: peer=%d%s\n", peer.m_id, message_prefixed);
+    TRACEPOINT(net, misbehaving_connection,
+        peer.m_id,
+        message.c_str()
+    );
 }
 
 void PeerManagerImpl::MaybePunishNodeForBlock(NodeId nodeid, const BlockValidationState& state,
diff --git a/test/functional/interface_usdt_net.py b/test/functional/interface_usdt_net.py
