From 52014dc0bb2d529037a1eaaf1afa4accf11e4558 Mon Sep 17 00:00:00 2001 From: Ivan Enderlin Date: Wed, 4 Feb 2026 15:03:47 +0100 Subject: [PATCH] chore(sdk): Log the `pos` and the `timeout` as part of the `sync_once` span. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This patch adds the `pos` and `timeout` value as new fields of the `sync_once` span. How to test it? ```sh $ cargo nextest run --retries 0 --no-fail-fast -E "not test(ensure_no_max_concurrent)" -p matrix-sdk-ui --nocapture -- test_sync_all_states | rg sync_once 2026-02-04T14:02:17.043301Z DEBUG sync_once{conn_id="room-list" pos="0" timeout=0}:send{request_id="REQ-3" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="647B" status=200 response_size="72B" request_duration=316.959µs}: matrix_sdk::http_client: Got response 2026-02-04T14:02:17.043783Z DEBUG sync_once{conn_id="room-list" pos="1" timeout=0}:send{request_id="REQ-4" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="648B"}: matrix_sdk::http_client::native: Sending request num_attempt=1 2026-02-04T14:02:17.044093Z DEBUG sync_once{conn_id="room-list" pos="1" timeout=0}:send{request_id="REQ-4" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="648B" status=200 response_size="72B" request_duration=283.75µs}: matrix_sdk::http_client: Got response 2026-02-04T14:02:17.044527Z DEBUG sync_once{conn_id="room-list" pos="2" timeout=0}:send{request_id="REQ-5" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="648B"}: matrix_sdk::http_client::native: Sending request num_attempt=1 2026-02-04T14:02:17.044808Z DEBUG sync_once{conn_id="room-list" pos="2" timeout=0}:send{request_id="REQ-5" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="648B" status=200 response_size="72B" request_duration=254.875µs}: matrix_sdk::http_client: Got response 2026-02-04T14:02:17.045245Z DEBUG sync_once{conn_id="room-list" pos="3" timeout=30000}:send{request_id="REQ-6" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="648B"}: matrix_sdk::http_client::native: Sending request num_attempt=1 2026-02-04T14:02:17.045517Z DEBUG sync_once{conn_id="room-list" pos="3" timeout=30000}:send{request_id="REQ-6" method=POST uri="http://127.0.0.1:49663/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="648B" status=200 response_size="72B" request_duration=247.417µs}: matrix_sdk::http_client: Got response ``` --- crates/matrix-sdk/src/http_client/mod.rs | 4 ++++ crates/matrix-sdk/src/sliding_sync/mod.rs | 9 +++++---- 2 files changed, 9 insertions(+), 4 deletions(-) diff --git a/crates/matrix-sdk/src/http_client/mod.rs b/crates/matrix-sdk/src/http_client/mod.rs index d3c511627..d7a0c1515 100644 --- a/crates/matrix-sdk/src/http_client/mod.rs +++ b/crates/matrix-sdk/src/http_client/mod.rs @@ -179,10 +179,14 @@ impl HttpClient { let method = request.method(); let mut uri_parts = request.uri().clone().into_parts(); + + // Erase the query parameters for the sake of secrecy (in case a token is + // present). if let Some(path_and_query) = &mut uri_parts.path_and_query { *path_and_query = path_and_query.path().try_into().expect("path is valid PathAndQuery"); } + let uri = http::Uri::from_parts(uri_parts).expect("created from valid URI"); span.record("method", debug(method)).record("uri", uri.to_string()); diff --git a/crates/matrix-sdk/src/sliding_sync/mod.rs b/crates/matrix-sdk/src/sliding_sync/mod.rs index 924844631..2f42ae205 100644 --- a/crates/matrix-sdk/src/sliding_sync/mod.rs +++ b/crates/matrix-sdk/src/sliding_sync/mod.rs @@ -400,7 +400,6 @@ impl SlidingSync { Ok(update_summary) } - #[instrument(skip_all)] async fn generate_sync_request( &self, ) -> Result<(http::Request, RequestConfig, OwnedMutexGuard)> { @@ -467,8 +466,6 @@ impl SlidingSync { position_guard.pos.clone() }; - Span::current().record("pos", &pos); - // When the client sends a request with no `pos`, MSC4186 returns no device // lists updates, as it only returns changes since the provided `pos` // (which is `null` in this case); this is in line with sync v2. @@ -496,6 +493,10 @@ impl SlidingSync { PollTimeout::Default => Some(self.inner.poll_timeout), }; + Span::current() + .record("pos", &pos) + .record("timeout", timeout.map(|duration| duration.as_millis())); + let mut request = assign!(http::Request::new(), { conn_id: Some(self.inner.id.clone()), pos, @@ -672,7 +673,7 @@ impl SlidingSync { /// /// Public for testing purposes only. #[doc(hidden)] - #[instrument(skip_all, fields(pos, conn_id = self.inner.id))] + #[instrument(skip_all, fields(conn_id = self.inner.id, pos, timeout))] pub async fn sync_once(&self) -> Result { let (request, request_config, position_guard) = self.generate_sync_request().await?;