aboutgitcodebugslistschat
diff options
context:
space:
mode:
-rw-r--r--flow.h7
-rw-r--r--log.h19
-rw-r--r--passt.c2
-rw-r--r--tcp_splice.c45
-rw-r--r--tcp_splice.h2
5 files changed, 53 insertions, 22 deletions
diff --git a/flow.h b/flow.h
index 897c9ea..6c6a926 100644
--- a/flow.h
+++ b/flow.h
@@ -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 */
diff --git a/log.h b/log.h
index c6befe3..69cfb50 100644
--- a/log.h
+++ b/log.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;
diff --git a/passt.c b/passt.c
index bc42ea3..b6fc12d 100644
--- a/passt.c
+++ b/passt.c
@@ -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);