fix latency calculation

Author: code-inflation

src/speedtest.rs

@@ -11,12 +11,14 @@ use reqwest::{blocking::Client, StatusCode};
 use serde::Serialize;
 use std::{
     fmt::Display,
+    sync::atomic::{AtomicBool, Ordering},
     time::{Duration, Instant},
 };
 
 const BASE_URL: &str = "https://speed.cloudflare.com";
 const DOWNLOAD_URL: &str = "__down?bytes=";
 const UPLOAD_URL: &str = "__up";
+static WARNED_NEGATIVE_LATENCY: AtomicBool = AtomicBool::new(false);
 
 #[derive(Clone, Copy, Debug, Hash, Serialize, Eq, PartialEq)]
 pub enum TestType {
@@ -180,29 +182,37 @@ pub fn test_latency(client: &Client) -> f64 {
     let req_builder = client.get(url);
 
     let start = Instant::now();
-    let response = req_builder.send().expect("failed to get response");
+    let mut response = req_builder.send().expect("failed to get response");
     let _status_code = response.status();
-    let duration = start.elapsed().as_secs_f64() * 1_000.0;
+    // Drain body to complete the request; ignore errors.
+    let _ = std::io::copy(&mut response, &mut std::io::sink());
+    let total_ms = start.elapsed().as_secs_f64() * 1_000.0;
 
     let re = Regex::new(r"cfRequestDuration;dur=([\d.]+)").unwrap();
+    let server_timing = response
+        .headers()
+        .get("Server-Timing")
+        .expect("No Server-Timing in response header")
+        .to_str()
+        .unwrap();
     let cf_req_duration: f64 = re
-        .captures(
-            response
-                .headers()
-                .get("Server-Timing")
-                .expect("No Server-Timing in response header")
-                .to_str()
-                .unwrap(),
-        )
+        .captures(server_timing)
         .unwrap()
         .get(1)
         .unwrap()
         .as_str()
         .parse()
         .unwrap();
-    let mut req_latency = duration - cf_req_duration;
+    let mut req_latency = total_ms - cf_req_duration;
+    log::debug!(
+        "latency debug: total_ms={total_ms:.3} cf_req_duration_ms={cf_req_duration:.3} req_latency_total={req_latency:.3} server_timing={server_timing}"
+    );
     if req_latency < 0.0 {
-        // TODO investigate negative latency values
+        if !WARNED_NEGATIVE_LATENCY.swap(true, Ordering::Relaxed) {
+            log::warn!(
+                "negative latency after server timing subtraction; clamping to 0.0 (total_ms={total_ms:.3} cf_req_duration_ms={cf_req_duration:.3})"
+            );
+        }
         req_latency = 0.0
     }
     req_latency