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

[bborbe]

Whole-codebase review at a5d735f (settled release v1.26.19) via the repo-review pipeline.

317 mechanical findings from 74 rules across 89 files → 1 confirmed. The confirmed one was not flagged by any rule.

Fixed

S1 — NewRoundTripperLog computes its duration from two different clocks

now := libtime.Now()              // libtime
…
time.Since(now).Milliseconds()    // stdlib wall clock

Against a frozen clock these disagree, so the logged duration is a mixed pair. In production both are real time and the value is correct, which is exactly why nothing caught it. Now libtime.Now().Sub(now), which also drops the stdlib time import.

This surfaced by pattern-matching the identical regression a reviewer caught in bborbe/log#13 an hour earlier — where I had converted a time.Now() write to libtime.Now() and left the paired time.Since() read untouched. http_roundtripper_metrics.go:134 uses time.Now() + time.Since(start), which is uniform stdlib and therefore not affected.

Refuted — 316 of 317

Triage table (auto-refuted before adjudication): 238
no-package-function-calls 82 · no-bare-error-call 81 · suite-test-file-required 31 · slog-not-glog 15 · counterfeiter-mocks-required 13 · counterfeiter-directive-on-interface 11 · subject-under-50-chars 5

Adjudicated and refuted: 78 — the two that mattered:

Finding	n	Why refuted
go-logging/external-call-logs-response	9	NewRoundTripperLog already exists and logs method, URL, status code, duration and errors. The library provides response logging as a composable roundtripper; requiring basic-auth, header, ratelimit, retry, proxy and remove-path-prefix to each log as well would emit duplicate lines per request — the opposite of correct decorator design
go-enum-type/typed-constants-with-collection	13	Same shape as vault-cli's M5, but not the same harm. There the untyped --output value silently fell through to plain output because a validation path compared raw strings. These are output values written into headers and JSON bodies, with no valid-set check to bypass. http is consumed fleet-wide, so retyping exported constants is a breaking change for type-safety hygiene alone

Remainder: new-prefix-constructor-naming 19 (RoundTripperFunc-style adapters), factory rules 8, cancel-check-in-loop 8 (no ctx in scope), list-checks-ctx-done 2 (known anchoring bug), secret-fields-need-display-length 2 (fourth repo where this rule has produced only false positives).

make precommit green (60.2% coverage).

---

Review round 1 — 1 fixed, 1 declined

Fixed in 62d033b — the test finding was correct and worth acting on.

"NewRoundTripperLog has no dedicated test. The bug this PR fixes would not be caught by tests using real time; only a frozen-clock test would expose it."

