From eb8b1a233beee1e11eb700e2201becc34f913f9e Mon Sep 17 00:00:00 2001 From: David Gibson Date: Thu, 30 Nov 2023 13:02:13 +1100 Subject: flow, tcp: Add logging helpers for connection related messages Most of the messages logged by the TCP code (be they errors, debug or trace messages) are related to a specific connection / flow. We're fairly consistent about prefixing these with the type of connection and the connection / flow index. However there are a few places where we put the index later in the message or omit it entirely. The template with the prefix is also a little bulky to carry around for every message, particularly for spliced connections. To help keep this consistent, introduce some helpers to log messages linked to a specific flow. It takes the flow as a parameter and adds a uniform prefix to each message. This makes things slightly neater now, but more importantly will help keep formatting consistent as we add more things to the flow table. Signed-off-by: David Gibson Signed-off-by: Stefano Brivio --- flow.c | 18 +++++++++++++ flow.h | 14 +++++++++++ tcp.c | 82 ++++++++++++++++++++++++++++-------------------------------- tcp_splice.c | 61 +++++++++++++++++++------------------------- 4 files changed, 96 insertions(+), 79 deletions(-) diff --git a/flow.c b/flow.c index 534638b..d24726d 100644 --- a/flow.c +++ b/flow.c @@ -66,3 +66,21 @@ void flow_table_compact(struct ctx *c, union flow *hole) memset(from, 0, sizeof(*from)); } + +/** flow_log_ - Log flow-related message + * @f: flow the message is related to + * @pri: Log priority + * @fmt: Format string + * @...: printf-arguments + */ +void flow_log_(const struct flow_common *f, int pri, const char *fmt, ...) +{ + char msg[BUFSIZ]; + va_list args; + + va_start(args, fmt); + (void)vsnprintf(msg, sizeof(msg), fmt, args); + va_end(args); + + logmsg(pri, "Flow %u (%s): %s", flow_idx(f), FLOW_TYPE(f), msg); +} diff --git a/flow.h b/flow.h index f3dad53..c820a15 100644 --- a/flow.h +++ b/flow.h @@ -43,4 +43,18 @@ union flow; void flow_table_compact(struct ctx *c, union flow *hole); +void flow_log_(const struct flow_common *f, int pri, const char *fmt, ...) + __attribute__((format(printf, 3, 4))); + +#define flow_log(f_, pri, ...) flow_log_(&(f_)->f, (pri), __VA_ARGS__) + +#define flow_dbg(f, ...) flow_log((f), LOG_DEBUG, __VA_ARGS__) +#define flow_err(f, ...) flow_log((f), LOG_ERR, __VA_ARGS__) + +#define flow_trace(f, ...) \ + do { \ + if (log_trace) \ + flow_dbg((f), __VA_ARGS__); \ + } while (0) + #endif /* FLOW_H */ diff --git a/tcp.c b/tcp.c index 0fca342..a83704e 100644 --- a/tcp.c +++ b/tcp.c @@ -624,7 +624,7 @@ static void conn_flag_do(const struct ctx *c, struct tcp_tap_conn *conn, unsigned long flag); #define conn_flag(c, conn, flag) \ do { \ - trace("TCP: flag at %s:%i", __func__, __LINE__); \ + flow_trace(conn, "flag at %s:%i", __func__, __LINE__); \ conn_flag_do(c, conn, flag); \ } while (0) @@ -695,7 +695,8 @@ static void tcp_timer_ctl(const struct ctx *c, struct tcp_tap_conn *conn) fd = timerfd_create(CLOCK_MONOTONIC, 0); if (fd == -1 || fd > FD_REF_MAX) { - debug("TCP: failed to get timer: %s", strerror(errno)); + flow_dbg(conn, "failed to get timer: %s", + strerror(errno)); if (fd > -1) close(fd); conn->timer = -1; @@ -704,7 +705,8 @@ static void tcp_timer_ctl(const struct ctx *c, struct tcp_tap_conn *conn) conn->timer = fd; if (epoll_ctl(c->epollfd, EPOLL_CTL_ADD, conn->timer, &ev)) { - debug("TCP: failed to add timer: %s", strerror(errno)); + flow_dbg(conn, "failed to add timer: %s", + strerror(errno)); close(conn->timer); conn->timer = -1; return; @@ -724,8 +726,8 @@ static void tcp_timer_ctl(const struct ctx *c, struct tcp_tap_conn *conn) it.it_value.tv_sec = ACT_TIMEOUT; } - debug("TCP: index %u, timer expires in %lu.%03lus", FLOW_IDX(conn), - it.it_value.tv_sec, it.it_value.tv_nsec / 1000 / 1000); + flow_dbg(conn, "timer expires in %lu.%03lus", it.it_value.tv_sec, + it.it_value.tv_nsec / 1000 / 1000); timerfd_settime(conn->timer, 0, &it, NULL); } @@ -746,10 +748,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_tap_conn *conn, return; conn->flags &= flag; - if (flag_index >= 0) { - debug("TCP: index %u: %s dropped", FLOW_IDX(conn), - tcp_flag_str[flag_index]); - } + if (flag_index >= 0) + flow_dbg(conn, "%s dropped", tcp_flag_str[flag_index]); } else { int flag_index = fls(flag); @@ -767,10 +767,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_tap_conn *conn, } conn->flags |= flag; - if (flag_index >= 0) { - debug("TCP: index %u: %s", FLOW_IDX(conn), - tcp_flag_str[flag_index]); - } + if (flag_index >= 0) + flow_dbg(conn, "%s", tcp_flag_str[flag_index]); } if (flag == STALLED || flag == ~STALLED) @@ -817,15 +815,14 @@ static void conn_event_do(const struct ctx *c, struct tcp_tap_conn *conn, if (conn->flags & ACTIVE_CLOSE) new += 5; - if (prev != new) { - debug("TCP: index %u, %s: %s -> %s", FLOW_IDX(conn), - num == -1 ? "CLOSED" : tcp_event_str[num], - prev == -1 ? "CLOSED" : tcp_state_str[prev], - (new == -1 || num == -1) ? "CLOSED" : tcp_state_str[new]); - } else { - debug("TCP: index %u, %s", FLOW_IDX(conn), - num == -1 ? "CLOSED" : tcp_event_str[num]); - } + if (prev != new) + flow_dbg(conn, "%s: %s -> %s", + num == -1 ? "CLOSED" : tcp_event_str[num], + prev == -1 ? "CLOSED" : tcp_state_str[prev], + (new == -1 || num == -1) ? "CLOSED" : tcp_state_str[new]); + else + flow_dbg(conn, "%s", + num == -1 ? "CLOSED" : tcp_event_str[num]); if ((event == TAP_FIN_RCVD) && !(conn->events & SOCK_FIN_RCVD)) conn_flag(c, conn, ACTIVE_CLOSE); @@ -838,7 +835,7 @@ static void conn_event_do(const struct ctx *c, struct tcp_tap_conn *conn, #define conn_event(c, conn, event) \ do { \ - trace("TCP: event at %s:%i", __func__, __LINE__); \ + flow_trace(conn, "event at %s:%i", __func__, __LINE__); \ conn_event_do(c, conn, event); \ } while (0) @@ -1206,9 +1203,8 @@ static void tcp_hash_insert(const struct ctx *c, struct tcp_tap_conn *conn) conn->next_index = tc_hash[b] ? FLOW_IDX(tc_hash[b]) : -1U; tc_hash[b] = conn; - debug("TCP: hash table insert: index %u, sock %i, bucket: %i, next: " - "%p", FLOW_IDX(conn), conn->sock, b, - (void *)conn_at_idx(conn->next_index)); + flow_dbg(conn, "hash table insert: sock %i, bucket: %i, next: %p", + conn->sock, b, (void *)conn_at_idx(conn->next_index)); } /** @@ -1233,9 +1229,9 @@ static void tcp_hash_remove(const struct ctx *c, } } - debug("TCP: hash table remove: index %u, sock %i, bucket: %i, new: %p", - FLOW_IDX(conn), conn->sock, b, - (void *)(prev ? conn_at_idx(prev->next_index) : tc_hash[b])); + flow_dbg(conn, "hash table remove: sock %i, bucket: %i, new: %p", + conn->sock, b, + (void *)(prev ? conn_at_idx(prev->next_index) : tc_hash[b])); } /** @@ -1318,8 +1314,7 @@ static void tcp_conn_destroy(struct ctx *c, union flow *flow) static void tcp_rst_do(struct ctx *c, struct tcp_tap_conn *conn); #define tcp_rst(c, conn) \ do { \ - debug("TCP: index %u, reset at %s:%i", FLOW_IDX(conn), \ - __func__, __LINE__); \ + flow_dbg((conn), "TCP reset at %s:%i", __func__, __LINE__); \ tcp_rst_do(c, conn); \ } while (0) @@ -1997,7 +1992,7 @@ static void tcp_conn_from_tap(struct ctx *c, mss = tcp_conn_tap_mss(conn, opts, optlen); if (setsockopt(s, SOL_TCP, TCP_MAXSEG, &mss, sizeof(mss))) - trace("TCP: failed to set TCP_MAXSEG on socket %i", s); + flow_trace(conn, "failed to set TCP_MAXSEG on socket %i", s); MSS_SET(conn, mss); tcp_get_tap_ws(conn, opts, optlen); @@ -2158,8 +2153,8 @@ static int tcp_data_from_sock(struct ctx *c, struct tcp_tap_conn *conn) if (SEQ_LT(already_sent, 0)) { /* RFC 761, section 2.1. */ - trace("TCP: ACK sequence gap: ACK for %u, sent: %u", - conn->seq_ack_from_tap, conn->seq_to_tap); + flow_trace(conn, "ACK sequence gap: ACK for %u, sent: %u", + conn->seq_ack_from_tap, conn->seq_to_tap); conn->seq_to_tap = conn->seq_ack_from_tap; already_sent = 0; } @@ -2391,8 +2386,9 @@ static int tcp_data_from_tap(struct ctx *c, struct tcp_tap_conn *conn, tcp_tap_window_update(conn, max_ack_seq_wnd); if (retr) { - trace("TCP: fast re-transmit, ACK: %u, previous sequence: %u", - max_ack_seq, conn->seq_to_tap); + flow_trace(conn, + "fast re-transmit, ACK: %u, previous sequence: %u", + max_ack_seq, conn->seq_to_tap); conn->seq_ack_from_tap = max_ack_seq; conn->seq_to_tap = max_ack_seq; tcp_data_from_sock(c, conn); @@ -2541,8 +2537,7 @@ int tcp_tap_handler(struct ctx *c, uint8_t pif, int af, return 1; } - trace("TCP: packet length %zu from tap for index %u", - len, FLOW_IDX(conn)); + flow_trace(conn, "packet length %zu from tap", len); if (th->rst) { conn_event(c, conn, CLOSED); @@ -2782,17 +2777,16 @@ void tcp_timer_handler(struct ctx *c, union epoll_ref ref) tcp_timer_ctl(c, conn); } else if (conn->flags & ACK_FROM_TAP_DUE) { if (!(conn->events & ESTABLISHED)) { - debug("TCP: index %u, handshake timeout", FLOW_IDX(conn)); + flow_dbg(conn, "handshake timeout"); tcp_rst(c, conn); } else if (CONN_HAS(conn, SOCK_FIN_SENT | TAP_FIN_ACKED)) { - debug("TCP: index %u, FIN timeout", FLOW_IDX(conn)); + flow_dbg(conn, "FIN timeout"); tcp_rst(c, conn); } else if (conn->retrans == TCP_MAX_RETRANS) { - debug("TCP: index %u, retransmissions count exceeded", - FLOW_IDX(conn)); + flow_dbg(conn, "retransmissions count exceeded"); tcp_rst(c, conn); } else { - debug("TCP: index %u, ACK timeout, retry", FLOW_IDX(conn)); + flow_dbg(conn, "ACK timeout, retry"); conn->retrans++; conn->seq_to_tap = conn->seq_ack_from_tap; tcp_data_from_sock(c, conn); @@ -2810,7 +2804,7 @@ void tcp_timer_handler(struct ctx *c, union epoll_ref ref) */ timerfd_settime(conn->timer, 0, &new, &old); if (old.it_value.tv_sec == ACT_TIMEOUT) { - debug("TCP: index %u, activity timeout", FLOW_IDX(conn)); + flow_dbg(conn, "activity timeout"); tcp_rst(c, conn); } } diff --git a/tcp_splice.c b/tcp_splice.c index a1c32a0..cd0fc70 100644 --- a/tcp_splice.c +++ b/tcp_splice.c @@ -139,8 +139,7 @@ static int tcp_splice_epoll_ctl(const struct ctx *c, if (epoll_ctl(c->epollfd, m, conn->s[0], &ev[0]) || epoll_ctl(c->epollfd, m, conn->s[1], &ev[1])) { int ret = -errno; - err("TCP (spliced): index %u, ERROR on epoll_ctl(): %s", - FLOW_IDX(conn), strerror(errno)); + flow_err(conn, "ERROR on epoll_ctl(): %s", strerror(errno)); return ret; } @@ -165,10 +164,9 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn, return; conn->flags &= flag; - if (flag_index >= 0) { - debug("TCP (spliced): index %u: %s dropped", FLOW_IDX(conn), - tcp_splice_flag_str[flag_index]); - } + if (flag_index >= 0) + flow_dbg(conn, "%s dropped", + tcp_splice_flag_str[flag_index]); } else { int flag_index = fls(flag); @@ -176,10 +174,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn, return; conn->flags |= flag; - if (flag_index >= 0) { - debug("TCP (spliced): index %u: %s", FLOW_IDX(conn), - tcp_splice_flag_str[flag_index]); - } + if (flag_index >= 0) + flow_dbg(conn, "%s", tcp_splice_flag_str[flag_index]); } if (flag == CLOSING) { @@ -190,8 +186,7 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn, #define conn_flag(c, conn, flag) \ do { \ - trace("TCP (spliced): flag at %s:%i", \ - __func__, __LINE__); \ + flow_trace(conn, "flag at %s:%i", __func__, __LINE__); \ conn_flag_do(c, conn, flag); \ } while (0) @@ -211,10 +206,8 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn, return; conn->events &= event; - if (flag_index >= 0) { - debug("TCP (spliced): index %u, ~%s", FLOW_IDX(conn), - tcp_splice_event_str[flag_index]); - } + if (flag_index >= 0) + flow_dbg(conn, "~%s", tcp_splice_event_str[flag_index]); } else { int flag_index = fls(event); @@ -222,10 +215,8 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn, return; conn->events |= event; - if (flag_index >= 0) { - debug("TCP (spliced): index %u, %s", FLOW_IDX(conn), - tcp_splice_event_str[flag_index]); - } + if (flag_index >= 0) + flow_dbg(conn, "%s", tcp_splice_event_str[flag_index]); } if (tcp_splice_epoll_ctl(c, conn)) @@ -234,8 +225,7 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn, #define conn_event(c, conn, event) \ do { \ - trace("TCP (spliced): event at %s:%i", \ - __func__, __LINE__); \ + flow_trace(conn, "event at %s:%i",__func__, __LINE__); \ conn_event_do(c, conn, event); \ } while (0) @@ -281,7 +271,7 @@ void tcp_splice_destroy(struct ctx *c, union flow *flow) conn->events = SPLICE_CLOSED; conn->flags = 0; - debug("TCP (spliced): index %u, CLOSED", FLOW_IDX(conn)); + flow_dbg(conn, "CLOSED"); flow_table_compact(c, flow); } @@ -314,16 +304,17 @@ static int tcp_splice_connect_finish(const struct ctx *c, if (conn->pipe[side][0] < 0) { if (pipe2(conn->pipe[side], O_NONBLOCK | O_CLOEXEC)) { - err("TCP (spliced): cannot create %d->%d pipe: %s", - side, !side, strerror(errno)); + flow_err(conn, "cannot create %d->%d pipe: %s", + side, !side, strerror(errno)); conn_flag(c, conn, CLOSING); return -EIO; } if (fcntl(conn->pipe[side][0], F_SETPIPE_SZ, c->tcp.pipe_size)) { - trace("TCP (spliced): cannot set %d->%d pipe size to %zu", - side, !side, c->tcp.pipe_size); + flow_trace(conn, + "cannot set %d->%d pipe size to %zu", + side, !side, c->tcp.pipe_size); } } } @@ -363,8 +354,8 @@ static int tcp_splice_connect(const struct ctx *c, struct tcp_splice_conn *conn, if (setsockopt(conn->s[1], SOL_TCP, TCP_QUICKACK, &((int){ 1 }), sizeof(int))) { - trace("TCP (spliced): failed to set TCP_QUICKACK on socket %i", - conn->s[1]); + flow_trace(conn, "failed to set TCP_QUICKACK on socket %i", + conn->s[1]); } if (CONN_V6(conn)) { @@ -475,7 +466,7 @@ bool tcp_splice_conn_from_sock(const struct ctx *c, } if (setsockopt(s, SOL_TCP, TCP_QUICKACK, &((int){ 1 }), sizeof(int))) - trace("TCP (spliced): failed to set TCP_QUICKACK on %i", s); + flow_trace(conn, "failed to set TCP_QUICKACK on %i", s); conn->f.type = FLOW_TCP_SPLICE; conn->s[0] = s; @@ -555,7 +546,7 @@ retry: readlen = splice(conn->s[fromside], NULL, conn->pipe[fromside][1], NULL, c->tcp.pipe_size, SPLICE_F_MOVE | SPLICE_F_NONBLOCK); - trace("TCP (spliced): %zi from read-side call", readlen); + flow_trace(conn, "%zi from read-side call", readlen); if (readlen < 0) { if (errno == EINTR) goto retry; @@ -581,8 +572,8 @@ eintr: written = splice(conn->pipe[fromside][0], NULL, conn->s[!fromside], NULL, to_write, SPLICE_F_MOVE | more | SPLICE_F_NONBLOCK); - trace("TCP (spliced): %zi from write-side call (passed %zi)", - written, to_write); + flow_trace(conn, "%zi from write-side call (passed %zi)", + written, to_write); /* Most common case: skip updating counters. */ if (readlen > 0 && readlen == written) { @@ -794,8 +785,8 @@ void tcp_splice_timer(struct ctx *c, union flow *flow) if ((conn->flags & set) && !(conn->flags & act)) { if (setsockopt(conn->s[side], SOL_SOCKET, SO_RCVLOWAT, &((int){ 1 }), sizeof(int))) { - trace("TCP (spliced): can't set SO_RCVLOWAT on " - "%i", conn->s[side]); + flow_trace(conn, "can't set SO_RCVLOWAT on %d", + conn->s[side]); } conn_flag(c, conn, ~set); } -- cgit v1.2.3