Browse Source

SOCKET сообщения жизненного цикла: INFO→DEBUG

bbr
Evgeny 4 months ago
parent
commit
23732039de
  1. 16
      lib/tcp_io.c
  2. 30
      src/proxy/tcp_proxy_server.c

16
lib/tcp_io.c

@ -91,14 +91,14 @@ struct tcp_conn* tcp_conn_create(
if (getpeername(sock, (struct sockaddr*)&addr, &alen) == 0) tc->connected = 1;
}
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_conn_create: fd=%d entry=%zu chunk=%zu hw=%d lw=%d connected=%d",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_conn_create: fd=%d entry=%zu chunk=%zu hw=%d lw=%d connected=%d",
(int)sock, entry_data_size, write_chunk_size, read_high_water, read_low_water, tc->connected);
return tc;
}
void tcp_conn_destroy(struct tcp_conn* tc) {
if (!tc) return;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_conn_destroy: fd=%d connected=%d error=%d fin_remote=%d fin_local=%d closed=%d",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_conn_destroy: fd=%d connected=%d error=%d fin_remote=%d fin_local=%d closed=%d",
(int)tc->sock, tc->connected, tc->error, tc->fin_remote, tc->fin_local, tc->closed);
if (tc->socket_id) {
@ -202,7 +202,7 @@ static void read_cb(socket_t sock, void* arg) {
memory_pool_free(tc->data_pool, buf);
queue_entry_free(e);
tc->fin_remote = 1;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_io: FIN fd=%d", (int)tc->sock);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_io: FIN fd=%d", (int)tc->sock);
uasync_set_socket_read(tc->ua, tc->socket_id, 0);
queue_waiter_cancel(tc->read_queue, &tc->read_waiter);
if (tc->read_queue->count == 0) {
@ -288,14 +288,14 @@ static void write_queue_fetch_cb(struct ll_queue* q, void* arg) {
if (e->len == 0) {
if (!e->dgram) {
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_io: CLOSE fd=%d", (int)tc->sock);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_io: CLOSE fd=%d", (int)tc->sock);
queue_entry_free(e); queue_resume_callback(q);
uasync_remove_socket_t(tc->ua, tc->sock);
socket_close_wrapper(tc->sock);
tc->socket_id = NULL; tc->sock = SOCKET_INVALID; tc->closed = 1;
if (tc->on_closed) tc->on_closed(tc, tc->arg);
} else if (e->dgram == &tcp_fin_sentinel) {
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_io: FIN fd=%d", (int)tc->sock);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_io: FIN fd=%d", (int)tc->sock);
queue_entry_free(e); queue_resume_callback(q);
shutdown(tc->sock, SHUT_WR);
tc->fin_local = 1;
@ -365,7 +365,7 @@ static void write_cb(socket_t sock, void* arg) {
socklen_t len = sizeof(err);
if (getsockopt(tc->sock, SOL_SOCKET, SO_ERROR, &err, &len) == 0 && err == 0) {
tc->connected = 1;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_io: connect ok fd=%d", (int)tc->sock);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_io: connect ok fd=%d", (int)tc->sock);
} else {
DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "tcp_io: connect fail fd=%d err=%d", (int)tc->sock, err);
tcp_conn_handle_error(tc, err ? err : -1);
@ -403,7 +403,7 @@ int tcp_conn_push_fin(struct tcp_conn* tc) {
struct ll_entry* e = queue_entry_new_from_pool(tc->entry_pool);
if (!e) { DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "tcp_io: push_fin entry_pool exhausted fd=%d", (int)tc->sock); return -1; }
e->dgram = (uint8_t*)&tcp_fin_sentinel; e->len = 0;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_io: push_fin fd=%d wq=%d", (int)tc->sock, tc->write_queue->count + 1);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_io: push_fin fd=%d wq=%d", (int)tc->sock, tc->write_queue->count + 1);
queue_data_put(tc->write_queue, e);
return 0;
}
@ -414,7 +414,7 @@ int tcp_conn_push_close(struct tcp_conn* tc) {
struct ll_entry* e = queue_entry_new_from_pool(tc->entry_pool);
if (!e) { DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "tcp_io: push_close entry_pool exhausted fd=%d", (int)tc->sock); return -1; }
e->dgram = NULL; e->len = 0;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "tcp_io: push_close fd=%d wq=%d", (int)tc->sock, tc->write_queue->count + 1);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "tcp_io: push_close fd=%d wq=%d", (int)tc->sock, tc->write_queue->count + 1);
queue_data_put(tc->write_queue, e);
return 0;
}

