Skip to content

Enhance logging (debug level) of net and tls messages: log sock more often #1766

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
michaelortmann wants to merge 4 commits into
base: develop
Choose a base branch
from
+40 −37
Open

Enhance logging (debug level) of net and tls messages: log sock more often #1766

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
5393c69
Enhance net and tls logging, log sock
michaelortmann Feb 4, 2025
3dc1931
More and add debug6()
michaelortmann Feb 4, 2025
d067a11
Merge remote-tracking branch 'upstream/develop' into net.tls.log.sock
michaelortmann Dec 2, 2025
8f1ec62
Merge remote-tracking branch 'upstream/develop' into net.tls.log.sock
michaelortmann Dec 25, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 7 additions & 6 deletions src/eggdrop.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand Down
37 changes: 19 additions & 18 deletions src/net.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -550,11 +550,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;
}
Expand Down Expand Up @@ -591,8 +591,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;
}
Expand Down Expand Up @@ -957,7 +957,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;
Expand All @@ -978,20 +978,21 @@ 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 {
long err2 = ERR_get_error();
debug3("net: sockread(): SSL_read() error = %s (%i) (%li)",
ERR_error_string(err2, 0), err, err2);
debug4("net: sockread(): SSL_read() sock %d error = %s (%i) (%li)",
slist[i].sock, ERR_error_string(err2, 0), err, err2);
if ((err == SSL_ERROR_SSL) &&
(ERR_GET_REASON(err2) == SSL_R_PEER_DID_NOT_RETURN_A_CERTIFICATE))
putlog(LOG_MISC, "*", "NET: SSL read failed. Peer did not return a certificate, which is mandatory due to ssl-verify settings.");
Expand All @@ -1011,11 +1012,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 */
}
}
Expand Down Expand Up @@ -1483,8 +1484,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 */
Expand All @@ -1502,8 +1503,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.
Expand Down
27 changes: 14 additions & 13 deletions src/tls.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -866,19 +866,19 @@ 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
certificate information. */
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 OPENSSL_VERSION_NUMBER >= 0x30000000L /* 3.0.0 */
if ((cert = SSL_get0_peer_certificate(ssl))) {
Expand Down Expand Up @@ -918,16 +918,16 @@ 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));
if (!strcmp(SSL_alert_type_string(ret), "F") &&
!strcmp(SSL_alert_desc_string(ret), "RO"))
putlog(LOG_MISC, "*", "TLS: Long TLSCiphertext field received, connection failed. Is this really a TLS port?");
} 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) {
Expand All @@ -941,7 +941,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));
Expand All @@ -950,13 +951,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
Expand All @@ -983,7 +984,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;
Expand Down Expand Up @@ -1069,7 +1070,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())) {
Expand Down
Loading