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 <noreply@anthropic.com>

* 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 <noreply@anthropic.com>

* 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 <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

* 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 <noreply@anthropic.com>

---------

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
RustDesk
2026-08-06 10:57:09 +08:00
committed by GitHub
parent ef3a57580f
commit 7eb9150116
2 changed files with 152 additions and 2 deletions

View File

@@ -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,

View File

@@ -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<String> {
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::<Value>(&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) {