[PATCH proxmox v2] fix #6738: rest-server: improve TLS handshake error logging

[PATCH proxmox v2] fix #6738: rest-server: improve TLS handshake error logging

[Max R. Carrara]

Right now, when a client connects to the server, we continuously peek
into the TCP stream's buffer until we can perform the TLS handshake
check. If the client closes the connection after sending < 5 bytes, we
exit the peek loop. If the client instead keeps the connection open,
the future times out if the handshake check isn't made.

Instead of exiting with `ErrorKind::ConnectionAborted`, wrap the
return type in an `Option` and use `None` to signal that we could not
finish the check for the TLS handshake. That way we avoid mixing our
own logic into IO error handling.

Reduce the amount of log noise by ignoring the above case where the
TLS handshake check did not finish (which means that the client either
closed the connection or is not sending any bytes).

Log timeouts without their error chain (like before), as
there isn't any additional context for them.

Because any other kinds of errors should be sufficiently rare, log
them with their error chain. The error chain is formatted to stay in
one line, as the default formatting looks quite awkward otherwise.

Make the context added to the `async_io()` coroutine call more
general and informative, as not only the stream buffer peeking can
fail. Shorten the general log message as well.

Signed-off-by: Max R. Carrara <m.carrara@proxmox.com>
---
Changes v1 --> v2:
* Incorporated Hannes's feedback (thanks!), but using an Option instead
  of introducing a new error type
  See: https://lore.proxmox.com/pbs-devel/b7be5976-bf7c-49ea-808a-5816f9306603@proxmox.com/
* Tested this through opening a socket by hand using Python and sending
  different byte sequences, but would be nice if somebody else could
  test this as well :)

 proxmox-rest-server/src/connection.rs | 37 ++++++++++++++++++++-------
 1 file changed, 28 insertions(+), 9 deletions(-)

diff --git a/proxmox-rest-server/src/connection.rs b/proxmox-rest-server/src/connection.rs
index d76eda01..765b7e44 100644
--- a/proxmox-rest-server/src/connection.rs
+++ b/proxmox-rest-server/src/connection.rs
@@ -466,18 +466,35 @@ impl AcceptBuilder {
             Self::wait_for_client_tls_handshake(socket_ref, CLIENT_HANDSHAKE_TIMEOUT).await;

         match handshake_res {
-            Ok(true) => {
+            Ok(Some(true)) => {
                 Self::do_accept_tls(state, flags, secure_sender).await;
             }
-            Ok(false) => {
+            Ok(Some(false)) => {
                 let insecure_stream = Box::pin(state.socket);

                 if let Err(send_err) = insecure_sender.send(Ok(insecure_stream)).await {
                     log::error!("[{peer}] failed to accept connection - connection channel closed: {send_err}");
                 }
             }
+            Ok(None) => {
+                log::debug!(
+                    "[{peer}] could not check for TLS handshake\
+                    - client either didn't send enough bytes or closed the connection"
+                );
+            }
             Err(err) => {
-                log::error!("[{peer}] failed to check for TLS handshake: {err}");
+                // Timeouts are printed without their cause
+                if err.downcast_ref::<tokio::time::error::Elapsed>().is_some() {
+                    log::error!("[{peer}] TLS handshake error: {err}");
+                    return;
+                }
+
+                // As other kinds of errors are relatively rare, print them with their error chain
+                let mut err_chain = err.chain().map(ToString::to_string);
+                let err_text = err_chain.by_ref().take(1).collect::<Vec<_>>().join("");
+                let cause = err_chain.collect::<Vec<_>>().join(" - ");
+
+                log::error!("[{peer}] TLS handshake error: {err_text} - Caused by: {cause}");
             }
         }
     }
@@ -485,7 +502,7 @@ impl AcceptBuilder {
     async fn wait_for_client_tls_handshake(
         incoming_stream: &TcpStream,
         timeout: Duration,
-    ) -> Result<bool, Error> {
+    ) -> Result<Option<bool>, Error> {
         const HANDSHAKE_BYTES_LEN: usize = 5;

         let future = async {
@@ -515,21 +532,23 @@ impl AcceptBuilder {
                         // This means we will peek into the stream's queue until we got
                         // HANDSHAKE_BYTE_LEN bytes or an error.
                         Ok(peek_len) if peek_len < HANDSHAKE_BYTES_LEN => {
-                            // if we detect the same peek len again but still got a readable stream,
-                            // the connection was probably closed, so abort here
+                            // If we detect the same peek len again but still got a readable stream,
+                            // the connection was probably closed, so exit here.
                             if peek_len == previous_peek_len {
-                                Err(io::ErrorKind::ConnectionAborted.into())
+                                Ok(None)
                             } else {
                                 previous_peek_len = peek_len;
                                 Err(io::ErrorKind::WouldBlock.into())
                             }
                         }
                         // Either we got Ok(HANDSHAKE_BYTES_LEN) or some error.
-                        res => res.map(|_| contains_tls_handshake_fragment(&buf)),
+                        res => res.map(|_| Some(contains_tls_handshake_fragment(&buf))),
                     }
                 })
                 .await
-                .context("couldn't peek into incoming TCP stream")
+                .context(
+                    "failed to determine whether the peer is initiating a TLS handshake or not",
+                )
         };

         tokio::time::timeout(timeout, future)
--
2.47.3