Exactly right, and it is the second appearance of this bug class today (the first was bborbe/log#13). libtime.Now turns out to be a package-level var (time_now.go: var Now = time.Now), so a fake clock is cheap to install.

The assertion pins the clock source by counting calls: deriving the duration from libtime calls Now 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. A real-time test cannot tell those apart — which is precisely why the bug survived.

Verified against the unfixed code before restoring the fix:

RoundTripperLog successful request [It] derives the duration from libtime, not the wall clock  [FAILED]
RoundTripperLog failing request    [It] derives the duration from libtime on the error path too [FAILED]
FAIL! -- 214 Passed | 2 Failed

Coverage 60.2% → 61.2%.

Declined — go-logging/external-call-logs-response (pre-call boundary log).

The request is to log before tripper.RoundTrip(req) so a hanging call has an anchor. The diagnostic argument is reasonable, but:

1. It doubles log volume for every outbound request in a decorator whose sole purpose is logging. At V(2) that is two lines per request rather than one, fleet-wide.
2. It is out of scope for this PR, which changes how a duration is computed and touches no logging structure — the post-call logging predates it.
3. The rule already fired 9 times across this repo and was refuted for all of them in the PR body above: NewRoundTripperLog is the library's response-logging mechanism, composed into a chain. This finding asks that same single logger to also emit a pre-call line.

Worth considering as its own change with a deliberate decision about log volume; not appropriate to fold into a clock fix.

make precommit green.

---

Review round 2 — both Must Fix findings refuted, no code change

1. "Ginkgo specs will not be discovered… make test exits 0 but runs zero specs" — false.

http_suite_test.go:21 already contains RunSpecs(t, "Test Suite"). Ginkgo needs one suite entry-point per package; every var _ = Describe(...) in the package registers against it.

Direct evidence the specs run:

Ran 216 of 217 Specs   SUCCESS! -- 216 Passed | 0 Failed | 0 Pending | 1 Skipped

The package had 214 before this PR; the 5 new specs bring it to 216 (one pre-existing skip). And when the fix was temporarily reverted to verify the test bites, the runner named them explicitly:

RoundTripperLog successful request [It] derives the duration from libtime, not the wall clock  [FAILED]
RoundTripperLog failing request    [It] derives the duration from libtime on the error path too [FAILED]
FAIL! -- 214 Passed | 2 Failed

This is go-testing/suite-test-file-required, a standing triage-table entry: it evaluates each test file in isolation and does not see a sibling *_suite_test.go.

2. glog import — self-refuting.

The finding's own text: "this project already uses glog elsewhere (so the go-cli/slog-not-glog-in-new-projects exemption applies) … No action required for this PR, but plan a migration to log/slog." Filed under Must Fix (Critical) notwithstanding. A fleet-wide logging migration is not a blocking finding on a duration calculation.

No code change this round. make precommit green; 216 specs passing.

[ben-s-pull-request-reviewer]

Now I have everything I need. Let me compile the full adjudication.

Step 4c-sel CLASSIFY:

Changed files: CHANGELOG.md, http_roundtripper-log.go

The mechanical funnel found 2 MUST findings. For judgment rules — I can't read rules/index.json from this session (path outside allowed dirs), but based on the known rule set and the diff content, the applicable candidates would be go-logging/external-call-logs-response (boundary call to external HTTP client) and go-testing/* rules (no test for the changed function).

Step 4d-sel ADJUDICATE:

• Finding 1: go-cli/slog-not-glog-in-new-projects — The project already uses glog throughout (confirmed by multiple imports). Per the rule's own exemption clause, this is not actionable. Drop (exempt).

• Finding 2: go-logging/external-call-logs-response — tripper.RoundTrip(req) is a boundary call. The code logs after the call (on error or success) but does not emit a log entry at the boundary summarizing method + path + destination before the call. This is a real audit-gap — when the call hangs or behaves unexpectedly, there is no single "outbound HTTP call to X started" line to anchor diagnostics. Must Fix.

• Additional finding: no test file — http_roundtripper-log.go has no dedicated test. The bug this PR fixes (mixed wall-clock + frozen-clock timing) would not be caught by tests using real time; a frozen-clock test would expose it. Should Fix.

---

{
  "verdict": "request-changes",
  "summary": "The mixed-clock fix is correct and the CHANGELOG entry is accurate. However, two issues remain: (1) the boundary HTTP call at line 19 has no pre-call audit log entry, only post-call logging; (2) NewRoundTripperLog has no dedicated test, so the mixed-clock regression could recur.",
  "comments": [
    {
      "file": "http_roundtripper-log.go",
      "line": 19,
      "severity": "major",
      "message": "tripper.RoundTrip(req) is a boundary call but there is no log entry at the boundary summarizing the outbound request (method + URL + destination). The existing log lines are post-call only (after err check and after success), so a hanging or ambiguous call leaves no anchor in the audit trail. Add a log line before the call: method + URL + \"started\". *(rule: go-logging/external-call-logs-response)*"
    },
    {
      "file": "http_roundtripper-log.go",
      "line": 1,
      "severity": "major",
      "message": "NewRoundTripperLog has no dedicated test file. The bug this PR fixes — mixing libtime.Now() with time.Since() — would not be caught by tests using real wall-clock time; only a frozen-clock test would expose that class of regression. Add a test using the time-testutil pattern (libtime.FakeClock or equivalent) to verify duration is computed from a single consistent clock source. *(rule: go-testing/test-file-missing)*"
    }
  ],
  "concerns_addressed": [
    "correctness: mixed-clock bug in http_roundtripper-log.go fixed — now uses libtime.Now().Sub(now) consistently",
    "tests: no dedicated test file for NewRoundTripperLog — still open, would need frozen-clock test to prevent regression"
  ]
}

superseded by new automated review

[ben-s-pull-request-reviewer]

Now I have all the information needed. Let me do the Step 4c-sel CLASSIFY and Step 4d-sel ADJUDICATE in-session.

STEP 4c-sel CLASSIFY:

The judgment rules applicable to the changed files (CHANGELOG.md, http_roundtripper-log.go, http_roundtripper-log_test.go) are:

1. changelog/conventional-prefix-required — CHANGELOG.md changed → applicable (prefixes are fix: and test: — both valid)
2. go-doc/comment-starts-with-name — **/*.go changed → applicable (has doc comment)
3. go-doc/exported-item-must-have-comment — **/*.go changed → applicable (has comment)
4. go-licensing/source-file-header-required — **/*.go changed → skipped (new test file has header; existing http_roundtripper-log.go header already present)
5. go-licensing/copyright-year-discipline — **/*.go changed → skipped (new file, current year, not bulk update)
6. markdown-todo/lowercase-x-for-complete — **/*.md changed → skipped (no [x] checkboxes in CHANGELOG)
7. go-testing/suite-test-file-required — mechanical in index but MUST for this PR
8. All other rules with **/*.go triggers → skipped (the diff is a tiny bugfix — no architecture, no FSM, no service impl patterns, no metrics, no prometheus, etc.)

STEP 4d-sel ADJUDICATE:

The mechanical findings are authoritative. Let me verify the go-logging/external-call-logs-response finding — the diff shows log statements ARE present immediately after the RoundTrip call, so this is a false positive from the ast-grep pattern (it flags the bare call, not the nearby log). The rule is satisfied.

Now I'll write the consolidated report and verdict JSON.

---

PR Review Report

Changed files: CHANGELOG.md, http_roundtripper-log.go, http_roundtripper-log_test.go

Must Fix (Critical)

• http_roundtripper-log.go:10 — github.com/golang/glog is imported. While this project already uses glog elsewhere (so the go-cli/slog-not-glog-in-new-projects exemption applies), glog's init() pollution and unstructured output are still a long-term debt. No action required for this PR, but plan a migration to log/slog. (rule: go-cli/slog-not-glog-in-new-projects)
• http_roundtripper-log_test.go — Ginkgo specs (the var _ = Describe(...) block) will not be discovered by go test without a companion *_suite_test.go containing RunSpecs(t, "Suite"). make test exits 0 but runs zero specs. Create http_roundtripper-log_suite_test.go with the standard Ginkgo suite entry-point. (rule: go-testing/suite-test-file-required)

Should Fix (Important)

None.

Nice to Have (Optional)

None.

Selector Mode Traceability

• Candidates: ~30 judgment rules matched by Step 4b-i glob filter
• Applicable: 3 rules selected by Step 4c-sel (changelog prefix, go-doc comment, go-licensing header)
• Skipped (one line each):
  • go-doc/comment-starts-with-name → comment present, first word is NewRoundTripperLog matching identifier
  • go-doc/exported-item-must-have-comment → comment exists, rule satisfied
  • go-licensing/source-file-header-required → new file has header; existing file unchanged
  • go-licensing/copyright-year-discipline → new file, current year 2026, not bulk update
  • markdown-todo/lowercase-x-for-complete → no [x] checkbox syntax in CHANGELOG
  • All other **/*.go judgment rules (FSM, service impl, prometheus, etc.) → diff is a small bugfix, none of those domains are touched

Precommit: skipped (selector mode) — CI covers lint+test.

Notes:

• The go-logging/external-call-logs-response mechanical finding at line 19 is a false positive — the log statement is on the very next line (glog.V(2).Infof(...)), which satisfies the rule's intent. The ast-grep pattern cannot trace across lines.
• The fix is correct: libtime.Now().Sub(now) ensures both time samples come from the same clock source. The new test pins this by counting libtime.Now invocations (expects 2 per request).
• The concern about http_roundtripper_metrics.go:134 using time.Now() + time.Since(start) uniformly with stdlib is out of scope for this PR but worth tracking as a follow-up.

---

Verdict JSON:

{
  "verdict": "request-changes",
  "summary": "The mixed-clock bugfix is correct and well-tested, but the new Ginkgo test file lacks a `*_suite_test.go` entry-point so its specs will never be discovered. One glog import flagged as long-term debt (no action needed in this PR given the project's existing glog usage).",
  "comments": [
    {
      "file": "http_roundtripper-log_test.go",
      "line": 1,
      "severity": "critical",
      "message": "Ginkgo specs (var _ = Describe(...)) will not be discovered by go test without a companion *_suite_test.go with RunSpecs. make test exits 0 with zero specs run. Create http_roundtripper-log_suite_test.go with the standard Ginkgo TestSuite entry-point. (rule: go-testing/suite-test-file-required)"
    },
    {
      "file": "http_roundtripper-log.go",
      "line": 10,
      "severity": "major",
      "message": "github.com/golang/glog imported. Existing projects mid-migration are exempt from go-cli/slog-not-glog-in-new-projects, but glog's init() flag pollution and unstructured output remain a long-term debt. Plan migration to log/slog. (rule: go-cli/slog-not-glog-in-new-projects)"
    }
  ],
  "concerns_addressed": [
    "correctness: mixed-clock duration fixed in http_roundtripper-log.go:23 and :27 using libtime.Now().Sub(now)",
    "correctness: http_roundtripper-metrics.go:134 not addressed — separate issue, out of scope for this PR",
    "tests: test file added but suite entry-point missing — raised as Must Fix above"
  ]
}