From 5d9365f4f74f7a9c51a50c4c1aab0acfa301524a Mon Sep 17 00:00:00 2001 From: He Xian Date: Sat, 20 Jan 2024 15:49:39 +0800 Subject: [PATCH] event: log packet before encryption Signed-off-by: He Xian --- src/event_pkt.c | 19 ++++++++----------- src/pktqueue.c | 17 +++++++++++++++++ src/session.c | 4 +++- 3 files changed, 28 insertions(+), 12 deletions(-) diff --git a/src/event_pkt.c b/src/event_pkt.c index 0b97ec6..3347374 100644 --- a/src/event_pkt.c +++ b/src/event_pkt.c @@ -18,19 +18,15 @@ #include #include -#define MSG_LOGV(what, msg) \ +#define PKT_LOGV(what, msg) \ do { \ if (!LOGLEVEL(VERBOSE)) { \ break; \ } \ char addr[64]; \ format_sa(&(msg)->addr.sa, addr, sizeof(addr)); \ - LOG_F(VERBOSE, what ": %" PRIu16 " bytes to %s", (msg)->len, \ - addr); \ - FILE *log_fp = slog_file; \ - if (log_fp != NULL) { \ - print_bin(log_fp, " ", (msg)->buf, (msg)->len); \ - } \ + LOG_F(VERBOSE, what ": %" PRIu16 " bytes, addr=%s", \ + (msg)->len, addr); \ } while (0) static void udp_reset(struct server *restrict s) @@ -127,7 +123,7 @@ static size_t pkt_recv(struct server *restrict s, const int fd) msg->len = (size_t)mmsgs[i].msg_len; msg->ts = now; q->mq_recv[q->mq_recv_len++] = msg; - MSG_LOGV("pkt recv", msg); + PKT_LOGV("pkt recv", msg); } /* collect unused frames */ for (size_t i = n; i < nbatch; i++) { @@ -176,7 +172,7 @@ static size_t pkt_recv(struct server *restrict s, const int fd) msg->len = (size_t)nbrecv; msg->ts = now; q->mq_recv[q->mq_recv_len++] = msg; - MSG_LOGV("pkt recv", msg); + PKT_LOGV("pkt recv", msg); s->stats.pkt_rx += nbrecv; nrecv++; navail--; @@ -203,6 +199,7 @@ static size_t pkt_send_drop(struct pktqueue *restrict q) msgframe_delete(q, q->mq_send[i]); } q->mq_send_len = 0; + LOGV_F("pkt send: dropping %zu packets", count); return count; } @@ -265,7 +262,7 @@ static size_t pkt_send(struct server *restrict s, const int fd) for (size_t i = 0; i < n; i++) { struct msgframe *restrict msg = q->mq_send[nsend + i]; nbsend += msg->len; - MSG_LOGV("pkt send", msg); + PKT_LOGV("pkt send", msg); msgframe_delete(q, msg); } nsend += n; @@ -318,7 +315,7 @@ static size_t pkt_send(struct server *restrict s, const int fd) } for (size_t i = 0; i < nsend; i++) { struct msgframe *restrict msg = q->mq_send[i]; - MSG_LOGV("pkt send", msg); + PKT_LOGV("pkt send", msg); msgframe_delete(q, msg); } const size_t remain = count - nsend; diff --git a/src/pktqueue.c b/src/pktqueue.c index 5f8770d..5d5f0cd 100644 --- a/src/pktqueue.c +++ b/src/pktqueue.c @@ -28,6 +28,21 @@ #include #include +#define MSG_LOGV(what, msg) \ + do { \ + if (!LOGLEVEL(VERBOSE)) { \ + break; \ + } \ + char addr[64]; \ + format_sa(&(msg)->addr.sa, addr, sizeof(addr)); \ + LOG_F(VERBOSE, what ": %" PRIu16 " bytes, addr=%s", \ + (msg)->len, addr); \ + FILE *log_fp = slog_file; \ + if (log_fp != NULL) { \ + print_bin(log_fp, " ", (msg)->buf, (msg)->len); \ + } \ + } while (0) + #if WITH_CRYPTO static bool crypto_open_inplace( @@ -88,6 +103,7 @@ static bool crypto_seal_inplace( static void queue_recv(struct server *restrict s, struct msgframe *restrict msg) { + MSG_LOGV("queue_recv", msg); const unsigned char *kcp_packet = msg->buf + msg->off; uint32_t conv = ikcp_getconv(kcp_packet); if (conv == UINT32_C(0)) { @@ -227,6 +243,7 @@ size_t queue_dispatch(struct server *restrict s) bool queue_send(struct server *restrict s, struct msgframe *restrict msg) { struct pktqueue *restrict q = s->pkt.queue; + MSG_LOGV("queue_send", msg); #if WITH_CRYPTO if (q->crypto != NULL) { const size_t cap = MAX_PACKET_SIZE - (size_t)msg->off; diff --git a/src/session.c b/src/session.c index c224936..bc91865 100644 --- a/src/session.c +++ b/src/session.c @@ -621,7 +621,9 @@ ss0_on_connect(struct server *restrict s, struct msgframe *restrict msg) return false; } if (!s->pkt.listened) { - LOGE("rendezvous connect: no server available"); + char addr_str[64]; + format_sa(&msg->addr.sa, addr_str, sizeof(addr_str)); + LOGE_F("failed connecting %s: no server available", addr_str); return true; } if (LOGLEVEL(INFO)) {