From 5393c6903fe822fa8efe5f2635015ea60ede6238 Mon Sep 17 00:00:00 2001 From: Michael Ortmann <41313082+michaelortmann@users.noreply.github.com> Date: Tue, 4 Feb 2025 04:06:30 +0100 Subject: [PATCH 1/2] Enhance net and tls logging, log sock --- src/net.c | 29 +++++++++++++++-------------- src/tls.c | 27 ++++++++++++++------------- 2 files changed, 29 insertions(+), 27 deletions(-) diff --git a/src/net.c b/src/net.c index 42be92b34f..c7bd8b54f8 100644 --- a/src/net.c +++ b/src/net.c @@ -592,8 +592,8 @@ int open_telnet_raw(int sock, sockname_t *addr) if (res == EINPROGRESS) /* Operation now in progress */ return sock; /* This could probably fail somewhere */ if (res == ECONNREFUSED) { /* Connection refused */ - debug2("net: attempted socket connection refused: %s:%i", - iptostr(&addr->addr.sa), get_port_from_addr(addr)); + debug3("net: open_telnet_raw(): sock %d attempted socket connection refused: %s:%i", + sock, iptostr(&addr->addr.sa), get_port_from_addr(addr)); errno = res; return -4; } @@ -958,7 +958,7 @@ int sockread(char *s, int *len, sock_list *slist, int slistmax, int tclonly) #else else if (!(slist[i].flags & SOCK_STRONGCONN)) { #endif - debug1("net: connect! sock %d", slist[i].sock); + debug1("net: sockread(): sock %d connect!", slist[i].sock); s[0] = 0; *len = 0; return i; @@ -979,19 +979,20 @@ int sockread(char *s, int *len, sock_list *slist, int slistmax, int tclonly) if (!x && (SSL_get_shutdown(slist[i].ssl) == SSL_RECEIVED_SHUTDOWN)) { *len = slist[i].sock; slist[i].flags &= ~SOCK_CONNECT; - debug1("net: SSL_read(): received shutdown sock %i", slist[i].sock); + debug1("net: SSL_read(): sock %d received shutdown", slist[i].sock); return -1; } else if (x < 0) { int err = SSL_get_error(slist[i].ssl, x); if (err == SSL_ERROR_WANT_READ || err == SSL_ERROR_WANT_WRITE) errno = EAGAIN; else if (err == SSL_ERROR_SYSCALL) { - debug0("net: sockread(): SSL_read() SSL_ERROR_SYSCALL"); + debug1("net: sockread(): SSL_read(): sock %d SSL_ERROR_SYSCALL", + slist[i].sock); putlog(LOG_MISC, "*", "NET: SSL read failed. Non-SSL connection?"); } else - debug2("net: sockread(): SSL_read() error = %s (%i)", - ERR_error_string(ERR_get_error(), 0), err); + debug3("net: sockread(): SSL_read(): sock %d error = %s (%i)", + slist[i].sock, ERR_error_string(ERR_get_error(), 0), err); x = -1; } } else @@ -1007,11 +1008,11 @@ int sockread(char *s, int *len, sock_list *slist, int slistmax, int tclonly) * otherwise it will connect. */ *len = slist[i].sock; slist[i].flags &= ~SOCK_CONNECT; - debug1("net: eof!(read) socket %d", slist[i].sock); + debug1("net: sockread(): sock %d eof!(read)", slist[i].sock); return -1; } else { - debug3("sockread EAGAIN: %d %d (%s)", slist[i].sock, errno, - strerror(errno)); + debug3("net: sockread(): sock %d EAGAIN: %d (%s)", slist[i].sock, + errno, strerror(errno)); continue; /* EAGAIN */ } } @@ -1465,8 +1466,8 @@ void dequeue_sockets() #endif ) { /* This detects an EOF during writing */ - debug3("net: eof!(write) socket %d (%s,%d)", socklist[i].sock, - strerror(errno), errno); + debug3("net: dequeue_sockets(): sock %d eof!(write) (%s,%d)", + socklist[i].sock, strerror(errno), errno); socklist[i].flags |= SOCK_EOFD; } else if (x == socklist[i].handler.sock.outbuflen) { /* If the whole buffer was sent, nuke it */ @@ -1484,8 +1485,8 @@ void dequeue_sockets() socklist[i].handler.sock.outbuflen -= x; nfree(p); } else { - debug3("dequeue_sockets(): errno = %d (%s) on %d", errno, - strerror(errno), socklist[i].sock); + debug3("net: dequeue_sockets(): sock %d errno = %d (%s)", + socklist[i].sock, errno, strerror(errno)); } /* All queued data was sent. Call handler if one exists and the * dcc entry wants it. diff --git a/src/tls.c b/src/tls.c index d3af0c6ea0..c4cb1ea3c5 100644 --- a/src/tls.c +++ b/src/tls.c @@ -764,10 +764,10 @@ static void ssl_info(const SSL *ssl, int where, int ret) /* We're doing non-blocking IO, so we check here if the handshake has finished */ + sock = SSL_get_fd(ssl); if (where & SSL_CB_HANDSHAKE_DONE) { /* Callback for completed handshake. Cheaper and more convenient than using H_tls */ - sock = SSL_get_fd(ssl); if (data->cb) data->cb(sock); /* Call TLS binds. We allow scripts to take over or disable displaying of @@ -775,8 +775,8 @@ static void ssl_info(const SSL *ssl, int where, int ret) if (check_tcl_tls(sock)) return; - putlog(data->loglevel, "*", "TLS: handshake successful. Secure connection " - "established."); + putlog(data->loglevel, "*", "TLS: sock %d handshake successful. Secure " + "connection established.", sock); if ((cert = SSL_get_peer_certificate(ssl))) { ssl_showcert(cert, LOG_DEBUG); @@ -811,13 +811,13 @@ static void ssl_info(const SSL *ssl, int where, int ret) } else if (where & SSL_CB_ALERT) { if (strcmp(SSL_alert_type_string(ret), "W") || strcmp(SSL_alert_desc_string(ret), "CN")) { - putlog(data->loglevel, "*", "TLS: alert during %s: %s (%s).", - (where & SSL_CB_READ) ? "read" : "write", + putlog(data->loglevel, "*", "TLS: sock %d alert during %s: %s (%s).", + sock, (where & SSL_CB_READ) ? "read" : "write", SSL_alert_type_string_long(ret), SSL_alert_desc_string_long(ret)); } else { /* Ignore close notify warnings */ - debug1("TLS: Received close notify during %s", + debug2("TLS: sock %d Received close notify during %s", sock, (where & SSL_CB_READ) ? "read" : "write"); } } else if (where & SSL_CB_EXIT) { @@ -831,7 +831,8 @@ static void ssl_info(const SSL *ssl, int where, int ret) /* However we still check <0 as man example does so too */ if (err & (SSL_ERROR_WANT_READ | SSL_ERROR_WANT_WRITE)) { /* Errors to be ignored for non-blocking */ - debug1("TLS: awaiting more %s", (err & SSL_ERROR_WANT_READ) ? "reads" : "writes"); + debug2("TLS: sock %d awaiting more %s", sock, + (err & SSL_ERROR_WANT_READ) ? "reads" : "writes"); } else { putlog(data->loglevel, "*", "TLS: error in: %s.", SSL_state_string_long(ssl)); @@ -840,13 +841,13 @@ static void ssl_info(const SSL *ssl, int where, int ret) } /* Display the state of the engine for debugging purposes */ else if (where == SSL_CB_HANDSHAKE_START) - debug1("TLS: handshake start: %s", SSL_state_string_long(ssl)); + debug2("TLS: sock %d handshake start: %s", sock, SSL_state_string_long(ssl)); else if (where == SSL_CB_CONNECT_LOOP) - debug1("TLS: connect loop: %s", SSL_state_string_long(ssl)); + debug2("TLS: sock %d connect loop: %s", sock, SSL_state_string_long(ssl)); else if (where == SSL_CB_ACCEPT_LOOP) - debug1("TLS: accept loop: %s", SSL_state_string_long(ssl)); + debug2("TLS: sock %d accept loop: %s", sock, SSL_state_string_long(ssl)); else - debug1("TLS: state change: %s", SSL_state_string_long(ssl)); + debug2("TLS: sock %d state change: %s", sock, SSL_state_string_long(ssl)); } /* Switch a socket to SSL communication @@ -873,7 +874,7 @@ int ssl_handshake(int sock, int flags, int verify, int loglevel, char *host, ssl_appdata *data; struct threaddata *td = threaddata(); - debug0("TLS: attempting SSL negotiation..."); + debug1("TLS: sock %d attempting SSL negotiation...", sock); if (!ssl_ctx && ssl_init()) { debug0("TLS: Failed. OpenSSL not initialized properly."); return -1; @@ -959,7 +960,7 @@ int ssl_handshake(int sock, int flags, int verify, int loglevel, char *host, err = SSL_get_error(td->socklist[i].ssl, ret); /* Normal condition for async I/O, similar to EAGAIN */ if (ret > 0 || err == SSL_ERROR_WANT_READ || err == SSL_ERROR_WANT_WRITE) { - debug0("TLS: handshake in progress"); + debug1("TLS: sock %d handshake in progress", sock); return 0; } if ((err = ERR_peek_error())) { From 3dc19319c61974f98d54a049b22fd6721faebe47 Mon Sep 17 00:00:00 2001 From: Michael Ortmann <41313082+michaelortmann@users.noreply.github.com> Date: Tue, 4 Feb 2025 04:32:16 +0100 Subject: [PATCH 2/2] More and add debug6() --- src/eggdrop.h | 13 +++++++------ src/net.c | 8 ++++---- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/src/eggdrop.h b/src/eggdrop.h index 393de019d4..e94dfa10cc 100644 --- a/src/eggdrop.h +++ b/src/eggdrop.h @@ -250,12 +250,13 @@ typedef uint32_t IP; /* Debug logging macros */ -#define debug0(x) putlog(LOG_DEBUG,"*",x) -#define debug1(x,a1) putlog(LOG_DEBUG,"*",x,a1) -#define debug2(x,a1,a2) putlog(LOG_DEBUG,"*",x,a1,a2) -#define debug3(x,a1,a2,a3) putlog(LOG_DEBUG,"*",x,a1,a2,a3) -#define debug4(x,a1,a2,a3,a4) putlog(LOG_DEBUG,"*",x,a1,a2,a3,a4) -#define debug5(x,a1,a2,a3,a4,a5) putlog(LOG_DEBUG,"*",x,a1,a2,a3,a4,a5) +#define debug0(x) putlog(LOG_DEBUG,"*",x) +#define debug1(x,a1) putlog(LOG_DEBUG,"*",x,a1) +#define debug2(x,a1,a2) putlog(LOG_DEBUG,"*",x,a1,a2) +#define debug3(x,a1,a2,a3) putlog(LOG_DEBUG,"*",x,a1,a2,a3) +#define debug4(x,a1,a2,a3,a4) putlog(LOG_DEBUG,"*",x,a1,a2,a3,a4) +#define debug5(x,a1,a2,a3,a4,a5) putlog(LOG_DEBUG,"*",x,a1,a2,a3,a4,a5) +#define debug6(x,a1,a2,a3,a4,a5,a6) putlog(LOG_DEBUG,"*",x,a1,a2,a3,a4,a5,a6) /* These apparently are unsafe without recasting. */ #define egg_isdigit(x) isdigit((int) (unsigned char) (x)) diff --git a/src/net.c b/src/net.c index c7bd8b54f8..5950d03f5c 100644 --- a/src/net.c +++ b/src/net.c @@ -553,11 +553,11 @@ int open_telnet_raw(int sock, sockname_t *addr) for (i = 0; i < dcc_total; i++) if (dcc[i].sock == sock) { /* Got idx from sock ? */ #ifdef TLS - debug5("net: open_telnet_raw(): idx %i host %s ip %s port %i ssl %i", - i, dcc[i].host, iptostr(&addr->addr.sa), dcc[i].port, dcc[i].ssl); + debug6("net: open_telnet_raw(): sock %d idx %i host %s ip %s port %i ssl %i", + sock, i, dcc[i].host, iptostr(&addr->addr.sa), dcc[i].port, dcc[i].ssl); #else - debug4("net: open_telnet_raw(): idx %i host %s ip %s port %i", - i, dcc[i].host, iptostr(&addr->addr.sa), dcc[i].port); + debug5("net: open_telnet_raw(): sock %d idx %i host %s ip %s port %i", + sock, i, dcc[i].host, iptostr(&addr->addr.sa), dcc[i].port); #endif break; }