From: Viktor Dukhovni <postfix-users@dukhovni.org>
Date: Wed, 13 May 2020 19:53:36 +0000 (-0400)
Subject: New TLS loglevel "io" logs status of TLS I/O operations
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=9a414aa42abe65a65ba382ec7832b3428a84907d;p=thirdparty%2Fpostfix.git

New TLS loglevel "io" logs status of TLS I/O operations

To debug I/O issues:

        # Just like level 1, but with I/O status logging
        smtp_tls_loglevel = summary,io
        smtpd_tls_loglevel = summary,io
---

diff --git a/postfix/src/tls/tls.h b/postfix/src/tls/tls.h
index 2a8cc1199..760231c52 100644
--- a/postfix/src/tls/tls.h
+++ b/postfix/src/tls/tls.h
@@ -329,6 +329,7 @@ extern int tls_log_mask(const char *, const char *);
 #define TLS_LOG_DEBUG			(1<<7)
 #define TLS_LOG_TLSPKTS			(1<<8)
 #define TLS_LOG_ALLPKTS			(1<<9)
+#define TLS_LOG_IO			(1<<10)
 
  /*
   * Client and Server application contexts
diff --git a/postfix/src/tls/tls_bio_ops.c b/postfix/src/tls/tls_bio_ops.c
index 1f4ec41f1..52b5d714d 100644
--- a/postfix/src/tls/tls_bio_ops.c
+++ b/postfix/src/tls/tls_bio_ops.c
@@ -186,6 +186,8 @@ int     tls_bio(int fd, int timeout, TLS_SESS_STATE *TLScontext,
 	if (enable_deadline) {
 	    GETTIMEOFDAY(&time_deadline);
 	    time_deadline.tv_sec += timeout;
+            if (TLScontext->log_mask & TLS_LOG_IO)
+                msg_info("%s: enabling deadline timer: %d", myname, timeout);
 	}
     }
 
@@ -204,6 +206,9 @@ int     tls_bio(int fd, int timeout, TLS_SESS_STATE *TLScontext,
 	    msg_panic("%s: nothing to do here", myname);
 	err = SSL_get_error(TLScontext->con, status);
 
+        if (TLScontext->log_mask & TLS_LOG_IO)
+            msg_info("%s: SSL_get_error(%d) = %d", myname, status, err);
+
 	/*
 	 * Correspondence between SSL_ERROR_* error codes and tls_bio_(read,
 	 * write, accept, connect, shutdown) return values (for brevity:
@@ -240,15 +245,21 @@ int     tls_bio(int fd, int timeout, TLS_SESS_STATE *TLScontext,
 		GETTIMEOFDAY(&time_now);
 		timersub(&time_deadline, &time_now, &time_left);
 		timeout = time_left.tv_sec + (time_left.tv_usec > 0);
+                if (TLScontext->log_mask & TLS_LOG_IO)
+                    msg_info("%s: remaining deadline timer: %d", myname, timeout);
 		if (timeout <= 0) {
 		    errno = ETIMEDOUT;
 		    return (-1);
 		}
 	    }
 	    if (err == SSL_ERROR_WANT_WRITE) {
+                if (TLScontext->log_mask & TLS_LOG_IO)
+                    msg_info("%s: waiting for writable socket", myname);
 		if (write_wait(fd, timeout) < 0)
 		    return (-1);		/* timeout error */
 	    } else {
+                if (TLScontext->log_mask & TLS_LOG_IO)
+                    msg_info("%s: waiting for readable socket", myname);
 		if (read_wait(fd, timeout) < 0)
 		    return (-1);		/* timeout error */
 	    }
@@ -273,14 +284,25 @@ int     tls_bio(int fd, int timeout, TLS_SESS_STATE *TLScontext,
 	     * need to have ad-hoc code like this.
 	     */
 	case SSL_ERROR_SSL:
+            if (TLScontext->log_mask & TLS_LOG_IO)
+                msg_info("%s: TLS layer error", myname);
 	    if (rfunc || wfunc)
 		tls_print_errors();
-	    /* FALLTHROUGH */
+	    errno = 0;				/* avoid bogus warnings */
+	    return (status);
 	case SSL_ERROR_ZERO_RETURN:
+            if (TLScontext->log_mask & TLS_LOG_IO)
+                msg_info("%s: TLS layer EOF", myname);
+	    errno = 0;				/* avoid bogus warnings */
+	    return (status);
 	case SSL_ERROR_NONE:
+            if (TLScontext->log_mask & TLS_LOG_IO)
+                msg_info("%s: TLS success", myname);
 	    errno = 0;				/* avoid bogus warnings */
-	    /* FALLTHROUGH */
+	    return (status);
 	case SSL_ERROR_SYSCALL:
+            if (TLScontext->log_mask & TLS_LOG_IO)
+                msg_info("%s: Socket layer error: %m", myname);
 	    return (status);
 	}
     }
diff --git a/postfix/src/tls/tls_misc.c b/postfix/src/tls/tls_misc.c
index 527233dfe..6c3c4a8c3 100644
--- a/postfix/src/tls/tls_misc.c
+++ b/postfix/src/tls/tls_misc.c
@@ -522,6 +522,7 @@ static const NAME_MASK tls_log_table[] = {
     "ssl-debug", TLS_LOG_DEBUG,		/* SSL library debug/verbose */
     "ssl-handshake-packet-dump", TLS_LOG_TLSPKTS,
     "ssl-session-packet-dump", TLS_LOG_TLSPKTS | TLS_LOG_ALLPKTS,
+    "io", TLS_LOG_IO,
     0, 0,
 };