diff --git a/bpf/tctracer/tc_ip.h b/bpf/tctracer/tc_ip.h index 11a5db41d..a84444cca 100644 --- a/bpf/tctracer/tc_ip.h +++ b/bpf/tctracer/tc_ip.h @@ -27,7 +27,7 @@ static __always_inline void print_tp(tp_info_pid_t *new_tp) { unsigned char tp_buf[TP_MAX_VAL_LENGTH]; make_tp_string(tp_buf, &new_tp->tp); - bpf_dbg_printk("tp: %s", tp_buf); + bpf_dbg_printk("%s: tp=%s", __FUNCTION__, tp_buf); } static __always_inline void @@ -39,12 +39,12 @@ parse_ip_options_ipv4(struct __sk_buff *skb, connection_info_t *conn, protocol_i sort_connection_info(conn); bpf_skb_load_bytes(skb, ip_off, &key, sizeof(key)); - bpf_dbg_printk("options %llx, len = %d", key, tcp->ip_len); + bpf_dbg_printk("%s: options=%llx, len=%d", __FUNCTION__, key, tcp->ip_len); if (key == TC_TP_ID) { tp_info_pid_t *existing_tp = (tp_info_pid_t *)bpf_map_lookup_elem(&incoming_trace_map, conn); if (!existing_tp) { - bpf_dbg_printk("Found tp context in opts! ihl = %d", tcp->ip_len); + bpf_dbg_printk("%s: found tp context in opts! ihl=%d", __FUNCTION__, tcp->ip_len); tp_info_pid_t new_tp = {.pid = 0, .valid = 1}; populate_span_id_from_tcp_info(&new_tp.tp, tcp); @@ -56,14 +56,14 @@ parse_ip_options_ipv4(struct __sk_buff *skb, connection_info_t *conn, protocol_i bpf_map_update_elem(&incoming_trace_map, conn, &new_tp, BPF_ANY); } else { - bpf_dbg_printk("ignoring existing tp"); + bpf_dbg_printk("%s: ignoring existing tp", __FUNCTION__); } } } static __always_inline void parse_ip_options_ipv6(struct __sk_buff *skb, connection_info_t *conn, protocol_info_t *tcp) { - bpf_dbg_printk("IPv6 ingress"); + bpf_dbg_printk("%s: IPv6 ingress", __FUNCTION__); dbg_print_http_connection_info(conn); sort_connection_info(conn); @@ -109,8 +109,10 @@ static __always_inline u8 inject_tc_ip_options_ipv4(struct __sk_buff *skb, new_hdr_len += (MAX_TC_TP_LEN / 4); // IHL is a number of 32bit words new_hdr_len |= hdr_ver & 0xf0; - bpf_dbg_printk( - "prev h_len %d, new_h_len %d, new_tot_len %d", hdr_len, new_hdr_len, new_tot_len); + bpf_dbg_printk("inject_tc_ip_options_ipv4: prev h_len=%d, new_h_len=%d, new_tot_len=%d", + hdr_len, + new_hdr_len, + new_tot_len); bpf_skb_store_bytes(skb, offset_ip_tot_len, &new_tot_len, sizeof(u16), 0); bpf_skb_store_bytes(skb, ETH_HLEN, &new_hdr_len, sizeof(u8), 0); diff --git a/bpf/tctracer/tctracer.c b/bpf/tctracer/tctracer.c index bfe7aec44..6e0331e0f 100644 --- a/bpf/tctracer/tctracer.c +++ b/bpf/tctracer/tctracer.c @@ -58,18 +58,24 @@ static __always_inline void update_outgoing_request_span_id(pid_connection_info_ const egress_key_t *e_key) { http_info_t *h_info = bpf_map_lookup_elem(&ongoing_http, p_conn); if (h_info && tp->valid) { - bpf_dbg_printk("Found HTTP info, resetting the span id to %x%x", tcp->seq, tcp->ack); + bpf_dbg_printk("%s: found HTTP info, resetting the span id to seq=%x, ack=%x", + __FUNCTION__, + tcp->seq, + tcp->ack); + populate_span_id_from_tcp_info(&h_info->tp, tcp); } go_addr_key_t *g_key = bpf_map_lookup_elem(&go_ongoing_http, e_key); if (g_key) { - bpf_dbg_printk("Found Go HTTP info, trying to find the span id"); + bpf_dbg_printk("%s: found Go HTTP info, trying to find the span id", __FUNCTION__); http_func_invocation_t *invocation = bpf_map_lookup_elem(&go_ongoing_http_client_requests, g_key); if (invocation) { - bpf_dbg_printk( - "Found Go HTTP invocation, resetting the span id to %x%x", tcp->seq, tcp->ack); + bpf_dbg_printk("%s: found Go HTTP invocation, resetting the span id to seq=%x, ack=%x", + __FUNCTION__, + tcp->seq, + tcp->ack); populate_span_id_from_tcp_info(&invocation->tp, tcp); } } @@ -80,12 +86,12 @@ encode_data_in_ip_options(struct __sk_buff *skb, protocol_info_t *tcp, tp_info_p // Handling IPv4 // We only do this if the IP header doesn't have any options, this can be improved if needed if (tcp->h_proto == ETH_P_IP && tcp->ip_len == MIN_IP_LEN) { - bpf_dbg_printk("Adding the trace_id in the IP Options"); + bpf_dbg_printk("%s: adding the trace_id in the IP Options", __FUNCTION__); inject_tc_ip_options_ipv4(skb, tcp, tp); tp->valid = 0; } else if (tcp->h_proto == ETH_P_IPV6 && tcp->l4_proto == IPPROTO_TCP) { // Handling IPv6 - bpf_dbg_printk("Found IPv6 header"); + bpf_dbg_printk("%s: found IPv6 header", __FUNCTION__); inject_tc_ip_options_ipv6(skb, tcp, tp); tp->valid = 0; @@ -179,7 +185,7 @@ static __always_inline void track_sock(struct __sk_buff *skb, const connection_i const struct ethhdr *eth = (struct ethhdr *)(data); if ((void *)(eth + 1) > data_end) { - bpf_dbg_printk("bad size"); + bpf_dbg_printk("%s: bad size", __FUNCTION__); return; } @@ -190,7 +196,7 @@ static __always_inline void track_sock(struct __sk_buff *skb, const connection_i //bpf_printk("tuple %llx, next %llx, data end %llx", tuple, (void *)((u8 *)tuple + sizeof(*tuple)), data_end); if (!tuple) { - bpf_dbg_printk("bad tuple %llx, next %llx, data end %llx", + bpf_dbg_printk("track_sock: bad tuple=%llx, next=%llx, data end=%llx", tuple, (void *)(tuple + sizeof(struct bpf_sock_tuple)), data_end); @@ -198,7 +204,7 @@ static __always_inline void track_sock(struct __sk_buff *skb, const connection_i } struct bpf_sock *sk = lookup_sock_from_tuple(skb, tuple, proto, data_end); - bpf_dbg_printk("sk=%llx\n", sk); + bpf_dbg_printk("%s: sk=%llx", __FUNCTION__, sk); if (!sk) { return; @@ -238,7 +244,7 @@ int obi_app_egress(struct __sk_buff *skb) { // deleted by the kprobes when tp->written == 1, but it does not hurt to // be robust if (tp->written) { - bpf_dbg_printk("tp already written by L7, not injecting IP options"); + bpf_dbg_printk("%s: tp already written by L7, not injecting IP options", __FUNCTION__); bpf_map_delete_elem(&outgoing_trace_map, &e_key); return TC_ACT_UNSPEC; } @@ -250,7 +256,8 @@ int obi_app_egress(struct __sk_buff *skb) { // means we haven't seen this request yet. p_conn.pid = tp->pid; - bpf_dbg_printk("egress flags %x, sequence %x, valid %d", tcp.flags, tcp.seq, tp->valid); + bpf_dbg_printk( + "%s: egress flags=%x, sequence=%x, valid=%d", __FUNCTION__, tcp.flags, tcp.seq, tp->valid); dbg_print_http_connection_info(&conn); // If it's the first packet of a request: diff --git a/bpf/tpinjector/tpinjector.c b/bpf/tpinjector/tpinjector.c index 43dfb6eaf..1fd24d270 100644 --- a/bpf/tpinjector/tpinjector.c +++ b/bpf/tpinjector/tpinjector.c @@ -225,7 +225,7 @@ static __always_inline connection_info_t sk_msg_extract_key_ip6(struct sk_msg_md static __always_inline bool create_trace_info(u64 id, const connection_info_t *conn, tp_info_pid_t *tp_p) { - bpf_dbg_printk("=== %s ===", __FUNCTION__); + bpf_dbg_printk("=== obi_packet_extender(%s) ===", __FUNCTION__); pid_connection_info_t *p_conn = pid_conn_info_buf(); @@ -248,11 +248,11 @@ create_trace_info(u64 id, const connection_info_t *conn, tp_info_pid_t *tp_p) { urand_bytes(tp_p->tp.span_id, SPAN_ID_SIZE_BYTES); if (find_trace_for_client_request(p_conn, p_conn->conn.d_port, &tp_p->tp)) { - bpf_dbg_printk("found existing tp info"); + bpf_dbg_printk("obi_packet_extender(%s): found existing tp info", __FUNCTION__); return true; } - bpf_dbg_printk("generating tp info"); + bpf_dbg_printk("obi_packet_extender(%s): generating tp info", __FUNCTION__); new_trace_id(&tp_p->tp); __builtin_memset(tp_p->tp.parent_id, 0, sizeof(tp_p->tp.parent_id)); @@ -292,7 +292,7 @@ static __always_inline void bpf_sock_ops_opt_len_cb(struct bpf_sock_ops *skops) const long ret = bpf_reserve_hdr_opt(skops, sizeof(struct tp_option), 0); if (ret != 0) { - bpf_dbg_printk("bpf_sock_ops_opt_len_cb: failed to reserve TCP option: %d", ret); + bpf_dbg_printk("%s: failed to reserve TCP option: %d", __FUNCTION__, ret); return; } } @@ -307,7 +307,7 @@ static __always_inline void bpf_sock_ops_write_hdr_cb(struct bpf_sock_ops *skops const tp_info_pid_t *tp_pid = bpf_sk_storage_get(&sk_tp_info_pid_map, sk, NULL, 0); if (!tp_pid) { - bpf_dbg_printk("bpf_sock_ops_write_hdr_cb: tp info not found"); + bpf_dbg_printk("%s: tp info not found", __FUNCTION__); return; } @@ -323,14 +323,14 @@ static __always_inline void bpf_sock_ops_write_hdr_cb(struct bpf_sock_ops *skops const long ret = bpf_store_hdr_opt(skops, &opt, sizeof(opt), 0); if (ret != 0) { - bpf_dbg_printk("bpf_sock_ops_write_hdr_cb: failed to store option: %d", ret); + bpf_dbg_printk("%s: failed to store option: %d", __FUNCTION__, ret); } if (k_bpf_debug) { const char *tp_str = tp_string_from_opt(&opt); if (tp_str) { - bpf_dbg_printk("bpf_sock_ops_write_hdb_cb: written TP to TCP options: %s", tp_str); + bpf_dbg_printk("%s: written TP to TCP options: %s", __FUNCTION__, tp_str); } } } @@ -346,7 +346,7 @@ static __always_inline void bpf_sock_ops_parse_hdr_cb(struct bpf_sock_ops *skops } if (ret < 0) { - bpf_dbg_printk("bpf_sock_ops_parse_hdr_cb: error parsing TCP option = %d", ret); + bpf_dbg_printk("%s: error parsing TCP option: %d", __FUNCTION__, ret); return; } @@ -354,7 +354,7 @@ static __always_inline void bpf_sock_ops_parse_hdr_cb(struct bpf_sock_ops *skops const char *tp_str = tp_string_from_opt(&opt); if (tp_str) { - bpf_dbg_printk("bpf_sock_ops_parse_hdr_cb: found TP in TCP options: %s", tp_str); + bpf_dbg_printk("%s: found TP in TCP options: %s", __FUNCTION__, tp_str); } } @@ -416,7 +416,7 @@ static __always_inline u8 protocol_detector(struct sk_msg_md *msg, u64 id, const connection_info_t *conn, const egress_key_t *e_key) { - bpf_dbg_printk("=== [protocol detector] %d size %d===", id, msg->size); + bpf_dbg_printk("%s: id=%d, size=%d", __FUNCTION__, id, msg->size); pid_connection_info_t p_conn = {}; __builtin_memcpy(&p_conn.conn, conn, sizeof(connection_info_t)); @@ -443,7 +443,7 @@ static __always_inline u8 protocol_detector(struct sk_msg_md *msg, unsigned char **msg_ptr = bpf_map_lookup_elem(&msg_buffer_mem, &(u32){0}); if (!msg_ptr) { - bpf_d_printk("protocol_detector: failed to reserve msg_buffer space"); + bpf_d_printk("%s: failed to reserve msg_buffer space", __FUNCTION__); return 0; } @@ -465,12 +465,12 @@ static __always_inline u8 protocol_detector(struct sk_msg_md *msg, // started tracking it. We only want to extend the first packet that // looks like HTTP, not something that's passing HTTP in the body. if (already_tracked(&p_conn)) { - bpf_dbg_printk("already extended before, ignoring this packet..."); + bpf_dbg_printk("%s: already extended before, ignoring this packet...", __FUNCTION__); return 0; } if (is_http_request_buf((const unsigned char *)msg_ptr)) { - bpf_dbg_printk("Setting up request to be extended"); + bpf_dbg_printk("%s: setting up request to be extended", __FUNCTION__); return 1; } @@ -550,7 +550,7 @@ make_tp_string_skb(unsigned char *buf, const tp_info_t *tp, const unsigned char *buf++ = '\r'; *buf++ = '\n'; - bpf_dbg_printk("obi_packet_extender: %s", tp_string); + bpf_dbg_printk("obi_packet_extender(%s): %s", __FUNCTION__, tp_string); } static __always_inline bool @@ -558,23 +558,25 @@ extend_and_write_tp(struct sk_msg_md *msg, u32 offset, const tp_info_t *tp) { const long err = bpf_msg_push_data(msg, offset, EXTEND_SIZE, 0); if (err != 0) { - bpf_d_printk("failed to push data: %d", err); + bpf_d_printk("%s: failed to push data: %d", __FUNCTION__, err); return false; } bpf_msg_pull_data(msg, 0, msg->size, 0); - bpf_dbg_printk( - "offset to split %d, available: %u, size %u", offset, msg->data_end - msg->data, msg->size); + bpf_dbg_printk("extend_and_write_tp: offset to split=%d, available=%u, size=%u", + offset, + msg->data_end - msg->data, + msg->size); if (!msg->data) { - bpf_d_printk("null data"); + bpf_d_printk("%s: null data", __FUNCTION__); return false; } unsigned char *ptr = msg->data + offset; if ((void *)ptr + EXTEND_SIZE >= msg->data_end) { - bpf_d_printk("not enough space"); + bpf_d_printk("%s: not enough space", __FUNCTION__); return false; } @@ -634,7 +636,7 @@ static __always_inline void write_http_traceparent(struct sk_msg_md *msg, tp_inf bpf_tail_call(msg, &extender_jump_table, k_tail_write_msg_traceparent); - bpf_d_printk("tailcall failed"); + bpf_d_printk("%s: tailcall failed", __FUNCTION__); } static __always_inline void handle_existing_tp_pid(struct sk_msg_md *msg, @@ -698,10 +700,10 @@ int obi_packet_extender(struct sk_msg_md *msg) { if (!valid_pid(id)) { return SK_PASS; } - - bpf_dbg_printk("MSG %llx:%d ->", conn.s_ip[3], conn.s_port); - bpf_dbg_printk("MSG TO %llx:%d", conn.d_ip[3], conn.d_port); - bpf_dbg_printk("MSG SIZE: %u", msg->size); + bpf_dbg_printk("=== %s ===", __FUNCTION__); + bpf_dbg_printk("%s: MSG=%llx:%d ->", __FUNCTION__, conn.s_ip[3], conn.s_port); + bpf_dbg_printk("%s: MSG TO=%llx:%d", __FUNCTION__, conn.d_ip[3], conn.d_port); + bpf_dbg_printk("%s: MSG SIZE=%u", __FUNCTION__, msg->size); if (msg->size <= MIN_HTTP_SIZE) { // not enough data to detect anything, bail @@ -721,9 +723,11 @@ int obi_packet_extender(struct sk_msg_md *msg) { return SK_PASS; } - bpf_dbg_printk("len %d, s_port %d, buf: %s", msg->size, msg->local_port, msg->data); - bpf_dbg_printk("ptr = %llx, end = %llx", ctx_msg_data(msg), ctx_msg_data_end(msg)); - bpf_dbg_printk("BUF: '%s'", ctx_msg_data(msg)); + bpf_dbg_printk("%s: len=%d, s_port=%d", __FUNCTION__, msg->size, msg->local_port); + bpf_dbg_printk("%s: buf=[%s]", __FUNCTION__, msg->data); + bpf_dbg_printk( + "%s: ptr=%llx, end=%llx", __FUNCTION__, ctx_msg_data(msg), ctx_msg_data_end(msg)); + bpf_dbg_printk("%s: BUF=[%s]", __FUNCTION__, ctx_msg_data(msg)); // we've found the start of a new HTTP request, let's generate new TP info for it tp_info_pid_t *tp_p = tp_buf(); @@ -748,7 +752,7 @@ int obi_packet_extender(struct sk_msg_md *msg) { if (inject_flags & k_inject_http_headers) { // write the HTTP headers bpf_tail_call(msg, &extender_jump_table, k_tail_write_msg_traceparent); - bpf_d_printk("tailcall failed"); + bpf_d_printk("%s: tailcall failed", __FUNCTION__); } return SK_PASS; @@ -762,17 +766,17 @@ int obi_packet_extender_write_msg_tp(struct sk_msg_md *msg) { tp_info_pid_t *tp_p = tp_buf(); if (!tp_p) { - bpf_dbg_printk("empty tp_buf"); + bpf_dbg_printk("%s: empty tp_buf", __FUNCTION__); return SK_PASS; } bpf_msg_pull_data(msg, 0, msg->size, 0); if (!write_msg_traceparent(msg, &tp_p->tp)) { - bpf_d_printk("failed to write traceparent"); + bpf_d_printk("%s: failed to write traceparent", __FUNCTION__); } - bpf_dbg_printk("BUF = [%s]", msg->data); + bpf_dbg_printk("%s: BUF=[%s]", __FUNCTION__, msg->data); return SK_PASS; } diff --git a/devdocs/README.md b/devdocs/README.md index 93eb992f6..5ac426e98 100644 --- a/devdocs/README.md +++ b/devdocs/README.md @@ -9,3 +9,4 @@ This directory contains documentation that is not useful for our users but might - [Features](features.md): features supported by OBI. - [Context Propagation Architecture](context-propagation.md): how OpenTelemetry context propagation works in the eBPF instrumentation. - [Protocols](protocols.md): documentation about supported protocols. +- [BPF print format](bpf-print-format.md): it explains a uniform standard for all BPF print debug statements across the project. diff --git a/devdocs/bpf-print-format.md b/devdocs/bpf-print-format.md new file mode 100644 index 000000000..0e0f69b7f --- /dev/null +++ b/devdocs/bpf-print-format.md @@ -0,0 +1,117 @@ +# BPF print format + +This document explains a uniform standard for all BPF print debug statements across the project. + +The goal is to ensure that our logs are not just data dumps, but more structured and useful. + +## Table Of Contents + +- [Formatting data](#formatting-data) + - [Multiple variables (key-value pairs)](#multiple-variables-key-value-pairs) + - [Single result or status](#single-result-or-status) + - [Avoiding concatenation](#avoiding-concatenation) +- [Function name in log messages](#function-name-in-log-messages) + - [Function name in eBPF probe](#function-name-in-ebpf-probe) + - [Function name in generic functions](#function-name-in-generic-functions) +- [Compatibility and workarounds](#compatibility-and-workarounds) + +### Formatting data + +This section will cover the difference between using **`=`** and **`:`**. + +#### Multiple variables (key-value pairs) + +The equals sign **`=`** is best for creating clear key-value pairs, especially when logging multiple variables. Example: + +```c +bpf_dbg_printk("%s: id=%d, size=%d", __FUNCTION__, id, msg->size); +``` + +Log output: `protocol_detector: id=12, size=33`. + +#### Single result or status + +The colon **`:`** is best for introducing a single, consequential piece of information that completes or explains the preceding human-readable sentence. Example: + +```c +bpf_d_printk("%s: failed to push data: %d", __FUNCTION__, err); +``` + +Log output: `extend_and_write_tp: failed to push data: -1`. + +#### Avoiding concatenation + +Addressing issues like logging multiple variables without a separator (e.g., avoiding `%x%x`). Example: + +```c +bpf_dbg_printk("%s: found HTTP info, resetting the span id to seq=%x, ack=%x", __FUNCTION__, tcp->seq, tcp->ack); +``` + +Log output: `update_outgoing_request_span_id: found HTTP info, resetting the span id to seq=5a3b9c1d, ack=0e2f`. + +For logging the contents of a buffer like `msg->data`, it is best to use a key like `BUF=` followed by brackets **`[]`** around the string. Example: + +```c +bpf_dbg_printk("%s: BUF=[%s]", __FUNCTION__, msg->data); +``` + +Log output: `obi_packet_extender_write_msg_tp: BUF=[Hello]` + +### Function name in log messages + +This section ensures every log message is contextualized. + +We use **`__FUNCTION__`** which is a compile-time string literal (not a runtime function call) to print the function name. + +#### Function name in eBPF probe + +At the beginning of an eBPF probe (not every probe, as it can be too verbose\!), print the function name in the following way: + +```c +bpf_dbg_printk("=== %s ===", __FUNCTION__); +``` + +Log output: `=== obi_kprobe_do_vfs_ioctl ===`. + +Note that **`at the beginning`** does not mean as the first instruction, but you need to find the best place, like after some initial checks (example: after `if (!valid_pid(id)) {...}`). + +The rest of the print statements in the eBPF probe function will be without **`===`** with the **`:`** after the eBPF probe function name. Example: + +```c +bpf_d_printk("%s: tailcall failed", __FUNCTION__); +``` + +Log output: `obi_packet_extender: tailcall failed`. + +#### Function name in generic functions + +To print the function name in a generic function, use the **`__FUNCTION__`** identifier in **every log statement** without the bounding **`===`**. The triple equals signs are reserved exclusively for entry points of eBPF probes. Example: + +```c +bpf_dbg_printk("%s: found IPv6 header", __FUNCTION__); +``` + +Log output: `encode_data_in_ip_options: found IPv6 header`. + +**Special case**: there can be certain functions that are only called by an eBPF probe, and it can be useful to have both the eBPF probe function name and the function name of the current function. Example: + +```c +bpf_dbg_printk("=== obi_packet_extender(%s) ===", __FUNCTION__); +``` + +Log output: `=== obi_packet_extender(create_trace_info) ===`. + +In this case the rest of the print statements in the function will be without **`===`** with the **`:`** after the eBPF probe function name and current function name. Example: + +```c +bpf_dbg_printk("obi_packet_extender(%s): generating tp info", __FUNCTION__); +``` + +Log output: `obi_packet_extender(create_trace_info): generating tp info`. + +### Compatibility and workarounds + +It can happen, sometimes, that the number of arguments to print is 3, but when `__FUNCTION__` is included, the total reaches 4. In these cases, `bpf_dbg_printk` calls `bpf_printk`, which subsequently calls `___bpf_pick_printk`. This chain then selects and calls `__bpf_vprintk` (for 4+ arguments), which finally invokes `bpf_trace_vprintk`. Since `bpf_trace_vprintk` is only available starting in [kernel version 5.16](https://docs.ebpf.io/linux/helper-function/bpf_trace_vprintk/), two options are available to avoid errors when loading the eBPF program: + +1. Split the print into two separate calls: one with one argument and one with two arguments, where `__FUNCTION__` is added to both. +2. Hardcode the function name instead of using `__FUNCTION__`, so that the total number of arguments remains three.