From 287068396f40f17373220bb9eefb23e8f4072afe Mon Sep 17 00:00:00 2001 From: Thomas Eizinger Date: Tue, 18 Feb 2025 17:12:52 +1100 Subject: [PATCH] chore(snownet): advance backoff after accessing interval (#8175) When we detect timed-out request to a relay, we print the duration we were waiting for. Currently, this is offset by one "backoff tick" because we advance the backoff too early. Here is a log-output of a test prior to the change: ``` snownet::allocation: Sending BINDING requests to pick active socket relay_socket=V4(127.0.0.1:3478) handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 1.5s, re-sending id=TransactionId(0x0BFA13E983FEF36EE4877719) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 2.25s, re-sending id=TransactionId(0x0BFA13E983FEF36EE4877719) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 3.375s, re-sending id=TransactionId(0x0BFA13E983FEF36EE4877719) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 3.375s, re-sending id=TransactionId(0x0BFA13E983FEF36EE4877719) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Backoff expired, giving up id=TransactionId(0x0BFA13E983FEF36EE4877719) method=binding dst=127.0.0.1:3478 ``` and with this change: ``` snownet::allocation: Sending BINDING requests to pick active socket relay_socket=V4(127.0.0.1:3478) handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 1s, re-sending id=TransactionId(0x6C79DD3607DF96806C4A7D8C) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 1.5s, re-sending id=TransactionId(0x6C79DD3607DF96806C4A7D8C) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 2.25s, re-sending id=TransactionId(0x6C79DD3607DF96806C4A7D8C) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Request timed out after 3.375s, re-sending id=TransactionId(0x6C79DD3607DF96806C4A7D8C) method=binding dst=127.0.0.1:3478 handle_timeout{active_socket=None}: snownet::allocation: Backoff expired, giving up id=TransactionId(0x6C79DD3607DF96806C4A7D8C) method=binding dst=127.0.0.1:3478 t ``` There is no functional difference, we were just logging the wrong duration. --- rust/connlib/snownet/src/allocation.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/rust/connlib/snownet/src/allocation.rs b/rust/connlib/snownet/src/allocation.rs index 9c61c2d32..b4c1b64ce 100644 --- a/rust/connlib/snownet/src/allocation.rs +++ b/rust/connlib/snownet/src/allocation.rs @@ -682,11 +682,11 @@ impl Allocation { .remove(&timed_out_request) .expect("ID is from list"); - backoff.handle_timeout(now); // Must update timeout here to avoid an endless loop. - let backoff_duration = backoff.interval(); let method = request.method(); + backoff.handle_timeout(now); // Must update timeout here to avoid an endless loop. + tracing::debug!(id = ?request.transaction_id(), %method, %dst, "Request timed out after {backoff_duration:?}, re-sending"); let needs_auth = method != BINDING;