diff options
| -rw-r--r-- | flow.h | 7 | ||||
| -rw-r--r-- | log.h | 19 | ||||
| -rw-r--r-- | passt.c | 2 | ||||
| -rw-r--r-- | tcp_splice.c | 45 | ||||
| -rw-r--r-- | tcp_splice.h | 2 |
5 files changed, 53 insertions, 22 deletions
@@ -311,4 +311,11 @@ void flow_log_details_(const struct flow_common *f, int pri, #define flow_dbg_details(f_) flow_log_details((f_), LOG_DEBUG) #define flow_err_details(f_) flow_log_details((f_), LOG_ERR) +#define flow_dbg_ratelimit(f, now, ...) \ + logmsg_ratelimit(flow_dbg, debug, now, f, __VA_ARGS__) +#define flow_err_ratelimit(f, now, ...) \ + logmsg_ratelimit(flow_err, err, now, f, __VA_ARGS__) +#define flow_perror_ratelimit(f, now, ...) \ + logmsg_ratelimit(flow_perror, err, now, f, __VA_ARGS__) + #endif /* FLOW_H */ @@ -103,9 +103,10 @@ void logmsg_perror(int pri, const char *format, ...) /** * logmsg_ratelimit() - Log a message with rate limiting * @fn: Logging function name (e.g. warn, info, debug) + * @fn_s: Logging function name for suppression messages * @now: Current timestamp */ -#define logmsg_ratelimit(fn, now, ...) \ +#define logmsg_ratelimit(fn, fn_s, now, ...) \ do { \ static unsigned int rl_suppressed_; \ static unsigned int rl_printed_; \ @@ -119,27 +120,27 @@ void logmsg_perror(int pri, const char *format, ...) if (rl_printed_ < LOG_RATELIMIT_BURST) { \ fn(__VA_ARGS__); \ if (rl_suppressed_) { \ - fn("(suppressed %u similar messages)", \ - rl_suppressed_); \ + fn_s("(suppressed %u similar messages)", \ + rl_suppressed_); \ rl_suppressed_ = 0; \ } \ rl_printed_++; \ if (rl_printed_ == LOG_RATELIMIT_BURST) \ - fn("(suppressing further similar" \ - " messages)"); \ + fn_s("(suppressing further similar" \ + " messages)"); \ } else { \ rl_suppressed_++; \ } \ } while (0) #define err_ratelimit(now, ...) \ - logmsg_ratelimit(err, now, __VA_ARGS__) + logmsg_ratelimit(err, err, now, __VA_ARGS__) #define warn_ratelimit(now, ...) \ - logmsg_ratelimit(warn, now, __VA_ARGS__) + logmsg_ratelimit(warn, warn, now, __VA_ARGS__) #define info_ratelimit(now, ...) \ - logmsg_ratelimit(info, now, __VA_ARGS__) + logmsg_ratelimit(info, info, now, __VA_ARGS__) #define debug_ratelimit(now, ...) \ - logmsg_ratelimit(debug, now, __VA_ARGS__) + logmsg_ratelimit(debug, debug, now, __VA_ARGS__) extern int log_file; extern int log_trace; @@ -273,7 +273,7 @@ static void passt_worker(void *opaque, int nfds, struct epoll_event *events) tcp_sock_handler(c, ref, eventmask); break; case EPOLL_TYPE_TCP_SPLICE: - tcp_splice_sock_handler(c, ref, eventmask); + tcp_splice_sock_handler(c, ref, eventmask, &now); break; case EPOLL_TYPE_TCP_LISTEN: tcp_listen_handler(c, ref, &now); diff --git a/tcp_splice.c b/tcp_splice.c index 42ee8ab..915ac11 100644 --- a/tcp_splice.c +++ b/tcp_splice.c @@ -478,11 +478,12 @@ void tcp_splice_conn_from_sock(const struct ctx *c, union flow *flow, int s0) * @c: Execution context * @ref: epoll reference * @events: epoll events bitmap + * @now: Current timestamp * * #syscalls:pasta splice */ void tcp_splice_sock_handler(struct ctx *c, union epoll_ref ref, - uint32_t events) + uint32_t events, const struct timespec *now) { struct tcp_splice_conn *conn = conn_at_sidx(ref.flowside); unsigned evsidei = ref.flowside.sidei, fromsidei; @@ -499,18 +500,25 @@ void tcp_splice_sock_handler(struct ctx *c, union epoll_ref ref, socklen_t sl = sizeof(err); rc = getsockopt(ref.fd, SOL_SOCKET, SO_ERROR, &err, &sl); - if (rc) + if (rc) { flow_perror(conn, "Error retrieving SO_ERROR"); - else - flow_trace(conn, "Error event on socket: %s", - strerror_(err)); - + } else { + flow_dbg_ratelimit(conn, now, + "Error event on %s socket: %s", + pif_name(conn->f.pif[evsidei]), + strerror_(err)); + } goto reset; } if (conn->events == SPLICE_CONNECT) { - if (!(events & EPOLLOUT)) + if (!(events & EPOLLOUT)) { + flow_err_ratelimit( + conn, now, + "Unexpected events 0x%x during connect", + events); goto reset; + } if (tcp_splice_connect_finish(c, conn)) goto reset; } @@ -545,8 +553,12 @@ retry: SPLICE_F_MOVE | SPLICE_F_NONBLOCK); while (readlen < 0 && errno == EINTR); - if (readlen < 0 && errno != EAGAIN) + if (readlen < 0 && errno != EAGAIN) { + flow_perror_ratelimit( + conn, now, "Splicing from %s socket", + pif_name(conn->f.pif[fromsidei])); goto reset; + } flow_trace(conn, "%zi from read-side call", readlen); @@ -569,8 +581,12 @@ retry: SPLICE_F_MOVE | more | SPLICE_F_NONBLOCK); while (written < 0 && errno == EINTR); - if (written < 0 && errno != EAGAIN) + if (written < 0 && errno != EAGAIN) { + flow_perror_ratelimit( + conn, now, "Splicing to %s socket", + pif_name(conn->f.pif[!fromsidei])); goto reset; + } flow_trace(conn, "%zi from write-side call (passed %zi)", written, c->tcp.pipe_size); @@ -627,8 +643,12 @@ retry: flow_foreach_sidei(sidei) { if ((conn->events & FIN_RCVD(sidei)) && !(conn->events & FIN_SENT(!sidei))) { - if (shutdown(conn->s[!sidei], SHUT_WR) < 0) + if (shutdown(conn->s[!sidei], SHUT_WR) < 0) { + flow_perror_ratelimit( + conn, now, "shutdown() on %s", + pif_name(conn->f.pif[!sidei])); goto reset; + } conn_event(conn, FIN_SENT(!sidei)); } } @@ -647,8 +667,11 @@ retry: goto swap; } - if (events & EPOLLHUP) + if (events & EPOLLHUP) { + flow_dbg_ratelimit(conn, now, "Hangup from %s socket", + pif_name(conn->f.pif[evsidei])); goto reset; + } return; diff --git a/tcp_splice.h b/tcp_splice.h index dbfd55d..8a1a1f6 100644 --- a/tcp_splice.h +++ b/tcp_splice.h @@ -12,7 +12,7 @@ struct tcp_splice_conn; union sockaddr_inany; void tcp_splice_sock_handler(struct ctx *c, union epoll_ref ref, - uint32_t events); + uint32_t events, const struct timespec *now); void tcp_splice_conn_from_sock(const struct ctx *c, union flow *flow, int s0); void tcp_splice_init(struct ctx *c); |
