{"record":{"id":"8f2416b7c2849619","repo":"JuliusBrussee/caveman","slug":"clock-regression","errorCode":"clock_regression","errorMessage":"cachebench: clock regressed while replaying %q","messagePattern":"cachebench: clock regressed while replaying %q","errorType":"exception","errorClass":"ReplayRunError","httpStatus":null,"severity":"error","filePath":"cacheengine/cachebench/replay.go","lineNumber":686,"sourceCode":"}\n\nfunc (runner ReplayRunner) executePrepared(ctx context.Context, item preparedReplay, evidence ReplayEvidenceRecord, started time.Time, now func() time.Time) (ReplayResult, error) {\n\trecord, optimized := item.record, item.optimized\n\tresponse, sendErr := runner.Transport.Send(ctx, ReplayOutbound{\n\t\tRequestID: record.RequestID, Provider: record.Provider, Model: record.Model,\n\t\tRegion: record.Region, Endpoint: record.Endpoint, Body: append([]byte(nil), optimized.Body...),\n\t})\n\tcompleted := now().UTC()\n\tevidence.HTTPStatus = response.StatusCode\n\tif len(response.Body) > 0 {\n\t\tevidence.ProviderEvidenceSHA256 = bodyDigest(response.Body)\n\t}\n\tif completed.Before(started) {\n\t\tevidence.CompletedAt = started.Format(time.RFC3339Nano)\n\t\tevidence.FailureCode = \"clock_regression\"\n\t\treturn ReplayResult{Evidence: evidence, ProviderResponse: append([]byte(nil), response.Body...)}, &ReplayRunError{\n\t\t\tRequestID: record.RequestID, FailureCode: evidence.FailureCode,\n\t\t\tErr: fmt.Errorf(\"cachebench: clock regressed while replaying %q\", record.RequestID),\n\t\t}\n\t}\n\tevidence.CompletedAt = completed.Format(time.RFC3339Nano)\n\tevidence.LatencyMilliseconds = completed.Sub(started).Milliseconds()\n\tif sendErr != nil {\n\t\tevidence.FailureCode = \"transport_error\"\n\t\treturn ReplayResult{Evidence: evidence, ProviderResponse: append([]byte(nil), response.Body...)}, &ReplayRunError{\n\t\t\tRequestID: record.RequestID, FailureCode: evidence.FailureCode,\n\t\t\tErr: fmt.Errorf(\"cachebench: provider transport failed for %q: %w\", record.RequestID, sendErr),\n\t\t}\n\t}\n\tif !validProviderRequestID(response.ProviderRequestID) {\n\t\tevidence.FailureCode = \"provider_response_invalid\"\n\t\treturn ReplayResult{Evidence: evidence, ProviderResponse: append([]byte(nil), response.Body...)}, &ReplayRunError{\n\t\t\tRequestID: record.RequestID, FailureCode: evidence.FailureCode,\n\t\t\tErr: fmt.Errorf(\"cachebench: provider returned invalid request identity for %q\", record.RequestID),\n\t\t}\n\t}","sourceCodeStart":668,"sourceCodeEnd":704,"githubUrl":"https://github.com/JuliusBrussee/caveman/blob/27d5a3981a347890211bb1bf2439e5c821a63bc9/cacheengine/cachebench/replay.go#L668-L704","documentation":"After Transport.Send returned, the completion timestamp (from the injected now function) was strictly before the start timestamp. The harness detects the impossible negative latency and fails the request with FailureCode clock_regression instead of recording corrupt timing evidence.","triggerScenarios":"A custom now function backed by a non-monotonic or mock clock whose value decreases between the two calls; NTP stepping a wall clock backwards mid-request when now is wall-clock based; a fake clock in tests advanced incorrectly.","commonSituations":"Tests injecting a stub clock that returns a fixed or decreasing time; production code passing time.Now while the host clock is stepped backward by NTP; swapping now between runs without resetting.","solutions":["Use a monotonic source for now (wrap time.Now; Go's time.Time carries monotonic reading when obtained via time.Now and compared with Sub).","In tests, make the fake clock strictly non-decreasing across started/completed reads.","If now must be wall-clock, tolerate small backward steps by clamping completed to started instead of failing.","Check host clock synchronization (chrony/ntp) if this reproduces on bare metal."],"exampleFix":"// before\nnow := func() time.Time { return wallClockNow() } // NTP steps it back mid-request\n\n// after\nnow := func() time.Time { return time.Now().UTC() } // monotonic-annotated clock","handlingStrategy":"validation","validationCode":"// monotonic, strictly non-decreasing clock wrapper\nvar last time.Time\nnow := func() time.Time {\n    t := time.Now().UTC()\n    if t.Before(last) { t = last }\n    last = t\n    return t\n}","typeGuard":"func isClockRegression(err error) bool {\n    var rre *cachebench.ReplayRunError\n    return errors.As(err, &rre) && rre.FailureCode == \"clock_regression\"\n}","tryCatchPattern":"if err := runner.Run(ctx, records, emit); err != nil {\n    if isClockRegression(err) {\n        // your injected now went backwards; switch to monotonic clock and re-run\n    }\n    return err\n}","preventionTips":["Always inject time.Now().UTC() (monotonic-annotated) as the now function in production.","In tests, make fake clocks tick forward on every read; never return a constant time.","Keep hosts NTP-disciplined (slew, not step) when wall clocks feed timing evidence."],"tags":["cachebench","clock","timing","replay"],"backgroundTag":null,"analyzedSha":"27d5a3981a347890211bb1bf2439e5c821a63bc9","analyzedAt":"2026-08-15T09:26:11.751Z","schemaVersion":2},"datasetVersion":"2026-08-15T17:31:12.345Z"}