misc: mark session logs with fd

Signed-off-by: He Xian <[email protected]>

src/api_server.c

@@ -64,7 +64,8 @@ ASSERT_SUPER(struct session, struct api_ctx, ss);
 		}                                                              \
 		char caddr[64];                                                \
 		format_sa(caddr, sizeof(caddr), &(ctx)->accepted_sa.sa);       \
-		LOG_F(level, "client `%s': " format, caddr, __VA_ARGS__);      \
+		LOG_F(level, "[%d] %s: " format, (ctx)->accepted_fd, caddr,    \
+		      __VA_ARGS__);                                            \
 	} while (0)
 #define API_CTX_LOG(level, ctx, message)                                       \
 	API_CTX_LOG_F(level, ctx, "%s", message)
@@ -717,9 +718,7 @@ static void api_ctx_stop(struct ev_loop *loop, struct api_ctx *restrict ctx)
 
 static void api_ctx_close(struct ev_loop *loop, struct api_ctx *restrict ctx)
 {
-	API_CTX_LOG_F(
-		VERBOSE, ctx, "close fd=%d state=%d", ctx->accepted_fd,
-		ctx->state);
+	API_CTX_LOG_F(VERBOSE, ctx, "close, state=%d", ctx->state);
 	api_ctx_stop(loop, ctx);
 
 	if (ctx->accepted_fd != -1) {

src/dialer.c

@@ -1347,6 +1347,6 @@ int dialer_get(struct dialer *d)
 
 void dialer_cancel(struct dialer *restrict d, struct ev_loop *loop)
 {
-	LOGV_F("dialer: [%p] cancel", (void *)d);
+	LOGV_F("dialer %p: cancel", (void *)d);
 	dialer_stop(d, loop, false);
 }

src/forward.c

@@ -62,7 +62,8 @@ ASSERT_SUPER(struct session, struct forward_ctx, ss);
 		}                                                              \
 		char caddr[64];                                                \
 		format_sa(caddr, sizeof(caddr), &(ctx)->accepted_sa.sa);       \
-		LOG_F(level, "client %s: " format, caddr, __VA_ARGS__);        \
+		LOG_F(level, "[%d] %s: " format, (ctx)->accepted_fd, caddr,    \
+		      __VA_ARGS__);                                            \
 	} while (0)
 #define FW_CTX_LOG(level, ctx, message) FW_CTX_LOG_F(level, ctx, "%s", message)
 
