diff --git a/CHANGELOG.md b/CHANGELOG.md index 3ea34a0..487d940 100644 --- a/CHANGELOG.md +++ b/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 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 }) } 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)) + }) + }) +})