From: Arran Cudbard-Bell <a.cudbardb@freeradius.org>
Date: Sat, 2 Oct 2021 16:26:15 +0000 (-0500)
Subject: Improve fr_tls_log_io_error
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=86607e75237092d58418bd4b9d6cda588dcb5eae;p=thirdparty%2Ffreeradius-server.git

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 ff49a41d91..049ece4d17 100644
--- 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 93e83a2ed4..95aefe7ebf 100644
--- 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 530e708faf..2b59315f36 100644
--- 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);