@@ -100,9 +101,7 @@ forward_ctx_stop(struct ev_loop *loop, struct forward_ctx *restrict ctx)
 static void
 forward_ctx_close(struct ev_loop *loop, struct forward_ctx *restrict ctx)
 {
-	FW_CTX_LOG_F(
-		VERBOSE, ctx, "close fd=%d state=%d", ctx->accepted_fd,
-		ctx->state);
+	FW_CTX_LOG_F(VERBOSE, ctx, "close, state=%d", ctx->state);
 	forward_ctx_stop(loop, ctx);
 
 	if (ctx->accepted_fd != -1) {

src/http_proxy.c

@@ -70,10 +70,11 @@ static int format_status(
 	char caddr[64];
 	format_sa(caddr, sizeof(caddr), &ctx->accepted_sa.sa);
 	if ((ctx)->state != STATE_CONNECT) {
-		return snprintf(s, maxlen, "client %s", caddr);
+		return snprintf(s, maxlen, "[%d] %s", ctx->accepted_fd, caddr);
 	}
 	return snprintf(
-		s, maxlen, "%s -> `%s'", caddr, ctx->parser.msg.req.url);
+		s, maxlen, "[%d] %s -> `%s'", ctx->accepted_fd, caddr,
+		ctx->parser.msg.req.url);
 }
 
 #define HTTP_CTX_LOG_F(level, ctx, format, ...)                                \
@@ -130,8 +131,7 @@ static void http_ctx_stop(struct ev_loop *loop, struct http_ctx *restrict ctx)
 static void http_ctx_close(struct ev_loop *loop, struct http_ctx *restrict ctx)
 {
 	HTTP_CTX_LOG_F(
-		VERBOSE, ctx, "close fd=%d state=%d", ctx->accepted_fd,
-		ctx->state);
+		VERBOSE, ctx, "close state=%d", ctx->accepted_fd, ctx->state);
 	http_ctx_stop(loop, ctx);
 
 	if (ctx->accepted_fd != -1) {
@@ -234,8 +234,8 @@ static bool req_connect(
 {
 	const char *addr_str = ctx->parser.msg.req.url;
 	HTTP_CTX_LOG_F(
-		VERBOSE, ctx, "http: CONNECT `%s' username=`%s'", addr_str,
-		username);
+		VERBOSE, ctx, "http: username=%s CONNECT `%s'", username,
+		addr_str);
 #if WITH_RULESET
 	struct ruleset *restrict r = G.ruleset;
 	if (r != NULL) {
@@ -402,8 +402,7 @@ static void send_cb(struct ev_loop *loop, struct ev_io *watcher, int revents)
 	size_t len = ctx->parser.wbuf.len - ctx->parser.wpos;
 	int err = socket_send(fd, buf, &len);
 	if (err != 0) {
-		HTTP_CTX_LOG_F(
-			WARNING, ctx, "send: fd=%d %s", fd, strerror(err));
+		HTTP_CTX_LOG_F(WARNING, ctx, "send: %s", fd, strerror(err));
 		http_ctx_close(loop, ctx);
 		return;
 	}
@@ -418,9 +417,7 @@ static void send_cb(struct ev_loop *loop, struct ev_io *watcher, int revents)
 		len = cbuf->len - ctx->parser.cpos;
 		err = socket_send(watcher->fd, buf, &len);
 		if (err != 0) {
-			HTTP_CTX_LOG_F(
-				WARNING, ctx, "send: fd=%d %s", fd,
-				strerror(err));
+			HTTP_CTX_LOG_F(WARNING, ctx, "send: %s", strerror(err));
 			http_ctx_close(loop, ctx);
 			return;
 		}

src/resolver.c

@@ -54,7 +54,7 @@ struct resolve_query {
 static void
 resolve_finish(struct resolve_query *restrict q, struct ev_loop *loop)
 {
-	LOGV_F("resolve: [%p] finished ok=%d", q, q->ok);
+	LOGV_F("resolve %p: finished ok=%d", q, q->ok);
 	if (q->done_cb.func == NULL) { /* cancelled */
 		free(q);
 		return;
@@ -344,7 +344,7 @@ start_cb(struct ev_loop *loop, struct ev_watcher *watcher, int revents)
 {
 	CHECK_REVENTS(revents, EV_CUSTOM);
 	struct resolve_query *restrict q = watcher->data;
-	LOGV_F("resolve: [%p] start name=`%s' service=%s pf=%d", (void *)q,
+	LOGV_F("resolve %p: start name=`%s' service=%s pf=%d", (void *)q,
 	       q->name, q->service, q->family);
 	struct resolver *restrict r = q->resolver;
 	r->stats.num_query++;
@@ -404,7 +404,7 @@ struct resolve_query *resolve_do(
 
 void resolve_cancel(struct resolve_query *q)
 {
-	LOGV_F("resolve: [%p] cancel", q);
+	LOGV_F("resolve %p: cancel", q);
 	q->done_cb = (struct resolve_cb){
 		.func = NULL,
 		.data = NULL,

src/server.c

@@ -72,8 +72,8 @@ static void accept_cb(struct ev_loop *loop, struct ev_io *watcher, int revents)
 		if (LOGLEVEL(VERBOSE)) {
 			char addr_str[64];
 			format_sa(addr_str, sizeof(addr_str), &addr.sa);
-			LOG_F(VERBOSE, "accept `%s': fd=%d listener=%d",
-			      addr_str, fd, watcher->fd);
+			LOG_F(VERBOSE, "accept from listener %d: [%d] %s",
+			      watcher->fd, fd, addr_str);
 		}
 		if (is_startup_limited(s)) {
 			CLOSE_FD(fd);

src/socks.c

@@ -84,11 +84,12 @@ static int format_status(
 	char caddr[64];
 	format_sa(caddr, sizeof(caddr), &ctx->accepted_sa.sa);
 	if ((ctx)->state != STATE_CONNECT) {
-		return snprintf(s, maxlen, "client %s", caddr);
+		return snprintf(s, maxlen, "[%d] %s", ctx->accepted_fd, caddr);
 	}
 	char saddr[64];
-	dialaddr_format(saddr, sizeof(saddr), &(ctx)->addr);
-	return snprintf(s, maxlen, "%s -> `%s'", caddr, saddr);
+	dialaddr_format(saddr, sizeof(saddr), &ctx->addr);
+	return snprintf(
+		s, maxlen, "[%d] %s -> `%s'", ctx->accepted_fd, caddr, saddr);
 }
 
 #define SOCKS_CTX_LOG_F(level, ctx, format, ...)                               \
@@ -147,9 +148,7 @@ socks_ctx_stop(struct ev_loop *restrict loop, struct socks_ctx *restrict ctx)
 static void
 socks_ctx_close(struct ev_loop *restrict loop, struct socks_ctx *restrict ctx)
 {
-	SOCKS_CTX_LOG_F(
-		VERBOSE, ctx, "close fd=%d state=%d", ctx->accepted_fd,
-		ctx->state);
+	SOCKS_CTX_LOG_F(VERBOSE, ctx, "close, state=%d", ctx->state);
 	socks_ctx_stop(loop, ctx);
 
 	if (ctx->accepted_fd != -1) {
@@ -208,17 +207,15 @@ static bool
 send_rsp(struct socks_ctx *restrict ctx, const void *buf, const size_t len)
 {
 	const int fd = ctx->accepted_fd;
-	LOG_BIN_F(VERYVERBOSE, buf, len, "send_rsp: fd=%d %zu bytes", fd, len);
+	LOG_BIN_F(VERYVERBOSE, buf, len, "[%d] send_rsp: %zu bytes", fd, len);
 	const ssize_t nsend = send(fd, buf, len, 0);
 	if (nsend < 0) {
-		SOCKS_CTX_LOG_F(
-			WARNING, ctx, "send: fd=%d %s", fd, strerror(errno));
+		SOCKS_CTX_LOG_F(WARNING, ctx, "send: %s", strerror(errno));
 		return false;
 	}
 	if ((size_t)nsend != len) {
 		SOCKS_CTX_LOG_F(
-			WARNING, ctx, "send: fd=%d %zu < %zu", fd,
-			(size_t)nsend, len);
+			WARNING, ctx, "send: %zu < %zu", (size_t)nsend, len);
 		return false;
 	}
 	return true;
@@ -735,19 +732,18 @@ static int socks_recv(struct socks_ctx *restrict ctx, const int fd)
 		if (IS_TRANSIENT_ERROR(err)) {
 			return 1;
 		}
-		SOCKS_CTX_LOG_F(
-			WARNING, ctx, "recv: fd=%d %s", fd, strerror(err));
+		SOCKS_CTX_LOG_F(WARNING, ctx, "recv: %s", strerror(err));
 		return -1;
 	}
 	if (nrecv == 0) {
 		/* connection is not established yet, we do not expect EOF here */
-		SOCKS_CTX_LOG_F(WARNING, ctx, "recv: fd=%d early EOF", fd);
+		SOCKS_CTX_LOG(WARNING, ctx, "recv: early EOF");
 		return -1;
 	}
 	ctx->rbuf.len += (size_t)nrecv;
 	LOG_BIN_F(
 		VERYVERBOSE, ctx->rbuf.data, ctx->rbuf.len,
-		"recv: fd=%d %zu bytes", fd, ctx->rbuf.len);
+		"[%d] recv: %zu bytes", fd, ctx->rbuf.len);
 	const int want = socks_dispatch(ctx);
 	if (want < 0) {
 		return want;
@@ -788,7 +784,8 @@ static struct dialreq *req_connect(struct socks_ctx *restrict ctx)
 	CHECK(len >= 0 && (size_t)len < cap);
 	const char *username = ctx->auth.username;
 	const char *password = ctx->auth.password;
-	SOCKS_CTX_LOG_F(VERBOSE, ctx, "request: `%s' `%s'", request, username);
+	SOCKS_CTX_LOG_F(
+		VERBOSE, ctx, "request: username=%s `%s'", username, request);
 	switch (addr->type) {
 	case ATYP_DOMAIN:
 		return ruleset_resolve(ruleset, request, username, password);