Improve fr_tls_log_io_error

It now prints out the string identifier for the error, and produces debugging output for none fatal errors.

diff --git a/src/lib/tls/log.c b/src/lib/tls/log.c
index ff49a41d916a5254983d43aa2690807c2ebb209a..049ece4d17e102db1c73594f3296462cd65bce00 100644 (file)
--- a/src/lib/tls/log.c
+++ b/src/lib/tls/log.c
@@ -214,27 +214,35 @@ DIAG_ON(format-nonliteral)
  *   - SSL_write
  *
  * @param request      The current request (may be NULL).
- * @param session      The current tls_session.
- * @param ret          from the I/O operation.
- * @param msg          Error message describing the operation being attempted.
+ * @param err          returned from SSL_get_error().
+ * @param fmt          Error message describing the operation being attempted.
  * @param ...          Arguments for msg.
  * @return
  *     - 0 TLS session may still be viable.
  *     - -1 TLS session cannot continue.
  */
-int fr_tls_log_io_error(request_t *request, fr_tls_session_t *session, int ret, char const *msg, ...)
+int fr_tls_log_io_error(request_t *request, int err, char const *fmt, ...)
 {
-       int     error;
-       va_list ap;
+       static fr_table_num_ordered_t const ssl_io_error_table[] = {
+               { L("SSL_ERROR_NONE"),                  SSL_ERROR_NONE                  },
+               { L("SSL_ERROR_ZERO_RETURN"),           SSL_ERROR_ZERO_RETURN           },
+               { L("SSL_ERROR_WANT_READ"),             SSL_ERROR_WANT_READ             },
+               { L("SSL_ERROR_WANT_WRITE"),            SSL_ERROR_WANT_WRITE            },
+               { L("SSL_ERROR_WANT_CONNECT"),          SSL_ERROR_WANT_CONNECT          },
+               { L("SSL_ERROR_WANT_ACCEPT"),           SSL_ERROR_WANT_ACCEPT           },
+               { L("SSL_ERROR_WANT_X509_LOOKUP"),      SSL_ERROR_WANT_X509_LOOKUP      },
+               { L("SSL_ERROR_WANT_ASYNC"),            SSL_ERROR_WANT_ASYNC            },
+               { L("SSL_ERROR_WANT_ASYNC_JOB"),        SSL_ERROR_WANT_ASYNC_JOB        },
+               { L("SSL_ERROR_WANT_CLIENT_HELLO_CB"),  SSL_ERROR_WANT_CLIENT_HELLO_CB  },
+               { L("SSL_ERROR_SYSCALL"),               SSL_ERROR_SYSCALL               },
+               { L("SSL_ERROR_SSL"),                   SSL_ERROR_SSL                   }
+       };
+       static size_t ssl_io_error_table_len = NUM_ELEMENTS(ssl_io_error_table);
 
-       if (ERR_peek_error()) {
-               va_start(ap, msg);
-               fr_tls_log_error_va(request, msg, ap);
-               va_end(ap);
-       }
+       va_list ap;
+       char *msg = NULL;
 
-       error = SSL_get_error(session->ssl, ret);
-       switch (error) {
+       switch (err) {
        /*
         *      These seem to be harmless and already "dealt
         *      with" by our non-blocking environment. NB:
@@ -252,6 +260,15 @@ int fr_tls_log_io_error(request_t *request, fr_tls_session_t *session, int ret,
        case SSL_ERROR_WANT_WRITE:
        case SSL_ERROR_WANT_X509_LOOKUP:
        case SSL_ERROR_ZERO_RETURN:
+               if (DEBUG_ENABLED2 || RDEBUG_ENABLED2) {
+                       va_start(ap, fmt);
+                       msg = fr_vasprintf(NULL, fmt, ap);
+                       va_end(ap);
+
+                       ROPTIONAL(RDEBUG2, DEBUG2, "%s - %s (%i)",
+                                 msg, fr_table_str_by_value(ssl_io_error_table, err, "<UNKNOWN>"), err);
+                       talloc_free(msg);
+               }
                break;
 
        /*
@@ -260,11 +277,24 @@ int fr_tls_log_io_error(request_t *request, fr_tls_session_t *session, int ret,
         *      being regarded as "dead".
         */
        case SSL_ERROR_SYSCALL:
-               ROPTIONAL(REDEBUG, ERROR, "System call (I/O) error (%i)", ret);
+               va_start(ap, fmt);
+               msg = fr_vasprintf(NULL, fmt, ap);
+               va_end(ap);
+
+               ROPTIONAL(REDEBUG, ERROR, "%s - System call (I/O) error - %s (%i)",
+                         msg, fr_table_str_by_value(ssl_io_error_table, err, "<UNKNOWN>"), err);
+
+               talloc_free(msg);
                return -1;
 
+       /*
+        *      Docs say a more verbose error is available
+        *      in the normal error stack.
+        */
        case SSL_ERROR_SSL:
-               ROPTIONAL(REDEBUG, ERROR, "TLS protocol error (%i)", ret);
+               va_start(ap, fmt);
+               fr_tls_log_error_va(request, fmt, ap);
+               va_end(ap);
                return -1;
 
        /*
@@ -274,7 +304,15 @@ int fr_tls_log_io_error(request_t *request, fr_tls_session_t *session, int ret,
         *      the code needs updating here.
         */
        default:
-               ROPTIONAL(REDEBUG, ERROR, "TLS session error %i (%i)", error, ret);
+               va_start(ap, fmt);
+               msg = fr_vasprintf(NULL, fmt, ap);
+               va_end(ap);
+
+               ROPTIONAL(REDEBUG, ERROR, "%s - TLS session error - %s (%i)",
+                         msg, fr_table_str_by_value(ssl_io_error_table, err, "<UNKNOWN>"), err);
+
+               talloc_free(msg);
+
                return -1;
        }
 

diff --git a/src/lib/tls/log.h b/src/lib/tls/log.h
index 93e83a2ed4f4688d99a6f1c6066e2ffc0f6659f4..95aefe7ebfb1dc5f23f4e46ff795dc79c1adb3ca 100644 (file)
--- a/src/lib/tls/log.h
+++ b/src/lib/tls/log.h
@@ -39,8 +39,8 @@ RCSIDH(tls_log_h, "$Id$")
 void           _fr_tls_log_certificate_chain(char const *file, int line,
                                              request_t *request, fr_log_type_t log_type, STACK_OF(X509) *chain, X509 *cert);
 
-int            fr_tls_log_io_error(request_t *request, fr_tls_session_t *session, int ret, char const *msg, ...)
-                                   CC_HINT(format (printf, 4, 5));
+int            fr_tls_log_io_error(request_t *request, int err, char const *msg, ...)
+                                   CC_HINT(format (printf, 3, 4));
 
 int            fr_tls_log_error(request_t *request, char const *msg, ...) CC_HINT(format (printf, 2, 3));
 

diff --git a/src/lib/tls/session.c b/src/lib/tls/session.c
index 530e708fafbffd8d3791f160800acb3a8b386018..2b59315f363815972f194ef3fc77b2947acad734 100644 (file)
--- a/src/lib/tls/session.c
+++ b/src/lib/tls/session.c
@@ -915,7 +915,7 @@ int fr_tls_session_recv(request_t *request, fr_tls_session_t *tls_session)
 
                default:
                        REDEBUG("Error in fragmentation logic");
-                       fr_tls_log_io_error(request, tls_session, ret, "Failed in SSL_read (%s)", __FUNCTION__);
+                       fr_tls_log_io_error(request, code, "SSL_read (%s)", __FUNCTION__);
                        goto error;
                }
 
@@ -991,7 +991,8 @@ int fr_tls_session_send(request_t *request, fr_tls_session_t *tls_session)
                        tls_session->dirty_out.used = ret;
                        ret = 0;
                } else {
-                       if (fr_tls_log_io_error(request, tls_session, ret, "Failed in SSL_write") < 0) ret = -1;
+                       if (fr_tls_log_io_error(request, SSL_get_error(tls_session->ssl, ret),
+                                               "SSL_write (%s)", __FUNCTION__) < 0) ret = -1;
                }
        }
 