30
src/proxy/tcp_proxy_server.c

@ -114,16 +114,16 @@ static void on_fin_cb(struct tcp_conn* tc, void* arg) {
if (rc->cli_closed) return;
int pend = write_pending(tc);
if (tc->fin_local) {
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:DST_FIN fd=%d sid=%08x fin_local=%d — both FINs, closing",
(int)tc->sock, rc->stream_id, tc->fin_local);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:DST_FIN fd=%d sid=%08x fin_local=%d — both FINs, closing",
(int)tc->sock, rc->stream_id, tc->fin_local);
send_close(rc); tcp_conn_push_close(tc);
} else if (pend) {
tcp_conn_set_flushed(tc, on_flushed_cb);
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:DST_FIN fd=%d sid=%08x write_pend=%d → deferred",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:DST_FIN fd=%d sid=%08x write_pend=%d → deferred",
(int)tc->sock, rc->stream_id, pend);
} else {
send_fin(rc);
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:DST_FIN fd=%d sid=%08x → relay now",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:DST_FIN fd=%d sid=%08x → relay now",
(int)tc->sock, rc->stream_id);
}
}
@ -132,7 +132,7 @@ static void on_flushed_cb(struct tcp_conn* tc, void* arg) {
struct tcp_proxy_server_conn* rc = (struct tcp_proxy_server_conn*)arg;
if (rc->cli_closed) return;
if (tc->fin_local) {
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:FLUSHED fd=%d sid=%08x fin_local=%d — both FINs, closing",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:FLUSHED fd=%d sid=%08x fin_local=%d — both FINs, closing",
(int)tc->sock, rc->stream_id, tc->fin_local);
send_close(rc); tcp_conn_push_close(tc); return;
}
@ -141,7 +141,7 @@ static void on_flushed_cb(struct tcp_conn* tc, void* arg) {
static void on_closed_cb(struct tcp_conn* tc, void* arg) {
struct tcp_proxy_server_conn* rc = (struct tcp_proxy_server_conn*)arg;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:CLOSED fd=%d sid=%08x — freeing",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:CLOSED fd=%d sid=%08x — freeing",
tc ? (int)tc->sock : -1, rc->stream_id);
tcp_proxy_server_conn_free(rc);
}
@ -168,7 +168,7 @@ static void diag_timer_cb(void* arg) {
getsockopt(tc->sock, SOL_SOCKET, SO_RCVBUF, &rcv_buf, &optlen);
getsockopt(tc->sock, SOL_SOCKET, SO_SNDBUF, &snd_buf, &optlen);
DEBUG_INFO(DEBUG_CATEGORY_SOCKET,
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET,
"SOCK:DIAG fd=%d sid=%08x conn=%d fin=%d "
"rq=%d(%zub) wq=%d(%zub) wbuf=%s "
"ent_f=%d dat_f=%d tcp_rb=%zu tcp_sb=%zu",
@ -208,7 +208,7 @@ static void read_queue_drain_cb(struct ll_queue* q, void* arg) {
if (ret == 0) {
queue_resume_callback(q);
} else {
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:BACKPRESSURE fd=%d sid=%08x — pausing drain",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:BACKPRESSURE fd=%d sid=%08x — pausing drain",
(int)rc->tc->sock, rc->stream_id);
etcp_router_on_send_ready(inst, rc->peer_node_id, ETCP_ID_TCP_PROXY_CLIENT,
&rc->pause_waiter, pause_resume_cb, rc);
@ -235,14 +235,14 @@ static int conn_total(struct tcp_proxy_server_conn* rc) {
void tcp_proxy_server_conn_free(struct tcp_proxy_server_conn* rc) {
if (!rc) return;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:FREE enter rc=%p freed=%d sid=%08x", (void*)rc, rc->freed, rc->stream_id);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:FREE enter rc=%p freed=%d sid=%08x", (void*)rc, rc->freed, rc->stream_id);
if (rc->freed) {
DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "SOCK:FREE double rc=%p — IGNORED", (void*)rc);
return;
}
rc->freed = 1;
int total = conn_total(rc);
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:FREE fd=%d sid=%08x total=%d cli_closed=%d fin=%d error=%d",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:FREE fd=%d sid=%08x total=%d cli_closed=%d fin=%d error=%d",
rc->tc ? (int)rc->tc->sock : -1, rc->stream_id, total, rc->cli_closed, rc->tc ? rc->tc->fin_remote : 0, rc->tc ? rc->tc->error : 0);
if (rc->close_pending && rc->ctx && rc->ctx->inst) {
rc->close_pending = 0;
@ -257,7 +257,7 @@ void tcp_proxy_server_conn_free(struct tcp_proxy_server_conn* rc) {
if (rc->close_timer) { uasync_cancel_timeout(rc->ua, rc->close_timer); rc->close_timer = NULL; }
if (rc->diag_timer) { uasync_cancel_timeout(rc->ua, rc->diag_timer); rc->diag_timer = NULL; }
if (rc->ctx && rc->ctx->inst) etcp_router_cancel_send_ready(rc->ctx->inst, rc->peer_node_id, ETCP_ID_TCP_PROXY_CLIENT, &rc->pause_waiter);
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:FREE u_free rc=%p", (void*)rc);
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:FREE u_free rc=%p", (void*)rc);
u_free(rc);
}
@ -287,7 +287,7 @@ int tcp_proxy_server_handle_connect(struct UTUN_INSTANCE* inst, struct ll_entry*
socket_t sock = socket(AF_INET, SOCK_STREAM, 0);
if (sock == SOCKET_INVALID) { DEBUG_ERROR(DEBUG_CATEGORY_SOCKET, "TCP proxy server: socket() failed"); u_free(rc); queue_dgram_free(entry); queue_entry_free(entry); return -1; }
ctx->conn_count++;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:NEW fd=%d sid=%08x dest=%d.%d.%d.%d:%d total=%d",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:NEW fd=%d sid=%08x dest=%d.%d.%d.%d:%d total=%d",
(int)sock, stream_id, dest_ip[0],dest_ip[1],dest_ip[2],dest_ip[3],ntohs(dest_port), ctx->conn_count);
socket_set_nonblocking(sock);
@ -352,7 +352,7 @@ void tcp_proxy_server_handle_close(struct UTUN_INSTANCE* inst, uint32_t stream_i
struct tcp_proxy_server* ctx = &inst->tcp_proxy_server;
struct tcp_proxy_server_conn* rc = tcp_proxy_server_find_conn(ctx, stream_id);
if (!rc) { DEBUG_WARN(DEBUG_CATEGORY_SOCKET, "TCP proxy server: CLOSE sid=%08x — no conn", stream_id); return; }
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:CLOSE_RECV fd=%d sid=%08x total=%d fin=%d write_pend=%d",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:CLOSE_RECV fd=%d sid=%08x total=%d fin=%d write_pend=%d",
rc->tc ? (int)rc->tc->sock : -1, stream_id, conn_total(rc),
rc->tc ? rc->tc->fin_remote : 0, rc->tc ? write_pending(rc->tc) : 0);
rc->cli_closed = 1;
@ -374,7 +374,7 @@ void tcp_proxy_server_handle_error(struct UTUN_INSTANCE* inst, uint32_t stream_i
struct tcp_proxy_server* ctx = &inst->tcp_proxy_server;
struct tcp_proxy_server_conn* rc = tcp_proxy_server_find_conn(ctx, stream_id);
if (!rc) { DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "TCP proxy server: ERROR sid=%08x — no conn", stream_id); return; }
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:ERROR_RECV fd=%d sid=%08x total=%d fin=%d write_pend=%d",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:ERROR_RECV fd=%d sid=%08x total=%d fin=%d write_pend=%d",
rc->tc ? (int)rc->tc->sock : -1, stream_id, conn_total(rc),
rc->tc ? rc->tc->fin_remote : 0, rc->tc ? write_pending(rc->tc) : 0);
tcp_proxy_server_handle_close(inst, stream_id);
@ -385,7 +385,7 @@ void tcp_proxy_server_handle_fin(struct UTUN_INSTANCE* inst, uint32_t stream_id)
struct tcp_proxy_server* ctx = &inst->tcp_proxy_server;
struct tcp_proxy_server_conn* rc = tcp_proxy_server_find_conn(ctx, stream_id);
if (!rc || !rc->tc || !rc->tc->connected) return;
DEBUG_INFO(DEBUG_CATEGORY_SOCKET, "SOCK:FIN_RECV fd=%d sid=%08x — pushing FIN to wq",
DEBUG_DEBUG(DEBUG_CATEGORY_SOCKET, "SOCK:FIN_RECV fd=%d sid=%08x — pushing FIN to wq",
(int)rc->tc->sock, stream_id);
tcp_conn_push_fin(rc->tc);
}

Loading…
Cancel
Save