diff --git a/internal/cloudflare/client.go b/internal/cloudflare/client.go index 50ae9cc..fd4ada6 100644 --- a/internal/cloudflare/client.go +++ b/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)) diff --git a/internal/cloudflare/client_test.go b/internal/cloudflare/client_test.go index 0b381b4..b53beec 100644 --- a/internal/cloudflare/client_test.go +++ b/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) } } diff --git a/internal/cloudflare/measure.go b/internal/cloudflare/measure.go index 8691f46..74c9a53 100644 --- a/internal/cloudflare/measure.go +++ b/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 { diff --git a/internal/cloudflare/types.go b/internal/cloudflare/types.go index e78a05d..c86fc1a 100644 --- a/internal/cloudflare/types.go +++ b/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 diff --git a/internal/cloudflare/upload_test.go b/internal/cloudflare/upload_test.go new file mode 100644 index 0000000..5b676cb --- /dev/null +++ b/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) + } + }) + } +}