From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [IPv6:2a01:7e0:0:424::9]) by lore.proxmox.com (Postfix) with ESMTPS id DA4CF1FF133 for ; Mon, 27 Apr 2026 15:41:25 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id AF3111FB1D; Mon, 27 Apr 2026 15:41:25 +0200 (CEST) From: "Max R. Carrara" To: pbs-devel@lists.proxmox.com Subject: [PATCH proxmox v2] fix #6738: rest-server: improve TLS handshake error logging Date: Mon, 27 Apr 2026 15:40:45 +0200 Message-ID: <20260427134051.557840-1-m.carrara@proxmox.com> X-Mailer: git-send-email 2.47.3 MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Bm-Milter-Handled: 55990f41-d878-4baa-be0a-ee34c49e34d2 X-Bm-Transport-Timestamp: 1777297156539 X-SPAM-LEVEL: Spam detection results: 0 AWL 0.081 Adjusted score from AWL reputation of From: address BAYES_00 -1.9 Bayes spam probability is 0 to 1% DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment 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: NN2WU76TFRTJHT7XNHQBNLI2Q26W7RWJ X-Message-ID-Hash: NN2WU76TFRTJHT7XNHQBNLI2Q26W7RWJ 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: 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 --- 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::().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::>().join(""); + let cause = err_chain.collect::>().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 { + ) -> Result, 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