From 40cc7235b3a18b2653c2475ab8d98390223388d3 Mon Sep 17 00:00:00 2001 From: Benjamin Borbe Date: Wed, 12 Aug 2026 23:30:52 +0200 Subject: [PATCH 1/2] fix: measure roundtripper duration with libtime, not time.Since NewRoundTripperLog started its timer with libtime.Now() but measured the elapsed time with time.Since(now). Against a frozen clock those are two different clocks, so the logged duration came from a mixed pair. Now libtime.Now().Sub(now), which also drops the stdlib time import. Found by repo-review at a5d735f. No rule flagged it -- it surfaced by pattern-matching the identical regression a reviewer caught in bborbe/log#13 an hour earlier. --- CHANGELOG.md | 4 ++++ http_roundtripper-log.go | 5 ++--- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3ea34a0..9ee93d5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ 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)`. + ## v1.26.19 - update Go to 1.26.5 and update dependencies diff --git a/http_roundtripper-log.go b/http_roundtripper-log.go index 9f486bd..2c0769c 100644 --- a/http_roundtripper-log.go +++ b/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 }) } From 62d033b6cd1875f11b5d3f1429efdeca7cc34c7c Mon Sep 17 00:00:00 2001 From: Benjamin Borbe Date: Wed, 12 Aug 2026 23:57:58 +0200 Subject: [PATCH 2/2] test: pin the roundtripper duration to libtime with a fake clock libtime.Now is a package-level var (time_now.go: var Now = time.Now), so a test can swap it. Counting the calls is what pins the fix: deriving the duration from libtime calls it twice per request (start, then inside .Sub), whereas the previous time.Since(now) form called it once and took the delta from the stdlib wall clock. Verified against the unfixed code before restoring: 2 failed, 214 passed, on both the success and error paths. Addresses the review's second finding on #9. --- CHANGELOG.md | 1 + http_roundtripper-log_test.go | 84 +++++++++++++++++++++++++++++++++++ 2 files changed, 85 insertions(+) create mode 100644 http_roundtripper-log_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 9ee93d5..487d940 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,7 @@ Please choose versions by [Semantic Versioning](http://semver.org/). ## 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 diff --git a/http_roundtripper-log_test.go b/http_roundtripper-log_test.go new file mode 100644 index 0000000..2dba5e4 --- /dev/null +++ b/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)) + }) + }) +})