From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from gate001.proxmox.com (gate001.proxmox.com [45.144.208.40]) by lore.proxmox.com (Postfix) with ESMTPS id 785601FF0B4 for ; Tue, 10 Nov 2026 12:07:48 +0100 (CET) Received: from gate001.proxmox.com (localhost.localdomain [127.0.0.1]) by gate001.proxmox.com (Proxmox) with ESMTP id 41E4221625; Tue, 10 Nov 2026 12:07:47 +0100 (CET) From: "Max R. Carrara" To: pbs-devel@lists.proxmox.com Subject: [PATCH proxmox v3 5/5] fix #6738: rest-server: log early closed connections at debug level Date: Tue, 10 Nov 2026 12:07:27 +0100 Message-ID: <20261110110728.144880-6-m.carrara@proxmox.com> X-Mailer: git-send-email 2.47.3 In-Reply-To: <20261110110728.144880-1-m.carrara@proxmox.com> References: <20261110110728.144880-1-m.carrara@proxmox.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Bm-Milter-Handled: 55990f41-d878-4baa-be0a-ee34c49e34d2 X-Bm-Transport-Timestamp: 1794308858940 X-SPAM-LEVEL: Spam detection results: 0 AWL 0.309 Adjusted score from AWL reputation of From: address DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment (newer systems) RCVD_IN_DNSWL_MED -2.3 Sender listed at https://www.dnswl.org/, medium trust SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches SPF record Message-ID-Hash: KIKKZMRHHVD4MF3J4SUCJI6WP5OWLBEJ X-Message-ID-Hash: KIKKZMRHHVD4MF3J4SUCJI6WP5OWLBEJ X-MailFrom: m.carrara@proxmox.com X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; loop; banned-address; emergency; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header X-Mailman-Version: 3.3.10 Precedence: list List-Id: Proxmox Backup Server development discussion List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: 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 --- 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) { - let err = result.expect_err("check must fail"); - assert!(err.downcast_ref::().is_some(), "{err:#}"); + fn assert_connection_closed(result: Result) { + assert!( + matches!(result, Ok(TlsHandshakeCheck::ConnectionClosed)), + "{result:?}" + ); } fn assert_timeout_error(result: Result) { 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