@@ -1252,6 +1253,7 @@ static unlang_action_t tls_session_async_handshake_cont(rlm_rcode_t *p_result, i
                                                        request_t *request, void *uctx)
 {
        fr_tls_session_t        *tls_session = talloc_get_type_abort(uctx, fr_tls_session_t);
+       int                     err;
 
        RDEBUG3("(re-)entered state %s", __FUNCTION__);
 
@@ -1297,7 +1299,7 @@ static unlang_action_t tls_session_async_handshake_cont(rlm_rcode_t *p_result, i
         *      it'd like to perform the operation
         *      asynchronously.
         */
-       switch (SSL_get_error(tls_session->ssl, tls_session->last_ret)) {
+       switch (err = SSL_get_error(tls_session->ssl, tls_session->last_ret)) {
        case SSL_ERROR_WANT_ASYNC:      /* Certification validation or cache loads */
        {
                unlang_action_t ua;
@@ -1354,8 +1356,8 @@ static unlang_action_t tls_session_async_handshake_cont(rlm_rcode_t *p_result, i
                 *      Returns 0 if we can continue processing the handshake
                 *      Returns -1 if we encountered a fatal error.
                 */
-               if (fr_tls_log_io_error(request, tls_session,
-                                       tls_session->last_ret, "Failed in SSL_read (%s)", __FUNCTION__) < 0) goto error;
+               if (fr_tls_log_io_error(request,
+                                       err, "SSL_read (%s)", __FUNCTION__) < 0) goto error;
                return tls_session_async_handshake_done_round(p_result, priority, request, uctx);
        }
 }
@@ -1537,7 +1539,7 @@ fr_tls_session_t *fr_tls_session_alloc_client(TALLOC_CTX *ctx, SSL_CTX *ssl_ctx)
 
        ret = SSL_connect(tls_session->ssl);
        if (ret <= 0) {
-               fr_tls_log_io_error(NULL, tls_session, ret, "Failed in SSL_connect");
+               fr_tls_log_io_error(NULL, SSL_get_error(tls_session->ssl, ret), "SSL_connect (%s)", __FUNCTION__);
                fr_tls_session_request_unbind(tls_session->ssl);
                talloc_free(tls_session);