repo-review: mixed-clock duration in the logging roundtripper at a5d735f

CHANGELOG.md

@@ -8,6 +8,11 @@ Please choose versions by [Semantic Versioning](http://semver.org/).
 * MINOR version when you add functionality in a backwards-compatible manner, and
 * PATCH version when you make backwards-compatible bug fixes.
 
+## Unreleased
+
+- fix: `NewRoundTripperLog` measured request duration with `time.Since(now)` while starting the timer with `libtime.Now()`. Against a frozen clock those are two different clocks, so the logged duration was computed from a mixed pair. Now `libtime.Now().Sub(now)`.
+- test: add `http_roundtripper-log_test.go`, swapping the package-level `libtime.Now` var for a fake clock and asserting it is called twice per request. A real-time test cannot distinguish the two clock sources, which is why the mixed-clock bug went unnoticed; this fails against the previous implementation on both the success and error paths.
+
 ## v1.26.19
 
 - update Go to 1.26.5 and update dependencies

http_roundtripper-log.go

@@ -6,7 +6,6 @@ package http
 
 import (
 	"net/http"
-	"time"
 
 	libtime "github.com/bborbe/time"
 	"github.com/golang/glog"
@@ -21,11 +20,11 @@ func NewRoundTripperLog(tripper http.RoundTripper) http.RoundTripper {
 		resp, err := tripper.RoundTrip(req)
 		if err != nil {
 			glog.V(2).
-				Infof("%s request to %s in %d ms failed: %v", req.Method, req.URL, time.Since(now).Milliseconds(), err)
+				Infof("%s request to %s in %d ms failed: %v", req.Method, req.URL, libtime.Now().Sub(now).Milliseconds(), err)
 			return nil, err
 		}
 		glog.V(2).
-			Infof("%s request to %s completed with statusCode %d in %d ms", req.Method, req.URL, resp.StatusCode, time.Since(now).Milliseconds())
+			Infof("%s request to %s completed with statusCode %d in %d ms", req.Method, req.URL, resp.StatusCode, libtime.Now().Sub(now).Milliseconds())
 		return resp, nil
 	})
 }

http_roundtripper-log_test.go

@@ -0,0 +1,84 @@
+// Copyright (c) 2026 Benjamin Borbe All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package http_test
+
+import (
+	"net/http"
+	"time"
+
+	libtime "github.com/bborbe/time"
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+
+	libhttp "github.com/bborbe/http"
+)
+
+var _ = Describe("RoundTripperLog", func() {
+	var originalNow func() time.Time
+	var nowCalls int
+	var roundTripper http.RoundTripper
+	var resp *http.Response
+	var err error
+
+	// libtime.Now is a package-level var (time_now.go: `var Now = time.Now`),
+	// so it can be swapped for a fake clock. Counting the calls is what pins the
+	// fix: deriving the duration from libtime calls it twice per request (once
+	// for the start, once inside .Sub), whereas the previous
+	// time.Since(now) form called it only once and took the delta from the
+	// stdlib wall clock. A real-time test cannot tell those apart, which is why
+	// the mixed-clock bug survived.
+	BeforeEach(func() {
+		originalNow = libtime.Now
+		nowCalls = 0
+		libtime.Now = func() time.Time {
+			nowCalls++
+			return time.Date(2026, 8, 12, 10, 0, 0, 0, time.UTC)
+		}
+	})
+
+	AfterEach(func() {
+		libtime.Now = originalNow
+	})
+
+	Context("successful request", func() {
+		BeforeEach(func() {
+			roundTripper = libhttp.NewRoundTripperLog(
+				libhttp.RoundTripperFunc(func(req *http.Request) (*http.Response, error) {
+					return &http.Response{StatusCode: http.StatusOK}, nil
+				}),
+			)
+			req, _ := http.NewRequest(http.MethodGet, "http://example.com/path", nil)
+			resp, err = roundTripper.RoundTrip(req)
+		})
+		It("returns no error", func() {
+			Expect(err).To(BeNil())
+		})
+		It("returns the response", func() {
+			Expect(resp).NotTo(BeNil())
+			Expect(resp.StatusCode).To(Equal(http.StatusOK))
+		})
+		It("derives the duration from libtime, not the wall clock", func() {
+			Expect(nowCalls).To(Equal(2))
+		})
+	})
+
+	Context("failing request", func() {
+		BeforeEach(func() {
+			roundTripper = libhttp.NewRoundTripperLog(
+				libhttp.RoundTripperFunc(func(req *http.Request) (*http.Response, error) {
+					return nil, http.ErrHandlerTimeout
+				}),
+			)
+			req, _ := http.NewRequest(http.MethodGet, "http://example.com/path", nil)
+			resp, err = roundTripper.RoundTrip(req)
+		})
+		It("returns the error", func() {
+			Expect(err).NotTo(BeNil())
+		})
+		It("derives the duration from libtime on the error path too", func() {
+			Expect(nowCalls).To(Equal(2))
+		})
+	})
+})