[PATCH proxmox v3 5/5] fix #6738: rest-server: log early closed connections at debug level

["Max R. Carrara" <m.carrara@proxmox.com>]

When TLS is optional, the server waits for the first five bytes of a
new connection to check whether the client initiates a TLS handshake.

If the client closed the connection before sending these bytes, the
check failed with an error that was logged at error level. Health
checks and monitoring tools that only test whether the port is open
do exactly that, which floods the logs with these errors.

Report a connection that is closed before the check completes as a
separate outcome of the check, and log it only at debug level.

Treat a reset connection the same way, because some health checks
close their sockets like that to avoid lingering connections.

Use the debug log level instead of the acceptor's debug flag, which
other messages about misbehaving clients are tied to, so that these
messages can be enabled through the regular log level configuration.

Other errors are still logged at error level. This includes timeouts
of clients that connect but do not send enough data.

Signed-off-by: Max R. Carrara <m.carrara@proxmox.com>
---
 proxmox-rest-server/src/connection.rs | 39 ++++++++++++++++++---------
 1 file changed, 27 insertions(+), 12 deletions(-)

diff --git a/proxmox-rest-server/src/connection.rs b/proxmox-rest-server/src/connection.rs
index f116ef47..d2756c0b 100644
--- a/proxmox-rest-server/src/connection.rs
+++ b/proxmox-rest-server/src/connection.rs
@@ -307,10 +307,13 @@ enum TlsHandshakeCheck {
     /// See [contains_tls_handshake_fragment] for details on how this is
     /// checked.
     Initiated,
     /// The client sent data that does not start a TLS handshake.
     NotInitiated,
+    /// The client closed or reset the connection before sending enough data for
+    /// the check.
+    ConnectionClosed,
 }
 
 impl AcceptBuilder {
     async fn accept_connections(
         self,
@@ -488,10 +491,17 @@ impl AcceptBuilder {
                     log::error!(
                         "[{peer}] failed to accept connection - connection channel closed: {send_err}"
                     );
                 }
             }
+            Ok(TlsHandshakeCheck::ConnectionClosed) => {
+                // Health checks and port scanners often connect without sending
+                // anything, so keep this out of the logs by default
+                log::debug!(
+                    "[{peer}] client closed the connection before the TLS handshake check completed"
+                );
+            }
             Err(err) => {
                 log::error!("[{peer}] failed to check for TLS handshake: {err:#}");
             }
         }
     }
@@ -537,16 +547,21 @@ impl AcceptBuilder {
                         // The socket can be marked as readable again without any new data, for
                         // example if more data arrived between tokio receiving a readiness event
                         // and `peek()`. So, readiness *alone* is not a sign of a closed connection.
                         Ok(peek_len) if peek_len < HANDSHAKE_BYTES_LEN => {
                             if peek_len == 0 || ready.is_read_closed() {
-                                Err(io::ErrorKind::ConnectionAborted.into())
+                                Ok(TlsHandshakeCheck::ConnectionClosed)
                             } else {
                                 Err(io::ErrorKind::WouldBlock.into())
                             }
                         }
-                        // Either we got Ok(HANDSHAKE_BYTES_LEN) or some error.
+                        // Some clients, for example health checks, reset the connection by closing
+                        // their socket with SO_LINGER set to zero to avoid lingering connections.
+                        Err(err) if err.kind() == io::ErrorKind::ConnectionReset => {
+                            Ok(TlsHandshakeCheck::ConnectionClosed)
+                        }
+                        // Either we got Ok(HANDSHAKE_BYTES_LEN) or some other error.
                         res => res.map(|_| {
                             if contains_tls_handshake_fragment(&buf) {
                                 TlsHandshakeCheck::Initiated
                             } else {
                                 TlsHandshakeCheck::NotInitiated
@@ -604,11 +619,10 @@ fn contains_tls_handshake_fragment(buf: &[u8]) -> bool {
     buf[0] == 0x16 && buf[1] == 0x3 && (((buf[3] as u16) << 8) + buf[4] as u16) <= CONTENT_SIZE
 }
 
 #[cfg(test)]
 mod tests {
-    use std::io;
     use std::time::Duration;
 
     use anyhow::Error;
     use tokio::io::AsyncWriteExt;
     use tokio::net::TcpListener;
@@ -657,14 +671,15 @@ mod tests {
         drop(client.await.unwrap());
 
         result
     }
 
-    /// Asserts that the check failed because of the connection itself, not because of a timeout.
-    fn assert_connection_error(result: Result<TlsHandshakeCheck, Error>) {
-        let err = result.expect_err("check must fail");
-        assert!(err.downcast_ref::<io::Error>().is_some(), "{err:#}");
+    fn assert_connection_closed(result: Result<TlsHandshakeCheck, Error>) {
+        assert!(
+            matches!(result, Ok(TlsHandshakeCheck::ConnectionClosed)),
+            "{result:?}"
+        );
     }
 
     fn assert_timeout_error(result: Result<TlsHandshakeCheck, Error>) {
         let err = result.expect_err("check must time out");
         assert_eq!(
@@ -727,60 +742,60 @@ mod tests {
             drop(stream);
             None
         })
         .await;
 
-        assert_connection_error(result);
+        assert_connection_closed(result);
     }
 
     #[tokio::test]
     async fn a_client_closing_after_partial_data_is_reported() {
         let result = check_client(CHECK_TIMEOUT, |mut stream| async move {
             stream.write_all(&[0x16, 0x3]).await.unwrap();
             drop(stream);
             None
         })
         .await;
 
-        assert_connection_error(result);
+        assert_connection_closed(result);
     }
 
     #[tokio::test]
     async fn a_client_shutting_down_after_partial_data_is_reported() {
         let result = check_client(CHECK_TIMEOUT, |mut stream| async move {
             stream.write_all(&[0x16, 0x3]).await.unwrap();
             stream.shutdown().await.unwrap();
             Some(stream)
         })
         .await;
 
-        assert_connection_error(result);
+        assert_connection_closed(result);
     }
 
     #[tokio::test]
     async fn a_client_resetting_without_data_is_reported() {
         let result = check_client(CHECK_TIMEOUT, |stream| async move {
             stream.set_linger(Some(Duration::ZERO)).unwrap();
             drop(stream);
             None
         })
         .await;
 
-        assert_connection_error(result);
+        assert_connection_closed(result);
     }
 
     #[tokio::test]
     async fn a_client_resetting_after_partial_data_is_reported() {
         let result = check_client(CHECK_TIMEOUT, |mut stream| async move {
             stream.write_all(&[0x16, 0x3]).await.unwrap();
             stream.set_linger(Some(Duration::ZERO)).unwrap();
             drop(stream);
             None
         })
         .await;
 
-        assert_connection_error(result);
+        assert_connection_closed(result);
     }
 
     #[tokio::test]
     async fn an_idle_client_times_out() {
         let result = check_client(SHORT_CHECK_TIMEOUT, |stream| async move { Some(stream) }).await;
-- 
2.47.3