From 85b2603eec634257cd3b398900dbb92251db71e6 Mon Sep 17 00:00:00 2001 From: 0xb10c <0xb10c@gmail.com> Date: Mon, 2 May 2022 16:26:22 +0200 Subject: [PATCH 1/7] tracing: add inbound connection tracepoint --- doc/tracing.md | 12 ++++ src/net.cpp | 7 ++ test/functional/interface_usdt_net.py | 97 ++++++++++++++++++++++++++- 3 files changed, 115 insertions(+), 1 deletion(-) diff --git a/doc/tracing.md b/doc/tracing.md index 184f6b01002..80edea1e646 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -93,6 +93,18 @@ 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` (max. length 68 characters) +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. + ### Context `validation` #### Tracepoint `validation:block_connected` diff --git a/src/net.cpp b/src/net.cpp index 28499788711..d2056412c9f 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -53,6 +53,7 @@ #include #include +TRACEPOINT_SEMAPHORE(net, inbound_connection); TRACEPOINT_SEMAPHORE(net, outbound_message); /** Maximum number of block-relay-only anchor connections */ @@ -1833,6 +1834,12 @@ void CConnman::CreateNodeFromAcceptedSocket(std::unique_ptr&& 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); diff --git a/test/functional/interface_usdt_net.py b/test/functional/interface_usdt_net.py index 5468ddf8586..6849a210f08 100755 --- a/test/functional/interface_usdt_net.py +++ b/test/functional/interface_usdt_net.py @@ -11,7 +11,7 @@ import ctypes from io import BytesIO # Test will be skipped if we don't have bcc installed try: - from bcc import BPF, USDT # type: ignore[import] + from bcc import BPF, USDT # type: ignore[import] except ImportError: pass from test_framework.messages import msg_version @@ -27,6 +27,9 @@ MAX_MSG_TYPE_LENGTH = 20 # larger messanges see contrib/tracing/log_raw_p2p_msgs.py MAX_MSG_DATA_LENGTH = 150 +# from net_address.h +NETWORK_TYPE_UNROUTABLE = 0 + net_tracepoints_program = """ #include @@ -53,6 +56,20 @@ struct p2p_message u8 msg[MAX_MSG_DATA_LENGTH]; }; +struct Connection +{ + u64 id; + char addr[MAX_PEER_ADDR_LENGTH]; + char type[MAX_PEER_CONN_TYPE_LENGTH]; + u32 network; +}; + +struct NewConnection +{ + struct Connection conn; + u64 existing; +}; + BPF_PERF_OUTPUT(inbound_messages); int trace_inbound_message(struct pt_regs *ctx) { struct p2p_message msg = {}; @@ -78,9 +95,46 @@ int trace_outbound_message(struct pt_regs *ctx) { outbound_messages.perf_submit(ctx, &msg, sizeof(msg)); return 0; }; + +BPF_PERF_OUTPUT(inbound_connections); +int trace_inbound_connection(struct pt_regs *ctx) { + struct NewConnection inbound = {}; + void *conn_type_pointer = NULL, *address_pointer = NULL; + bpf_usdt_readarg(1, ctx, &inbound.conn.id); + bpf_usdt_readarg(2, ctx, &address_pointer); + bpf_usdt_readarg(3, ctx, &conn_type_pointer); + bpf_usdt_readarg(4, ctx, &inbound.conn.network); + bpf_usdt_readarg(5, ctx, &inbound.existing); + bpf_probe_read_user_str(&inbound.conn.addr, sizeof(inbound.conn.addr), address_pointer); + bpf_probe_read_user_str(&inbound.conn.type, sizeof(inbound.conn.type), conn_type_pointer); + inbound_connections.perf_submit(ctx, &inbound, sizeof(inbound)); + return 0; +}; + """ +class Connection(ctypes.Structure): + _fields_ = [ + ("id", ctypes.c_uint64), + ("addr", ctypes.c_char * MAX_PEER_ADDR_LENGTH), + ("conn_type", ctypes.c_char * MAX_PEER_CONN_TYPE_LENGTH), + ("network", ctypes.c_uint32), + ] + + def __repr__(self): + return f"Connection(peer={self.id}, addr={self.addr.decode('utf-8')}, conn_type={self.conn_type.decode('utf-8')}, network={self.network})" + + +class NewConnection(ctypes.Structure): + _fields_ = [ + ("conn", Connection), + ("existing", ctypes.c_uint64), + ] + + def __repr__(self): + return f"NewConnection(conn={self.conn}, existing={self.existing})" + class NetTracepointTest(BitcoinTestFramework): def set_test_params(self): self.num_nodes = 1 @@ -92,6 +146,10 @@ class NetTracepointTest(BitcoinTestFramework): self.skip_if_no_bpf_permissions() def run_test(self): + self.p2p_message_tracepoint_test() + self.inbound_conn_tracepoint_test() + + def p2p_message_tracepoint_test(self): # Tests the net:inbound_message and net:outbound_message tracepoints # See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#context-net @@ -166,7 +224,44 @@ class NetTracepointTest(BitcoinTestFramework): bpf.cleanup() + test_node.peer_disconnect() + def inbound_conn_tracepoint_test(self): + self.log.info("hook into the net:inbound_connection tracepoint") + ctx = USDT(pid=self.nodes[0].process.pid) + ctx.enable_probe(probe="net:inbound_connection", + fn_name="trace_inbound_connection") + bpf = BPF(text=net_tracepoints_program, usdt_contexts=[ctx], debug=0, cflags=["-Wno-error=implicit-function-declaration"]) + + inbound_connections = [] + EXPECTED_INBOUND_CONNECTIONS = 2 + + def handle_inbound_connection(_, data, __): + nonlocal inbound_connections + event = ctypes.cast(data, ctypes.POINTER(NewConnection)).contents + self.log.info(f"handle_inbound_connection(): {event}") + inbound_connections.append(event) + + bpf["inbound_connections"].open_perf_buffer(handle_inbound_connection) + + self.log.info("connect two P2P test nodes to our bitcoind node") + testnodes = list() + for _ in range(EXPECTED_INBOUND_CONNECTIONS): + testnode = P2PInterface() + self.nodes[0].add_p2p_connection(testnode) + testnodes.append(testnode) + bpf.perf_buffer_poll(timeout=200) + + assert_equal(EXPECTED_INBOUND_CONNECTIONS, len(inbound_connections)) + for inbound_connection in inbound_connections: + assert inbound_connection.conn.id > 0 + assert inbound_connection.existing > 0 + assert_equal(b'inbound', inbound_connection.conn.conn_type) + assert_equal(NETWORK_TYPE_UNROUTABLE, inbound_connection.conn.network) + + bpf.cleanup() + for node in testnodes: + node.peer_disconnect() if __name__ == '__main__': NetTracepointTest(__file__).main() From 4d61d52f4387622701cdad4bb0fb115127021106 Mon Sep 17 00:00:00 2001 From: 0xb10c <0xb10c@gmail.com> Date: Mon, 2 May 2022 16:27:13 +0200 Subject: [PATCH 2/7] tracing: add outbound connection tracepoint --- doc/tracing.md | 12 ++++++ src/net.cpp | 8 ++++ test/functional/interface_usdt_net.py | 57 +++++++++++++++++++++++++++ 3 files changed, 77 insertions(+) diff --git a/doc/tracing.md b/doc/tracing.md index 80edea1e646..a0720b68cf4 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -105,6 +105,18 @@ Arguments passed: 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` (max. length 68 characters) +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. + ### Context `validation` #### Tracepoint `validation:block_connected` diff --git a/src/net.cpp b/src/net.cpp index d2056412c9f..623901d9593 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -54,6 +54,7 @@ #include TRACEPOINT_SEMAPHORE(net, inbound_connection); +TRACEPOINT_SEMAPHORE(net, outbound_connection); TRACEPOINT_SEMAPHORE(net, outbound_message); /** Maximum number of block-relay-only anchor connections */ @@ -3002,6 +3003,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/test/functional/interface_usdt_net.py b/test/functional/interface_usdt_net.py index 6849a210f08..f4f77ab25bc 100755 --- a/test/functional/interface_usdt_net.py +++ b/test/functional/interface_usdt_net.py @@ -111,6 +111,21 @@ int trace_inbound_connection(struct pt_regs *ctx) { return 0; }; +BPF_PERF_OUTPUT(outbound_connections); +int trace_outbound_connection(struct pt_regs *ctx) { + struct NewConnection outbound = {}; + void *conn_type_pointer = NULL, *address_pointer = NULL; + bpf_usdt_readarg(1, ctx, &outbound.conn.id); + bpf_usdt_readarg(2, ctx, &address_pointer); + bpf_usdt_readarg(3, ctx, &conn_type_pointer); + bpf_usdt_readarg(4, ctx, &outbound.conn.network); + bpf_usdt_readarg(5, ctx, &outbound.existing); + bpf_probe_read_user_str(&outbound.conn.addr, sizeof(outbound.conn.addr), address_pointer); + bpf_probe_read_user_str(&outbound.conn.type, sizeof(outbound.conn.type), conn_type_pointer); + outbound_connections.perf_submit(ctx, &outbound, sizeof(outbound)); + return 0; +}; + """ @@ -148,6 +163,7 @@ class NetTracepointTest(BitcoinTestFramework): def run_test(self): self.p2p_message_tracepoint_test() self.inbound_conn_tracepoint_test() + self.outbound_conn_tracepoint_test() def p2p_message_tracepoint_test(self): # Tests the net:inbound_message and net:outbound_message tracepoints @@ -263,5 +279,46 @@ class NetTracepointTest(BitcoinTestFramework): for node in testnodes: node.peer_disconnect() + def outbound_conn_tracepoint_test(self): + self.log.info("hook into the net:outbound_connection tracepoint") + ctx = USDT(pid=self.nodes[0].process.pid) + ctx.enable_probe(probe="net:outbound_connection", + fn_name="trace_outbound_connection") + bpf = BPF(text=net_tracepoints_program, usdt_contexts=[ctx], debug=0, cflags=["-Wno-error=implicit-function-declaration"]) + + # that the handle_* function succeeds. + EXPECTED_OUTBOUND_CONNECTIONS = 2 + EXPECTED_CONNECTION_TYPE = "feeler" + outbound_connections = [] + + def handle_outbound_connection(_, data, __): + event = ctypes.cast(data, ctypes.POINTER(NewConnection)).contents + self.log.info(f"handle_outbound_connection(): {event}") + outbound_connections.append(event) + + bpf["outbound_connections"].open_perf_buffer( + handle_outbound_connection) + + self.log.info( + f"connect {EXPECTED_OUTBOUND_CONNECTIONS} P2P test nodes to our bitcoind node") + testnodes = list() + for p2p_idx in range(EXPECTED_OUTBOUND_CONNECTIONS): + testnode = P2PInterface() + self.nodes[0].add_outbound_p2p_connection( + testnode, p2p_idx=p2p_idx, connection_type=EXPECTED_CONNECTION_TYPE) + testnodes.append(testnode) + bpf.perf_buffer_poll(timeout=200) + + assert_equal(EXPECTED_OUTBOUND_CONNECTIONS, len(outbound_connections)) + for outbound_connection in outbound_connections: + assert outbound_connection.conn.id > 0 + assert outbound_connection.existing > 0 + assert_equal(EXPECTED_CONNECTION_TYPE, outbound_connection.conn.conn_type.decode('utf-8')) + assert_equal(NETWORK_TYPE_UNROUTABLE, outbound_connection.conn.network) + + bpf.cleanup() + for node in testnodes: + node.peer_disconnect() + if __name__ == '__main__': NetTracepointTest(__file__).main() From 68c1ef4f19bc4ebe0ca1af95ac378732c4fe6d22 Mon Sep 17 00:00:00 2001 From: 0xb10c <0xb10c@gmail.com> Date: Mon, 2 May 2022 16:28:09 +0200 Subject: [PATCH 3/7] tracing: add inbound connection eviction tracepoint --- doc/tracing.md | 11 ++++ src/net.cpp | 7 +++ test/functional/interface_usdt_net.py | 72 +++++++++++++++++++++++++++ 3 files changed, 90 insertions(+) diff --git a/doc/tracing.md b/doc/tracing.md index a0720b68cf4..5f7f80c1d99 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -117,6 +117,17 @@ Arguments passed: 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` (max. length 68 characters) +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 index 623901d9593..de947a1a98d 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -53,6 +53,7 @@ #include #include +TRACEPOINT_SEMAPHORE(net, evicted_inbound_connection); TRACEPOINT_SEMAPHORE(net, inbound_connection); TRACEPOINT_SEMAPHORE(net, outbound_connection); TRACEPOINT_SEMAPHORE(net, outbound_message); @@ -1710,6 +1711,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(pnode->m_connected)); pnode->fDisconnect = true; return true; } diff --git a/test/functional/interface_usdt_net.py b/test/functional/interface_usdt_net.py index f4f77ab25bc..00ddf498491 100755 --- a/test/functional/interface_usdt_net.py +++ b/test/functional/interface_usdt_net.py @@ -29,6 +29,9 @@ MAX_MSG_DATA_LENGTH = 150 # from net_address.h NETWORK_TYPE_UNROUTABLE = 0 +# Use in -maxconnections. Results in a maximum of 21 inbound connections +MAX_CONNECTIONS = 32 +MAX_INBOUND_CONNECTIONS = MAX_CONNECTIONS - 10 - 1 # 10 outbound and 1 feeler net_tracepoints_program = """ #include @@ -70,6 +73,12 @@ struct NewConnection u64 existing; }; +struct ClosedConnection +{ + struct Connection conn; + u64 time_established; +}; + BPF_PERF_OUTPUT(inbound_messages); int trace_inbound_message(struct pt_regs *ctx) { struct p2p_message msg = {}; @@ -126,6 +135,21 @@ int trace_outbound_connection(struct pt_regs *ctx) { return 0; }; +BPF_PERF_OUTPUT(evicted_inbound_connections); +int trace_evicted_inbound_connection(struct pt_regs *ctx) { + void *conn_type_pointer = NULL, *address_pointer = NULL; + void* address_pointer; + bpf_usdt_readarg(1, ctx, &evicted.conn.id); + bpf_usdt_readarg(2, ctx, &address_pointer); + bpf_usdt_readarg(3, ctx, &conn_type_pointer); + bpf_usdt_readarg(4, ctx, &evicted.conn.network); + bpf_usdt_readarg(5, ctx, &evicted.time_established); + bpf_probe_read_user_str(&evicted.conn.addr, sizeof(evicted.conn.addr), address_pointer); + bpf_probe_read_user_str(&evicted.conn.type, sizeof(evicted.conn.type), conn_type_pointer); + evicted_inbound_connections.perf_submit(ctx, &evicted, sizeof(evicted)); + return 0; +}; + """ @@ -150,9 +174,19 @@ class NewConnection(ctypes.Structure): def __repr__(self): return f"NewConnection(conn={self.conn}, existing={self.existing})" +class ClosedConnection(ctypes.Structure): + _fields_ = [ + ("conn", Connection), + ("time_established", ctypes.c_uint64), + ] + + def __repr__(self): + return f"ClosedConnection(conn={self.conn}, time_established={self.time_established})" + class NetTracepointTest(BitcoinTestFramework): def set_test_params(self): self.num_nodes = 1 + self.extra_args = [[f'-maxconnections={MAX_CONNECTIONS}']] def skip_test_if_missing_module(self): self.skip_if_platform_not_linux() @@ -164,6 +198,7 @@ class NetTracepointTest(BitcoinTestFramework): self.p2p_message_tracepoint_test() self.inbound_conn_tracepoint_test() self.outbound_conn_tracepoint_test() + self.evicted_inbound_conn_tracepoint_test() def p2p_message_tracepoint_test(self): # Tests the net:inbound_message and net:outbound_message tracepoints @@ -320,5 +355,42 @@ class NetTracepointTest(BitcoinTestFramework): for node in testnodes: node.peer_disconnect() + def evicted_inbound_conn_tracepoint_test(self): + self.log.info("hook into the net:evicted_inbound_connection tracepoint") + ctx = USDT(pid=self.nodes[0].process.pid) + ctx.enable_probe(probe="net:evicted_inbound_connection", + fn_name="trace_evicted_inbound_connection") + bpf = BPF(text=net_tracepoints_program, usdt_contexts=[ctx], debug=0, cflags=["-Wno-error=implicit-function-declaration"]) + + EXPECTED_EVICTED_CONNECTIONS = 2 + evicted_connections = [] + + def handle_evicted_inbound_connection(_, data, __): + event = ctypes.cast(data, ctypes.POINTER(ClosedConnection)).contents + self.log.info(f"handle_evicted_inbound_connection(): {event}") + evicted_connections.append(event) + + bpf["evicted_inbound_connections"].open_perf_buffer(handle_evicted_inbound_connection) + + self.log.info( + f"connect {MAX_INBOUND_CONNECTIONS + EXPECTED_EVICTED_CONNECTIONS} P2P test nodes to our bitcoind node and expect {EXPECTED_EVICTED_CONNECTIONS} evictions") + testnodes = list() + for p2p_idx in range(MAX_INBOUND_CONNECTIONS + EXPECTED_EVICTED_CONNECTIONS): + testnode = P2PInterface() + self.nodes[0].add_p2p_connection(testnode) + testnodes.append(testnode) + bpf.perf_buffer_poll(timeout=200) + + assert_equal(EXPECTED_EVICTED_CONNECTIONS, len(evicted_connections)) + for evicted_connection in evicted_connections: + assert evicted_connection.conn.id > 0 + assert evicted_connection.time_established > 0 + assert_equal("inbound", evicted_connection.conn.conn_type.decode('utf-8')) + assert_equal(NETWORK_TYPE_UNROUTABLE, evicted_connection.conn.network) + + bpf.cleanup() + for node in testnodes: + node.peer_disconnect() + if __name__ == '__main__': NetTracepointTest(__file__).main() From b2ad6ede95ea66e8677b31d614e183953966db54 Mon Sep 17 00:00:00 2001 From: 0xb10c <0xb10c@gmail.com> Date: Mon, 2 May 2022 16:30:15 +0200 Subject: [PATCH 4/7] tracing: add misbehaving conn tracepoint --- doc/tracing.md | 9 ++++ src/net_processing.cpp | 5 ++ test/functional/interface_usdt_net.py | 69 ++++++++++++++++++++++++++- 3 files changed, 81 insertions(+), 2 deletions(-) diff --git a/doc/tracing.md b/doc/tracing.md index 5f7f80c1d99..a092ece9c7e 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -128,6 +128,15 @@ Arguments passed: 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). + ### Context `validation` #### Tracepoint `validation:block_connected` diff --git a/src/net_processing.cpp b/src/net_processing.cpp index 8b7f737a98b..1da3ec9d211 100644 --- 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 index 00ddf498491..3cddd340c8a 100755 --- a/test/functional/interface_usdt_net.py +++ b/test/functional/interface_usdt_net.py @@ -14,7 +14,7 @@ try: from bcc import BPF, USDT # type: ignore[import] except ImportError: pass -from test_framework.messages import msg_version +from test_framework.messages import CBlockHeader, MAX_HEADERS_RESULTS, msg_headers, msg_version from test_framework.p2p import P2PInterface from test_framework.test_framework import BitcoinTestFramework from test_framework.util import assert_equal @@ -23,6 +23,7 @@ from test_framework.util import assert_equal MAX_PEER_ADDR_LENGTH = 68 MAX_PEER_CONN_TYPE_LENGTH = 20 MAX_MSG_TYPE_LENGTH = 20 +MAX_MISBEHAVING_MESSAGE_LENGTH = 128 # We won't process messages larger than 150 byte in this test. For reading # larger messanges see contrib/tracing/log_raw_p2p_msgs.py MAX_MSG_DATA_LENGTH = 150 @@ -40,11 +41,13 @@ net_tracepoints_program = """ #define MAX_PEER_CONN_TYPE_LENGTH {} #define MAX_MSG_TYPE_LENGTH {} #define MAX_MSG_DATA_LENGTH {} +#define MAX_MISBEHAVING_MESSAGE_LENGTH {} """.format( MAX_PEER_ADDR_LENGTH, MAX_PEER_CONN_TYPE_LENGTH, MAX_MSG_TYPE_LENGTH, - MAX_MSG_DATA_LENGTH + MAX_MSG_DATA_LENGTH, + MAX_MISBEHAVING_MESSAGE_LENGTH, ) + """ // A min() macro. Prefixed with _TRACEPOINT_TEST to avoid collision with other MIN macros. #define _TRACEPOINT_TEST_MIN(a,b) ({ __typeof__ (a) _a = (a); __typeof__ (b) _b = (b); _a < _b ? _a : _b; }) @@ -79,6 +82,12 @@ struct ClosedConnection u64 time_established; }; +struct MisbehavingConnection +{ + u64 id; + char message[MAX_MISBEHAVING_MESSAGE_LENGTH]; +}; + BPF_PERF_OUTPUT(inbound_messages); int trace_inbound_message(struct pt_regs *ctx) { struct p2p_message msg = {}; @@ -150,6 +159,16 @@ int trace_evicted_inbound_connection(struct pt_regs *ctx) { return 0; }; +BPF_PERF_OUTPUT(misbehaving_connections); +int trace_misbehaving_connection(struct pt_regs *ctx) { + struct MisbehavingConnection misbehaving = {}; + void *message_pointer = NULL; + bpf_usdt_readarg(1, ctx, &misbehaving.id); + bpf_usdt_readarg(2, ctx, &message_pointer); + bpf_probe_read_user_str(&misbehaving.message, sizeof(misbehaving.message), message_pointer); + misbehaving_connections.perf_submit(ctx, &misbehaving, sizeof(misbehaving)); + return 0; +}; """ @@ -183,6 +202,17 @@ class ClosedConnection(ctypes.Structure): def __repr__(self): return f"ClosedConnection(conn={self.conn}, time_established={self.time_established})" + +class MisbehavingConnection(ctypes.Structure): + _fields_ = [ + ("id", ctypes.c_uint64), + ("message", ctypes.c_char * MAX_MISBEHAVING_MESSAGE_LENGTH), + ] + + def __repr__(self): + return f"MisbehavingConnection(id={self.id}, message={self.message})" + + class NetTracepointTest(BitcoinTestFramework): def set_test_params(self): self.num_nodes = 1 @@ -199,6 +229,7 @@ class NetTracepointTest(BitcoinTestFramework): self.inbound_conn_tracepoint_test() self.outbound_conn_tracepoint_test() self.evicted_inbound_conn_tracepoint_test() + self.misbehaving_conn_tracepoint_test() def p2p_message_tracepoint_test(self): # Tests the net:inbound_message and net:outbound_message tracepoints @@ -392,5 +423,39 @@ class NetTracepointTest(BitcoinTestFramework): for node in testnodes: node.peer_disconnect() + def misbehaving_conn_tracepoint_test(self): + self.log.info("hook into the net:misbehaving_connection tracepoint") + ctx = USDT(pid=self.nodes[0].process.pid) + ctx.enable_probe(probe="net:misbehaving_connection", + fn_name="trace_misbehaving_connection") + bpf = BPF(text=net_tracepoints_program, usdt_contexts=[ctx], debug=0, cflags=["-Wno-error=implicit-function-declaration"]) + + EXPECTED_MISBEHAVING_CONNECTIONS = 2 + misbehaving_connections = [] + + def handle_misbehaving_connection(_, data, __): + event = ctypes.cast(data, ctypes.POINTER(MisbehavingConnection)).contents + self.log.info(f"handle_misbehaving_connection(): {event}") + misbehaving_connections.append(event) + + bpf["misbehaving_connections"].open_perf_buffer(handle_misbehaving_connection) + + self.log.info("connect a misbehaving P2P test nodes to our bitcoind node") + msg = msg_headers([CBlockHeader()] * (MAX_HEADERS_RESULTS + 1)) + for _ in range(EXPECTED_MISBEHAVING_CONNECTIONS): + testnode = P2PInterface() + self.nodes[0].add_p2p_connection(testnode) + testnode.send_message(msg) + bpf.perf_buffer_poll(timeout=500) + testnode.peer_disconnect() + + assert_equal(EXPECTED_MISBEHAVING_CONNECTIONS, len(misbehaving_connections)) + for misbehaving_connection in misbehaving_connections: + assert misbehaving_connection.id > 0 + assert len(misbehaving_connection.message) > 0 + assert misbehaving_connection.message == b"headers message size = 2001" + + bpf.cleanup() + if __name__ == '__main__': NetTracepointTest(__file__).main() From caa5486574baf805b36c8abc873554aee4ba82b7 Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Fri, 12 Aug 2022 16:04:16 +0200 Subject: [PATCH 5/7] tracing: connection closed tracepoint --- doc/tracing.md | 12 ++++++ src/net.cpp | 8 ++++ test/functional/interface_usdt_net.py | 57 ++++++++++++++++++++++++++- 3 files changed, 76 insertions(+), 1 deletion(-) diff --git a/doc/tracing.md b/doc/tracing.md index a092ece9c7e..c374cdb8583 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -137,6 +137,18 @@ 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` (max. length 68 characters) +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 index de947a1a98d..ebcd3cb77d4 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -53,6 +53,7 @@ #include #include +TRACEPOINT_SEMAPHORE(net, closed_connection); TRACEPOINT_SEMAPHORE(net, evicted_inbound_connection); TRACEPOINT_SEMAPHORE(net, inbound_connection); TRACEPOINT_SEMAPHORE(net, outbound_connection); @@ -563,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(m_connected)); } m_i2p_sam_session.reset(); } diff --git a/test/functional/interface_usdt_net.py b/test/functional/interface_usdt_net.py index 3cddd340c8a..beb25461530 100755 --- a/test/functional/interface_usdt_net.py +++ b/test/functional/interface_usdt_net.py @@ -146,8 +146,8 @@ int trace_outbound_connection(struct pt_regs *ctx) { BPF_PERF_OUTPUT(evicted_inbound_connections); int trace_evicted_inbound_connection(struct pt_regs *ctx) { + struct ClosedConnection evicted = {}; void *conn_type_pointer = NULL, *address_pointer = NULL; - void* address_pointer; bpf_usdt_readarg(1, ctx, &evicted.conn.id); bpf_usdt_readarg(2, ctx, &address_pointer); bpf_usdt_readarg(3, ctx, &conn_type_pointer); @@ -169,6 +169,21 @@ int trace_misbehaving_connection(struct pt_regs *ctx) { misbehaving_connections.perf_submit(ctx, &misbehaving, sizeof(misbehaving)); return 0; }; + +BPF_PERF_OUTPUT(closed_connections); +int trace_closed_connection(struct pt_regs *ctx) { + struct ClosedConnection closed = {}; + void *conn_type_pointer = NULL, *address_pointer = NULL; + bpf_usdt_readarg(1, ctx, &closed.conn.id); + bpf_usdt_readarg(2, ctx, &address_pointer); + bpf_usdt_readarg(3, ctx, &conn_type_pointer); + bpf_usdt_readarg(4, ctx, &closed.conn.network); + bpf_usdt_readarg(5, ctx, &closed.time_established); + bpf_probe_read_user_str(&closed.conn.addr, sizeof(closed.conn.addr), address_pointer); + bpf_probe_read_user_str(&closed.conn.type, sizeof(closed.conn.type), conn_type_pointer); + closed_connections.perf_submit(ctx, &closed, sizeof(closed)); + return 0; +}; """ @@ -193,6 +208,7 @@ class NewConnection(ctypes.Structure): def __repr__(self): return f"NewConnection(conn={self.conn}, existing={self.existing})" + class ClosedConnection(ctypes.Structure): _fields_ = [ ("conn", Connection), @@ -230,6 +246,7 @@ class NetTracepointTest(BitcoinTestFramework): self.outbound_conn_tracepoint_test() self.evicted_inbound_conn_tracepoint_test() self.misbehaving_conn_tracepoint_test() + self.closed_conn_tracepoint_test() def p2p_message_tracepoint_test(self): # Tests the net:inbound_message and net:outbound_message tracepoints @@ -457,5 +474,43 @@ class NetTracepointTest(BitcoinTestFramework): bpf.cleanup() + def closed_conn_tracepoint_test(self): + self.log.info("hook into the net:closed_connection tracepoint") + ctx = USDT(pid=self.nodes[0].process.pid) + ctx.enable_probe(probe="net:closed_connection", + fn_name="trace_closed_connection") + bpf = BPF(text=net_tracepoints_program, usdt_contexts=[ctx], debug=0, cflags=["-Wno-error=implicit-function-declaration"]) + + EXPECTED_CLOSED_CONNECTIONS = 2 + closed_connections = [] + + def handle_closed_connection(_, data, __): + event = ctypes.cast(data, ctypes.POINTER(ClosedConnection)).contents + self.log.info(f"handle_closed_connection(): {event}") + closed_connections.append(event) + + bpf["closed_connections"].open_perf_buffer(handle_closed_connection) + + self.log.info( + f"connect {EXPECTED_CLOSED_CONNECTIONS} P2P test nodes to our bitcoind node") + testnodes = list() + for p2p_idx in range(EXPECTED_CLOSED_CONNECTIONS): + testnode = P2PInterface() + self.nodes[0].add_p2p_connection(testnode) + testnodes.append(testnode) + for node in testnodes: + node.peer_disconnect() + self.wait_until(lambda: len(self.nodes[0].getpeerinfo()) == 0) + bpf.perf_buffer_poll(timeout=400) + + assert_equal(EXPECTED_CLOSED_CONNECTIONS, len(closed_connections)) + for closed_connection in closed_connections: + assert closed_connection.conn.id > 0 + assert_equal("inbound", closed_connection.conn.conn_type.decode('utf-8')) + assert_equal(0, closed_connection.conn.network) + assert closed_connection.time_established > 0 + + bpf.cleanup() + if __name__ == '__main__': NetTracepointTest(__file__).main() From b19b526758f055733e1c21809cf975169fdd39b0 Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Fri, 12 Aug 2022 18:34:48 +0200 Subject: [PATCH 6/7] tracing: log_p2p_connections.bt example A bpftrace script that logs information from the net:*_connection tracepoints. I've tested this script with bpftrace version 0.14.1 and v0.20.2. --- contrib/tracing/README.md | 21 +++++++++++ contrib/tracing/log_p2p_connections.bt | 51 ++++++++++++++++++++++++++ 2 files changed, 72 insertions(+) create mode 100755 contrib/tracing/log_p2p_connections.bt diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md index aa48b3e3f33..0757ab9c76d 100644 --- 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 new file mode 100755 index 00000000000..fd2cc934d73 --- /dev/null +++ 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); +} From e3622a969293feea75cfadc8f7c6083edcd6d8de Mon Sep 17 00:00:00 2001 From: 0xb10c Date: Wed, 13 Nov 2024 15:23:48 +0100 Subject: [PATCH 7/7] tracing: document that peer addrs can be >68 chars A v3 onion address with a `:` and a five digit port has a length of 68 chars. As noted in https://github.com/bitcoin/bitcoin/pull/25832#discussion_r1781040991 peers e.g. added via hostname might have a longer CNode::m_addr_name. These might be cut off in tracing tools. --- doc/tracing.md | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/doc/tracing.md b/doc/tracing.md index c374cdb8583..53577438fa7 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -55,6 +55,9 @@ 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 @@ -62,7 +65,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` @@ -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` @@ -100,7 +103,7 @@ the peer and the number of inbound connections including the newly opened connec 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. 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. @@ -112,7 +115,7 @@ the peer and the number of outbound connections including the newly opened conne 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. 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. @@ -123,7 +126,7 @@ Is called when a inbound connection is evicted by us. Passes information about t 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. 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`. @@ -144,7 +147,7 @@ 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` (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. 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`.