From 7eb915011626f99fa48b35a6fd45aab6f9e2fa82 Mon Sep 17 00:00:00 2001 From: RustDesk <71636191+rustdesk@users.noreply.github.com> Date: Thu, 6 Aug 2026 10:57:09 +0800 Subject: [PATCH] Audit retry nonce (#15759) * fix: retry audit posts and add per-record nonce A single post_request attempt meant any transient failure (timeout, DNS, connection reset) silently dropped the audit record. Retry up to 3 times with backoff and log at error level when a record is finally dropped. Retries (and the existing TCP-proxy fallback) can deliver the same record twice; attach a per-record nonce so the api server can dedup. Co-Authored-By: Claude Fable 5 * fix: fail audit posts on http error status post_request discards the status code, so a 5xx from a reverse proxy (e.g. nginx answering 502 while hbbs restarts) or any 4xx rejection was treated as success and the audit record silently dropped without a log line. Add post_request_with_status (same semantics and TCP-proxy fallback as post_request, status preserved; existing callers untouched) and use it for audit posts: 2xx succeeds, transport errors and 5xx retry, 4xx fails immediately since retrying a deterministic rejection cannot help. Co-Authored-By: Claude Fable 5 * fix: report audit posts rejected with 200 error body hbbs maps handler failures (e.g. a database write error) to HTTP 200 with an {"error": ...} body (WebError::ServerError), so the client treated them as success and the audit record was silently dropped. Detect the error body and fail visibly. No retry: the server already consumed the nonce, and persistence failures are the server's job to solve; the client's job is to make the loss visible. Co-Authored-By: Claude Fable 5 * fix: give audit retries a delay long enough to outlive a restart The backoff was 1s then 2s, so all three attempts landed within about three seconds. That does not cover the case the retry exists for: a reverse proxy answering 502 while the api server restarts fails fast, so every attempt hits the same outage and the record is dropped anyway. Use 10s and 30s instead. The window is bounded on the other side - the api server dedups by nonce for five minutes, and a retry arriving after that expired would be stored twice - so the worst case is now about three minutes, leaving room under that limit. Derive the attempt count from the delay table so the two cannot drift apart. Co-Authored-By: Claude Opus 5 (1M context) * fix: retry audit posts the server answered with an error body hbbs reports handler failures as 200 with an {"error": ...} body, and this treated them as final on the grounds that the server had already consumed the record's nonce. That is no longer how the server behaves: it releases the nonce when the write fails, and answers a post whose earlier attempt is still being written with an error as well. Both are exactly the cases where trying again is what gets the record stored, so giving up after the first attempt drops audit records the retry was added to save. Co-Authored-By: Claude Opus 5 (1M context) * fix: bound audit retries by elapsed time, and retry 408 and 429 The comment claimed the retry window fit inside the server's five-minute nonce memory with room to spare, and that was wrong: one attempt is up to 84s, not 12s, because post_request_ retries the TLS handshake up to four times at 12s each before the 36s TCP-proxy fallback. Three of those plus the delays is 292s against a 300s window, and a suspend between attempts stretches the wall clock without any bound at all, so counting attempts cannot bound this. Stop by elapsed time instead: no new attempt starts past 120s, which leaves the last one room to finish well inside the server's window. Also retry 408 and 429. Both are transient - the request timed out upstream, or a proxy is shedding load - but the 5xx test dropped the record after the first attempt. Co-Authored-By: Claude Opus 5 (1M context) * fix: only an empty 2xx body counts as a stored audit The success check was inverted: any 2xx body that failed to parse as an {"error": ...} object was reported as stored. A proxy interposing a 2xx maintenance page, or a malformed error value, therefore ended the retry loop with success and silently dropped the record - the exact loss the retry was added to prevent. The audit handlers' success contract is an empty body, so treat exactly that as success. A nonempty body with a valid error message stays a retryable server error; any other nonempty body is now a retryable "unexpected response body" instead of an accepted store. Both old and new hbbs answer success with an empty body, and no caller reads the returned text, so nothing depends on the previous acceptance. Co-Authored-By: Claude Opus 5 (1M context) * fix: do not start an audit retry past the deadline The deadline was only checked after an attempt returned, so an attempt could still begin up to one backoff delay past it - starting as late as ~150s and landing at ~234s, while the comment claimed no attempt starts past 120s. Re-check after the delay so the stated bound actually holds: the last attempt now starts before 120s and lands by ~204s, inside the server's five-minute nonce window with margin restored. Co-Authored-By: Claude Opus 5 (1M context) * docs: drop a retry rationale the server no longer backs The comment claimed hbbs answers a post whose earlier attempt is still being written with an error, so that retrying it is what stores the record. That stopped being true: hbbs now answers a concurrent duplicate as already stored rather than as retryable, having dropped the in-flight rejection along with the claim state machine it needed. Nothing in the handling changes - a 2xx carrying an {"error": ...} body is still retried, and that is still right, because the server releases the record's nonce when its write fails. Only the half of the rationale the server no longer backs is gone, since this comment is where the contract between the two repos is written down. Co-Authored-By: Claude Opus 5 --------- Co-authored-by: Claude Fable 5 --- src/common.rs | 52 ++++++++++++++++++++ src/server/connection.rs | 102 ++++++++++++++++++++++++++++++++++++++- 2 files changed, 152 insertions(+), 2 deletions(-) diff --git a/src/common.rs b/src/common.rs index cd35433e0..592ab2a45 100644 --- a/src/common.rs +++ b/src/common.rs @@ -1405,6 +1405,58 @@ pub async fn post_request(url: String, body: String, header: &str) -> ResultType .await } +/// POST request via TCP proxy, preserving the HTTP status code. +async fn post_request_via_tcp_proxy_status( + url: &str, + body: &str, + header: &str, +) -> ResultType<(u16, String)> { + let headers = parse_simple_header(header); + let resp = tcp_proxy_request("POST", url, body.as_bytes(), headers).await?; + if !resp.error.is_empty() { + bail!("TCP proxy error: {}", resp.error); + } + Ok(( + resp.status as u16, + String::from_utf8_lossy(&resp.body).to_string(), + )) +} + +/// Like `post_request`, but returns the HTTP status code so callers can tell +/// a server-side failure from success. Same fallback rules: on connection +/// failure or 5xx, retry once through the raw TCP proxy when eligible. +pub async fn post_request_with_status( + url: String, + body: String, + header: &str, +) -> ResultType<(u16, String)> { + if should_use_raw_tcp_for_api(&url) { + return post_request_via_tcp_proxy_status(&url, &body, header).await; + } + let http_result = post_request_http(&url, &body, header).await; + let should_fallback = match &http_result { + Err(_) => true, + Ok((status, _)) => *status >= 500, + }; + if should_fallback && can_fallback_to_raw_tcp(&url) { + log::warn!( + "HTTP POST to {} failed or 5xx (result: {:?}), trying TCP proxy fallback", + tcp_proxy_log_target(&url), + http_result + .as_ref() + .map(|(s, _)| *s) + .map_err(|e| e.to_string()), + ); + match post_request_via_tcp_proxy_status(&url, &body, header).await { + Ok(resp) => return Ok(resp), + Err(tcp_err) => { + log::warn!("TCP proxy fallback also failed: {:?}", tcp_err); + } + } + } + http_result +} + #[async_recursion] async fn post_request_( url: &str, diff --git a/src/server/connection.rs b/src/server/connection.rs index 4dc07d366..25d9b6792 100644 --- a/src/server/connection.rs +++ b/src/server/connection.rs @@ -1506,6 +1506,8 @@ impl Connection { v["uuid"] = json!(crate::encode64(hbb_common::get_uuid())); v["conn_id"] = json!(self.inner.id); v["session_id"] = json!(self.lr.session_id); + // Unique per record; the api server dedups retried posts by it. + v["nonce"] = json!(uuid::Uuid::new_v4().to_string()); allow_err!(self.tx_post_seq.send((url, v))); } @@ -1555,6 +1557,7 @@ impl Connection { "path":path, "is_file":is_file, "info":json!(info).to_string(), + "nonce": uuid::Uuid::new_v4().to_string(), }); tokio::spawn(async move { allow_err!(Self::post_audit_async(url, v).await); @@ -1576,6 +1579,7 @@ impl Connection { v["typ"] = json!(typ as i8); v["info"] = serde_json::Value::String(info.to_string()); v["conn_id"] = json!(self.inner.id()); + v["nonce"] = json!(uuid::Uuid::new_v4().to_string()); if typ == AlarmAuditType::IpWhitelist || typ == AlarmAuditType::IdWhitelist { if let Some(audit_ref) = self.conn_audit_ref() { v["conn_audit_ref"] = json!(audit_ref); @@ -1603,9 +1607,103 @@ impl Connection { ); } - #[inline] async fn post_audit_async(url: String, v: Value) -> ResultType { - crate::post_request(url, v.to_string(), "").await + // Audit records are compliance evidence; retry transport errors and + // 5xx (e.g. a reverse proxy answering while the api server restarts) + // so transient failures don't silently drop them. A 4xx is a + // deterministic rejection and fails immediately. + // + // The delays, not the attempt count, are what cover the case this exists + // for: a proxy answering 502 during a restart fails fast, so without them + // every attempt lands within a few seconds and none outlives the restart. + // + // The window is bounded on the other side: the api server only remembers a + // record's nonce for five minutes, so a retry arriving after that expired + // would be stored a second time. Counting attempts cannot bound it - one + // attempt is already up to 84s (post_request_ retries the TLS handshake up + // to four times at 12s each, then the TCP-proxy fallback adds 36s), and a + // suspend between attempts stretches the wall clock without limit. So stop + // by elapsed time instead, early enough that the last attempt still lands + // inside the server's window. + const RETRY_DEADLINE: Duration = Duration::from_secs(120); + // One delay per retry, so the attempt count follows from the table and the + // two cannot drift apart. + const RETRY_BACKOFF_SECS: [u64; 2] = [10, 30]; + const ATTEMPTS: usize = RETRY_BACKOFF_SECS.len() + 1; + let body = v.to_string(); + let started = Instant::now(); + let mut attempt = 0usize; + loop { + attempt += 1; + let (retryable, err) = + match crate::post_request_with_status(url.clone(), body.clone(), "").await { + Ok((status, text)) => { + if (200..300).contains(&status) { + // Success is an empty body. hbbs reports handler + // failures (e.g. a db write error) as 200 with an + // {"error": ...} body - retryable: the server + // releases the record's nonce when its write fails, + // so trying again is what stores the record. Any + // other nonempty body did not come from the audit + // handler (a proxy interposing a 2xx maintenance + // page, a malformed error) and must not be mistaken + // for storage, so it is retried rather than dropped. + if text.trim().is_empty() { + return Ok(text); + } + let server_err = serde_json::from_str::(&text) + .ok() + .and_then(|v| v.get("error")?.as_str().map(|s| s.to_owned())) + .filter(|e| !e.is_empty()); + let (label, detail) = match &server_err { + Some(e) => ("server error", e.as_str()), + None => ("unexpected response body", text.as_str()), + }; + let brief: String = detail.chars().take(128).collect(); + (true, format!("{}: {}", label, brief)) + } else { + let brief: String = text.chars().take(128).collect(); + // 408 and 429 are the transient 4xx: the request timed + // out upstream, or a proxy is shedding load. Every other + // 4xx is a deterministic rejection and retrying it would + // only delay the log line. + let transient = status >= 500 || status == 408 || status == 429; + (transient, format!("status {}: {}", status, brief)) + } + } + Err(e) => (true, e.to_string()), + }; + let elapsed = started.elapsed(); + if !retryable || attempt >= ATTEMPTS || elapsed >= RETRY_DEADLINE { + log::error!( + "Audit post dropped (attempt {}/{}, {:?} elapsed): {}", + attempt, + ATTEMPTS, + elapsed, + err + ); + bail!("{}", err); + } + log::warn!( + "Audit post failed (attempt {}/{}): {}", + attempt, + ATTEMPTS, + err + ); + // In range by construction: the guard above returns at ATTEMPTS. + time::sleep(Duration::from_secs(RETRY_BACKOFF_SECS[attempt - 1])).await; + // Re-checked after the delay so no attempt starts past the deadline; + // the check above alone would let one begin up to a backoff later. + if started.elapsed() >= RETRY_DEADLINE { + log::error!( + "Audit post dropped (attempt {}/{}, deadline passed during backoff): {}", + attempt, + ATTEMPTS, + err + ); + bail!("{}", err); + } + } } fn set_conn_audit_primary_auth(&mut self, method: ConnAuditPrimaryAuth) {