fix: measure upload and latency without server timing

internal/cloudflare/client.go

@@ -34,6 +34,11 @@ func MakeRequest(method, path string, payload []byte) (PerfData, error) {
 	}
 
 	trace := &httptrace.ClientTrace{
+		WroteRequest: func(info httptrace.WroteRequestInfo) {
+			if info.Err == nil {
+				pd.RequestWritten = time.Now()
+			}
+		},
 		GotFirstResponseByte: func() { pd.TTFB = time.Now() },
 	}
 	req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))

internal/cloudflare/client_test.go

@@ -184,7 +184,7 @@ func TestMeasurePhaseFallsBackWhenUploadServerTimingIsInvalid(t *testing.T) {
 	if result.FailedSamples != 0 {
 		t.Fatalf("result.FailedSamples = %d, want 0", result.FailedSamples)
 	}
-	if len(result.Warnings) == 0 || !strings.Contains(result.Warnings[0], "upload throughput measurement used fallback timing 1 time") {
+	if len(result.Warnings) == 0 || !strings.Contains(result.Warnings[0], "upload throughput measurement used fallback timing 2 time") {
 		t.Fatalf("result.Warnings = %v, want upload fallback warning", result.Warnings)
 	}
 }

internal/cloudflare/measure.go

@@ -57,17 +57,22 @@ func latencySample() (float64, error) {
 		return 0, errors.New("missing first response byte timing")
 	}
 
-	serverTiming, err := ParseServerTiming(pd.ServerTimingHeader)
-	if err != nil {
-		return 0, err
+	clientDuration := pd.TTFB.Sub(pd.Started).Seconds() * 1000
+	if clientDuration <= 0 {
+		return 0, fmt.Errorf("computed non-positive client latency: %.2f ms", clientDuration)
 	}
 
-	dur := pd.TTFB.Sub(pd.Started).Seconds()*1000 - serverTiming
-	if dur <= 0 {
-		return 0, fmt.Errorf("computed non-positive latency: %.2f ms", dur)
+	serverTiming, err := ParseServerTiming(pd.ServerTimingHeader)
+	if err == nil && !math.IsNaN(serverTiming) && !math.IsInf(serverTiming, 0) && serverTiming >= 0 {
+		dur := clientDuration - serverTiming
+		if dur <= 0 {
+			return 0, fmt.Errorf("computed non-positive latency: %.2f ms", dur)
+		}
+
+		return dur, nil
 	}
 
-	return dur, nil
+	return clientDuration, nil
 }
 
 // MeasureLatency sends lightweight requests and returns the unloaded latency samples in ms.
@@ -115,24 +120,17 @@ func uploadSample(size int, payload []byte) (float64, error, error) {
 		return 0, nil, err
 	}
 
-	serverTiming, err := ParseServerTiming(pd.ServerTimingHeader)
-	if err == nil && serverTiming > 0 {
-		return MeasureSpeed(size, serverTiming), nil, nil
+	requestDuration := pd.RequestWritten.Sub(pd.Started).Seconds() * 1000
+	if requestDuration > 0 {
+		return MeasureSpeed(size, requestDuration), nil, nil
 	}
 
 	fallbackDuration := pd.Ended.Sub(pd.Started).Seconds() * 1000
 	if fallbackDuration <= 0 {
-		if err != nil {
-			return 0, nil, err
-		}
 		return 0, nil, fmt.Errorf("computed non-positive upload duration: %.2f ms", fallbackDuration)
 	}
 
-	if err != nil {
-		return MeasureSpeed(size, fallbackDuration), fmt.Errorf("upload server timing unavailable, fell back to end-to-end duration: %w", err), nil
-	}
-
-	return MeasureSpeed(size, fallbackDuration), fmt.Errorf("upload server timing was non-positive (%.2f ms), fell back to end-to-end duration", serverTiming), nil
+	return MeasureSpeed(size, fallbackDuration), errors.New("request write timing unavailable, fell back to end-to-end duration"), nil
 }
 
 func validatePhaseSpecs(phaseType string, specs []PhaseSpec) error {

internal/cloudflare/types.go

@@ -43,6 +43,7 @@ type PhaseMeasurement struct {
 // PerfData holds timing data captured during an HTTP request.
 type PerfData struct {
 	Started            time.Time
+	RequestWritten     time.Time
 	TTFB               time.Time
 	Ended              time.Time
 	ServerTimingHeader string

internal/cloudflare/upload_test.go

@@ -0,0 +1,83 @@
+package cloudflare
+
+import (
+	"bytes"
+	"io"
+	"math"
+	"net/http"
+	"net/http/httptrace"
+	"strings"
+	"testing"
+	"time"
+)
+
+func TestUploadSampleUsesRequestWrittenTiming(t *testing.T) {
+	useTestHTTPClient(t, roundTripFunc(func(req *http.Request) (*http.Response, error) {
+		trace := httptrace.ContextClientTrace(req.Context())
+		if trace == nil || trace.WroteRequest == nil {
+			t.Fatal("request trace does not expose WroteRequest")
+		}
+
+		time.Sleep(10 * time.Millisecond)
+		trace.WroteRequest(httptrace.WroteRequestInfo{})
+
+		return &http.Response{
+			StatusCode: http.StatusOK,
+			Header: http.Header{
+				"Server-Timing": []string{"cfRequestDuration;dur=0.001"},
+			},
+			Body:    io.NopCloser(strings.NewReader("")),
+			Request: req,
+		}, nil
+	}))
+
+	speed, warning, err := uploadSample(10_000, bytes.Repeat([]byte("0"), 10_000))
+	if err != nil {
+		t.Fatalf("uploadSample() error = %v", err)
+	}
+	if warning != nil {
+		t.Fatalf("uploadSample() warning = %v, want nil", warning)
+	}
+	if speed <= 0 || speed >= 1_000 {
+		t.Fatalf("uploadSample() speed = %v, want a positive client-timed speed below 1000 Mbps", speed)
+	}
+}
+
+func TestLatencySampleFallsBackToClientTiming(t *testing.T) {
+	for _, serverTiming := range []string{
+		"cfSpeedEdge;dur=3",
+		"cfRequestDuration;dur=NaN",
+		"cfRequestDuration;dur=Inf",
+		"cfRequestDuration;dur=-Inf",
+		"cfRequestDuration;dur=-1000000000",
+	} {
+		t.Run(serverTiming, func(t *testing.T) {
+			useTestHTTPClient(t, roundTripFunc(func(req *http.Request) (*http.Response, error) {
+				trace := httptrace.ContextClientTrace(req.Context())
+				if trace == nil || trace.GotFirstResponseByte == nil {
+					t.Fatal("request trace does not expose GotFirstResponseByte")
+				}
+
+				time.Sleep(10 * time.Millisecond)
+				trace.GotFirstResponseByte()
+
+				return &http.Response{
+					StatusCode: http.StatusOK,
+					Header: http.Header{
+						"Server-Timing": []string{serverTiming},
+					},
+					Body:    io.NopCloser(strings.NewReader("")),
+					Request: req,
+				}, nil
+			}))
+
+			latency, err := latencySample()
+			if err != nil {
+				t.Fatalf("latencySample() error = %v", err)
+			}
+			if math.IsNaN(latency) || math.IsInf(latency, 0) || latency <= 0 || latency >= 60_000 {
+				t.Fatalf("latencySample() = %v, want a positive finite client-timed latency", latency)
+			}
+		})
+	}
+}