Skip to content

Uniform debug print messages in ebpf code #941

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Uniform debug print messages in ebpf code #941

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 9 additions & 7 deletions bpf/tctracer/tc_ip.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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);

Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand Down
29 changes: 18 additions & 11 deletions bpf/tctracer/tctracer.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Copy link
Contributor

@rafaelroquetto rafaelroquetto Nov 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe this is a mistake - the span id here is indeed meant to be the combination of %x%x, i.e. the concatenation of seq and ack.

Copy link
Contributor Author

@pinoOgni pinoOgni Nov 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ops, thanks!

__FUNCTION__,
tcp->seq,
tcp->ack);
populate_span_id_from_tcp_info(&invocation->tp, tcp);
}
}
Expand All @@ -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;
Expand Down Expand Up @@ -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;
}

Expand All @@ -190,15 +196,15 @@ 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);
return;
}

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;
Expand Down Expand Up @@ -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;
}
Expand All @@ -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:
Expand Down
66 changes: 35 additions & 31 deletions bpf/tpinjector/tpinjector.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();

Expand All @@ -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));
Expand Down Expand Up @@ -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;
}
}
Expand All @@ -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;
}

Expand All @@ -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);
}
}
}
Expand All @@ -346,15 +346,15 @@ 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;
}

if (k_bpf_debug) {
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);
}
}

Expand Down Expand Up @@ -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));
Expand All @@ -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;
}

Expand All @@ -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;
}
Expand Down Expand Up @@ -550,31 +550,33 @@ 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
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;
}

Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand All @@ -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();
Expand All @@ -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;
Expand All @@ -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;
}
1 change: 1 addition & 0 deletions devdocs/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Loading
Loading