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 2a8cc11999611c249c77233620af721b8791467f..760231c52d1b0bb8d3df04d8c4dcd57c706d0883 100644 (file)
--- 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 1f4ec41f17ea1e704428f5d6a777b991fc04a3b4..52b5d714d083259040992efafd23c6a9f6b9301c 100644 (file)
--- 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 527233dfe00a104b12144978f9652429127cb5f3..6c3c4a8c340de00be109d3525af1107d5e80491a 100644 (file)
--- 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,
 };