From e961836fb0829e685c36da03ff33f443ab88bbcb Mon Sep 17 00:00:00 2001 From: forever Date: Tue, 6 Oct 2026 11:14:29 -0700 Subject: [PATCH] usage, gateway, gui, provider, cli: the tests pass when a run crosses midnight, and a usage answer reads the clock once (#1046) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * usage: the usage tests pass at any time of day, midnight included The usage tests stamped their calls with the machine's time and then asked for today, 7 or 30 days, or a cached answer, which the code worked out from its own time.Now a moment later. A minute after midnight a call made "a minute ago" was yesterday's, and when midnight fell between the test's read and the code's, the call and the period were of two days. magpie usage, the TUI's Usage page, the two Codex cache-write tests and the computers' shared days failed in the first minutes after midnight (the TUI's after midnight UTC, the zone its package's tests run in since 1caea638), and 28 more failed when midnight fell inside them. usage.Clock is now the time every period is read by: the start of today, 7 days and 30 days (LedgerOf, Summarize, Direct, QueryPage), the hours or days of the chart (LedgerSeries, QueryPage), the day a cached summary or page is for, the time Append gives a call that has none, the days davsync shares and the date in an exported CSV's name. It is time.Now, as before, and a variable for the tests, like LogCalls. Each test that built its calls from the time now holds Clock at noon on 2026-09-30 (holdClock; holdUsageClock in gui and the CLI; three lines in tui and davsync) and stamps its calls from that instant, among them TestReasoningReplyTimedByItsAnswer, whose timeline rows 117b6c7f made at time.Now. TestPeriodsReadTheClock checks that every one of these reads goes through Clock. TestQueryPageSourceAndIdentityInvalidation is held too; that it fails when run alone is fixed apart from this, in #1045. Seven held tests could not fail at midnight before, and are held so that the tests read one clock: TestUsageSameSizeAndMtimeRewrite (All's totals), TestDirectCountsOnlySessionFileCalls (30 days around its own noon), TestQueryPageIOOutsideCacheLock (a file two days old), gui's TestUsageLedgerDayRoutes (7 days hold its calls from either day), TestLedgerSingleSnapshotAndLocalSession and TestLedgerNamesModelAtProvider (their calls are stamped after the code reads the time), and TestUsageRawAndPricedChunksShareBudget, which fails only when the midnight in it starts a new week of All's chart, on a Sunday night; at.sh sets the time of day and not the weekday, so that one was not shown. Verified with at.sh, a scratch script that runs a test binary under a zone made with zic, so that the local time of day is the one asked for as the run starts (HOME in a sandbox, Go's caches pinned). The runs were first made on c5a54bc7, and those marked (698da36f) again on 698da36f, with the same results. The tui package runs in UTC since 1caea638, a zone at.sh doesn't move, so its runs on 698da36f used copies of both trees whose TestMain keeps the zone TZ sets. Before, at 00:00:30, 00:01:30 and 12:00:00 (698da36f): TestUsageShowsCallsNotThroughMagpie, 00:00:30: usage_cli_test.go:95: no calls today · route an agent through magpie and its usage shows up here 00:01:30: "5 tokens today · 1 call · no price", without the calls not through magpie; TestUsagePageShowsCallsNotThroughMagpie (tui) fails the same two ways at usage_test.go:138 --- FAIL: TestCodexCacheWriteNotInInput (00:00:30) codex_cache_write_test.go:104: rows [] --- FAIL: TestCodexCacheWriteMatchesGatewayCall (00:01:30) codex_cache_write_test.go:73: filter {...}: 0 rows, 0 calls, want the gateway's 2: [] --- FAIL: TestUsageSharedBetweenComputers (00:01:30) usage_share_test.go:134: a's days on the server: [...-2026-10-05 ...-2026-10-06 ...-2026-10-07] 12:00:00: PASS Midnight inside a test, in scratch copies of the head. Started at 23:59:59.3 with the code's first period read held 1.5s, so that it reads after midnight what the test stamped before it, 16 usage tests, 3 gui tests and TestUsageCSV FAIL, among them ledger_test.go:257: today: 0 review_test.go:69: chart counted 0 incremental_log_test.go:202: concurrent append lost TestCachedSummaryRemainsCallerOwned: panic: runtime error: index out of range [0] with length 0 usage_test.go:121: second page: {... Period:today Rows:[] ... Total:0 ...} usage_test.go:311: "": magpie-requests-7d-2026-10-06 Started at 23:59:55 with the test waiting past midnight between two of its reads, 7 more FAIL: request_day_test.go:45: selecting a day changed the chart or its legend cache_bounds_test.go:84: uncached today summary stale growing_rewrite_test.go:71: today summary stale cache_bounds_test.go:153: page key changed instead of exercising the same cache priced_blocks_test.go:55, caller_provider_test.go:129 and :172: page differs TestReasoningReplyTimedByItsAnswer, with a scratch 1.5s sleep before its LedgerSeries, started at 23:59:59.3 (698da36f): usage_test.go:255: part: {Calls:0 Tokens:0 Cost:0 Timed:0 TTFT:0 DecodeMs:0 DecodeOut:0} After: the same at.sh runs PASS at 00:00:30, 00:01:30 and 12:00:00 (698da36f); the same scratch copies made of this change PASS, each test taking 1.5s or 5.2s, so midnight did fall inside it (698da36f for TestReasoningReplyTimedByItsAnswer's); and every changed test PASS at 23:59:59.9, 00:00:30 and 12:00:00 (698da36f). Without the change (698da36f): with the reads put back on time.Now, 21 usage tests, 6 gui, 2 CLI, the tui and the davsync test fail, among them --- FAIL: TestPeriodsReadTheClock clock_test.go:55: Direct(Today): 0 calls since 2026-10-06 00:00:00 -0700 PDT, want 1 since 2026-09-30 00:00:00 -0700 PDT clock_test.go:63: Summarize(Today) the next day: 1 calls, want 0 --- FAIL: TestReasoningReplyTimedByItsAnswer usage_test.go:255: part: {Calls:0 Tokens:0 ...} Each of the eleven reads put back alone fails a test: TestPeriodsReadTheClock for the nine in usage (LedgerSeries: "clock_test.go:52: LedgerSeries(Today): 0 calls, want 2"; the page's cache key: "clock_test.go:66: QueryPage(Today) the next day: 1 rows, want 0"), TestCSVStamp for the CSV's name (usage_test.go:325: "": magpie-requests-7d-2026-10-06) and TestUsageSharedBetweenComputers for davsync (usage_share_test.go:224: all computers: 4 rows, 707 in; want 5, 737). On this commit: go test -tags nogui -count=1 . ./internal/usage ./internal/tui ./internal/davsync ./internal/gui ok; -race -count=20 over the changed tests of each of these packages ok; gofmt -l prints nothing, and go vet -tags nogui on the five packages finds nothing. * usage: pages, CSVs and magpie usage asked at midnight show one day An answer about usage read the time more than once. The Requests page read it for the day it is kept for, for the period its log and session files are read over, for the period of its rows and for its chart's hours; the page from the ledger (QueryPage's path when LogCalls is set, as in the tests) for its rows and for its chart; Direct for its period and for its rows; a CSV for its rows and for its name; magpie usage and the TUI's Usage page for Summarize and then for Direct. Most of these reads have the log and the session files read between them, seconds on a large log, and when midnight fell between two of them the answer was of two days: yesterday's calls listed over today's empty chart, Direct starting yesterday and counting none of yesterday's calls, the calls not through magpie left out of magpie usage and the Usage page (they were the new day's, none yet), and yesterday's calls saved as magpie-requests-today-.csv. Each answer now reads Clock once and passes that moment down. queryPage reads it for its key, its sources, its rows and its chart (buildRequestBlocks takes it); the page from the ledger reads its rows and its chart at it (LedgerOfAt, ledgerSeriesAt); Direct reads the ledger at the moment of its period. usage.Summaries(p) is Summarize(p) and Direct(p) at one moment, and magpie usage and the TUI's Usage page, when a period is picked and when it is read again, ask for it: one exported name, the clock left inside usage and one line changed at each caller, where SummarizeAt and DirectAt would be two names and each caller would read the clock itself. The CSV download and export read their rows with the new usage.LedgerOfAt at the moment their file is named for, which csvStamp now takes; the rows and the name are read in two packages, so LedgerOfAt is exported. LedgerOf, LedgerSeries, Summarize, Direct and QueryPage keep their signatures, each reading Clock once. The new tests set Clock to read a tenth of a second before midnight the first time and a tenth of a second after it from then on, set again for each answer. The midnight is the one that starts 2026-10-01, local time: a past instant, at midnight because that is what is tested, and the day before it is the 2026-09-30 the held tests use. TestAnswerReadsTheClockOnce asks QueryPage(Today) from the indexed log and from the ledger: its 3 rows, one from a session file written that day at 23:00, are under that day's chart, and asked again after midnight the page is the next day's, not the one kept for the day before; Direct(Today) counts the call and starts that day. TestUsageAskedAtMidnight (magpie usage today), TestUsagePageAtMidnight (the TUI's Usage page, today picked and read again) and TestUsageCSVAtMidnight (download and export) check that the calls through magpie and those not through it, or the rows and the file's name, are of the day asked on. TestCSVStamp passes its time. Verified on the previous commit, at.sh as there. The runs were first made on c5a54bc7, when the tui package's tests still ran in the local zone, and those marked (698da36f) again on 698da36f, with the same results. Before: the new tests on the previous commit, at any time of day (at.sh at 12:00:00 too) (698da36f): --- FAIL: TestAnswerReadsTheClockOnce clock_test.go:131: QueryPage(Today): 0 rows, 0 in a chart from 2026-10-01 00:00:00 -0700 PDT; want 3 under one from 2026-09-30 00:00:00 -0700 PDT clock_test.go:141: QueryPage(Today): 3 rows, 0 in a chart from 2026-10-01 ...; want 3 under one from 2026-09-30 ... clock_test.go:145: Direct(Today): 0 calls since 2026-09-30 00:00:00 -0700 PDT, want 1 since 2026-09-30 00:00:00 -0700 PDT --- FAIL: TestUsageAskedAtMidnight usage_cli_test.go:154: 5 tokens today · 1 call · no price ..., with no part for the calls not through magpie --- FAIL: TestUsagePageAtMidnight usage_test.go:184: today picked: ... (the same) usage_test.go:187: read again: ... --- FAIL: TestUsageCSVAtMidnight usage_test.go:367: download: 200, attachment; filename="magpie-requests-today-2026-10-01.csv" with 2 rows (), want magpie-requests-today-2026-09-30.csv with 2 usage_test.go:378: export: 200 {"path":"~/Downloads/magpie-requests-today-2026-10-01.csv", "rows":1}, want magpie-requests-today-2026-09-30.csv with 1 row With the real clock, in scratch copies of both trees: scratch tests held one of Clock's reads 1.5s after it was made, as reading a large log does (the first; for one of them the page's third, its chart's), and at.sh started each at 23:59:59.3. Before, all 9 FAIL, among them asked 23:59:59.564, answered 00:00:01.068 Direct(Today): 0 calls since 2026-10-05 00:00:00 -0940 MID, want 1 since 2026-10-05 00:00:00 -0940 MID QueryPage(Today): 2 rows, 0 in a chart from 2026-10-06 ...; want 2 under one from 2026-10-05 ... download: attachment; filename="magpie-requests-today-2026-10-06.csv" with a call of 2026-10-05 23:59 After, all 9 PASS, answered at 00:00:00.9 to 00:00:01.0, so midnight fell inside each, except the chart's: its held read is gone with the change. A scratch sleep before the chart shows that one: before "2 rows, 0 in a chart from 2026-10-06", after PASS, asked 23:59:59.344 and answered 00:00:00.941. At 12:00:00 all of them PASS in both trees. After: every changed test PASS with at.sh at 23:59:59.9, 00:00:30 and 12:00:00 (698da36f). Without the change (698da36f): with the production put back to the previous commit's (gui/usage.go only so far that TestCSVStamp compiles: csvStamp takes the time, read apart from the rows as before), go test -count=1 . ./internal/usage ./internal/tui ./internal/gui fails the four new tests and no other, with the lines above. Each of the 16 places put back alone fails one of them: the page's key (clock_test.go:134: "3 rows, 3 in a chart from 2026-09-30 ...; want 0 under one from 2026-10-01 ..."), its sources (:131: "2 rows"), its rows (:131: "0 rows"), its chart (:131), the ledger page's rows and chart (:141), LedgerOfAt (:141, :145), ledgerSeriesAt (:141), Direct (:145); Summaries, indexedSummary and magpie usage (usage_cli_test.go:154); Summaries and the TUI's period key and reload (usage_test.go:184, :187); the CSV's download and export (usage_test.go:367, :378). On this commit: go test -tags nogui -count=1 . ./internal/usage ./internal/gui ./internal/tui ./internal/davsync ./internal/gateway ok; -race -count=20 over the changed tests of each package ok; gofmt -l prints nothing, and go vet -tags nogui finds nothing. * gateway: the key-limit tests pass when a run crosses local midnight A go test run that crossed local midnight could fail the gateway's key-limit tests. keyLimited and the /v1/magpie/limit endpoint each read time.Now() when they check a key, and access.Window turns that into a calendar window (a day from midnight, a week from Monday, a month from the 1st). The tests seed "yesterday" from their own time.Now() and then make several calls, so a run that crossed midnight saw its calls split over two windows: the second call of a 350-token day was let in, or a restart counted nothing. The gateway's key-limit path now reads limitClock, a variable for the tests like ruleClock and idClock, and production behaviour is unchanged (it is time.Now). TestKeyLimitRefusesBeforeUpstream, TestKeyLimitHoldsParallelRequests and TestKeyLimitWindowResets pin it at 2026-09-30 12:00 local and seed "yesterday" from that instant. Calls are still recorded at the real time, after the pinned one, and a window counts every call from its start, so they all count in the pinned window; the "tomorrow's window" check in TestKeyLimitWindowResets stays on the real now, the first window with none of those calls in it. No other test sets a key limit with records in its window (the gateway-key CLI test and the GUI caller-key tests count 0 calls or have no limit). TestKeyLimitRefusesBeforeUpstream now also checks that the 429's Retry-After and X-Magpie-Limit-Reset name the next midnight after the check, and that the limit endpoint's week starts on the pinned Monday. Verified with at.sh, a scratch script that runs the test binary under a zone made with zic, so that the local time of day is the one asked for as the run starts: - before, at.sh at 23:59:59 with COUNT=500/300 and FRAC 0.3/0.6/0.8: 3 of 6 runs of each test failed with key_limit_test.go:217: spent key let in key_limit_test.go:117: a restart forgot what the key used 200 key_limit_test.go:121: status &{Period:day Start:2026-10-06 ... Calls:0 Tokens:0 ...} - after, the same 6 runs (COUNT=500, both tests) print PASS, and so do ^TestKeyLimit at 12:00:00 and 00:00:00 with COUNT=20. - go test -tags nogui -count=1 ./internal/gateway: ok (79.5s); -race -count=20 -run '^TestKeyLimit' ./internal/gateway: ok. - gofmt -l prints nothing; go vet -tags nogui ./internal/gateway is clean. The month boundary (TestKeyLimitHoldsParallelRequests) and Monday can't be reproduced by changing the time of day; the pinned clock covers them the same way. Fails without the change (tests pinned, keyLimited back on time.Now): --- FAIL: TestKeyLimitRefusesBeforeUpstream key_limit_test.go:107: headers map[... Retry-After:[80228] X-Magpie-Limit-Reset:[2026-10-07T00:00:00-07:00] ...] and with only the limit endpoint back on time.Now: --- FAIL: TestKeyLimitRefusesBeforeUpstream key_limit_test.go:159: limit endpoint {... "period":"week", "start":"2026-10-05T00:00:00-07:00" ...} * gateway: the routing history tests pass when a run crosses midnight TestHistoryKeepsDaysAndDropsOld and TestRemoteMagpieGroupHistory took now := time.Now() and saved routes at now and now+1s. saveRoute files a route by its own day (r.Time.Local()), so a test started at 23:59:59 put the +1s route in tomorrow's file and History(today) found one route less. TestHistoryKeepsSessionAndTokenTiers raced the other clock: saveRoute prunes by time.Now(), so when the day turned between the test's time.Now() and the first saveRoute, the prune gzipped "today" after the first route, the second went to a new .jsonl, and the test's own pruneHistory gzipped that over the first .gz, losing route 1. saveRoute now prunes by historyClock (time.Now outside the tests). The three tests take historyNoon(t), which holds that clock at 2026-09-30 12:00 local and returns it as their now, restored with t.Cleanup. Every route, day file and prune is then on that one past day. The fixture can't be a fixed past day without the clock: pruning by the real today gzips that day's file at once (and, a month on, drops it as too old). The other history tests keep the real clock: TestHistoryRouteOutsideDayLimit writes its day files itself from one now and the code under test reads no clock, and TestHistoryRouteDayAndNoLock already uses a fixed day. Verified with at.sh, a scratch script that sets the local time of day through a zone made with zic as the run starts: - before, at.sh ./internal/gateway at 23:59:59: --- FAIL: TestHistoryKeepsDaysAndDropsOld history_test.go:50: days [{2026-10-06 1} {2026-10-05 1} {2026-10-04 1}] --- FAIL: TestRemoteMagpieGroupHistory remote_group_served_test.go:144: routes [... only ID 1 ...] and, with a 2s sleep after now := time.Now() standing in for the turn of the day, --- FAIL: TestHistoryKeepsSessionAndTokenTiers history_test.go:22: compressed history lost accounting: [only ID 2] 12:00:00 control: PASS. - after: the three tests PASS at 23:59:59, 23:59:59.9 (FRAC=0.9), 12:00:00, and 23:59:59 with the same 2s sleep; all TestHistory* and TestRemoteMagpieGroupHistory PASS at 23:59:59 with -test.count=3. - with saveRoute pruning by time.Now() again (the fixtures still pinned), at any time of day: --- FAIL: TestHistoryKeepsSessionAndTokenTiers history_test.go:32: compressed history lost accounting: [only ID 2] - go test -tags nogui -count=1 ./internal/gateway: ok; -race -count=20 on the three tests: ok; gofmt -l and go vet -tags nogui ./internal/gateway print nothing. * gateway, davsync: the request archive tests pass when a run crosses UTC midnight The archive names a call "/" from the call's own start, in UTC (archiving in archive.go). TestArchiveOn read time.Now().UTC() before posting and TestRequestArchiveToS3 read it before post(), and each expected that read's date. A run where UTC midnight (17:00 PDT) fell between the test's read and the request's start expected the day before the one the archive used, and failed. Both tests now take the date from the Time the call carries (s.Recent()[0].Time, the same start the archive's name is made from), in UTC, so nothing is read from the clock a second time. No production code changes. The other archive tests already go by the call's Archive name, and internal/gui's archive test uses a fixed name; no other test in internal/gateway, internal/davsync or internal/gui predicts an archive key or a UTC-dated name from its own clock. Verified: at.sh only moves the local time of day, and this is a UTC crossing (UTC midnight was ~16h away), so it was shown in a scratch copy whose serve starts each request 0.2s after the next UTC midnight, as a request does when the test read the clock just before it. There the old tests fail: archive_test.go:115: call archive "2026-10-07/000000-f4690de23ee8a859", want "2026-10-06/000000-f4690de23ee8a859" archive_test.go:93: nothing at "team x+y/magpie/archive/2026-10-06/000000-0e74a87816ef6a56.json" and the new ones pass. Unshifted, under at.sh at local 23:59:59, 00:00:00 and 12:00:00, both pass, as the old ones do at 23:59:59 and 00:00:00 (local time doesn't enter the name). With archiving naming by start.Format (local) instead of start.UTC().Format, both new tests fail under at.sh at local 23:00:00, where the local date is a day behind UTC's: --- FAIL: TestArchiveOn ... archive_test.go:116: call archive "2026-10-05/082500-7322712bd89f71da", want "2026-10-06/082500-7322712bd89f71da" --- FAIL: TestRequestArchiveToS3 ... archive_test.go:95: nothing at "team x+y/magpie/archive/2026-10-06/082500-3587ab4192da2cd5.json" and pass at 12:00:00. go test -tags nogui -count=1 ./internal/gateway ./internal/davsync passes in a sandbox HOME; -race -count=20 -run '^(TestArchiveOn|TestRequestArchiveToS3)$' passes; gofmt -l and go vet -tags nogui on both packages are clean. * gui: TestWhatsNewTodayRoute passes when the run crosses local midnight TestWhatsNewTodayRoute posts {"on":true} to /api/whatsnew/today, which writes today() to whatsnew-quiet-day, then checks quietToday(), which compares the file with a second today(). A run that crossed local midnight between the two read different days and failed with "on: 204 false". The neighbouring TestWhatsNewQuietAfterRestartToUpdate already pins today; this test didn't. The test now pins today to 2026-09-30 (restored with t.Cleanup), so the post and the check read the same day. The other What's new tests start from an empty folder, so quietToday finds no file and never reads today(). Verified: with a temporary 1s sleep between the post and the check, the unpinned test under at.sh (local time of day set by a zone) started at local 23:59:59.5 failed with "whatsnew_test.go:237: on: 204 false" and passed at 12:00:00; pinned, it passes at 23:59:59.5 (same sleep), and, without the sleep, at 23:59:59, 00:00:00 and 12:00:00. With setQuietToday writing time.Now().Format("2006-01-02") instead of today(), the test fails: "--- FAIL: TestWhatsNewTodayRoute ... whatsnew_test.go:239: on: 204 false". go test -tags nogui -count=1 ./internal/gui passes in a sandbox HOME; -race -count=20 -run '^TestWhatsNewTodayRoute$' passes; gofmt -l and go vet -tags nogui ./internal/gui are clean. * provider: TestZCodeStartSentAsTheApp passes when the run crosses midnight A ZCode Start Plan request opens with a context prefix that says "Today's date is " (zcodeDateReminder), the day zcodeStartRequest took from its own time.Now(). TestZCodeStartSentAsTheApp sent the request, then built the expected prefix from a second time.Now(). A run that crossed midnight between the two failed on "the context prefix", the request holding the day before. zcodeStartRequest now takes the time from zcodeClock (a package variable, time.Now outside tests, as gateway's ruleClock), and the test pins it to 2026-09-30 12:00 local, restored with t.Cleanup, and expects "Today's date is 2026-09-30." The test sets TZ=Asia/Shanghai, which moves time.Local only when nothing has read it yet; a mid-day instant in time.Local formats to the same day either way. The other calls to zcodeStartBody in the test check shaping only, not the day. No other provider test builds a day string from a second clock: the WorkBuddy credits, daily warm-up and check-in tests pass fixed times to code that takes now as an argument, and TestQoderCheckinOnTheCard's day is only carried, not compared. Verified with at.sh (local time of day set by a zone, run as -run '^(TestDailyCredits|TestZCodeStartSentAsTheApp)$' so that time.Local is read before the test's t.Setenv("TZ"), as in a full run; alone, Local becomes Asia/Shanghai): with a temporary 1s sleep after the request, the unpinned test started at local 23:59:59.5 failed with "zcode_client_test.go:195: the context prefix: ... Today's date is 2026-10-05." and passed at 12:00:00; pinned, it passes at 23:59:59.5 (same sleep) and, without the sleep, at 23:59:59, 00:00:00 and 12:00:00. With zcodeStartRequest back on time.Now(), the pinned test fails: "--- FAIL: TestZCodeStartSentAsTheApp ... zcode_client_test.go:196: the context prefix: ... Today's date is 2026-10-06." go test -tags nogui -count=1 ./internal/provider passes in a sandbox HOME; -race -count=20 -run '^TestZCodeStartSentAsTheApp$' passes; gofmt -l and go vet -tags nogui ./internal/provider are clean. * accounts, quota: a window's reset reads against one time per listing; TestQuotaCell passes across midnight quotaCell, a window in `magpie accounts` and `magpie quota`, read the clock three times: whether the reset had passed, how long until it, and ResetClock's label, which names the calendar day ("tomorrow 02:13" or "02:13"). TestQuotaCell set the reset 2h13m30s from time.Now() and built the expected label from yet another time.Now(); a run that crossed local midnight between quotaCell's read and the test's got "tomorrow 02:13" from one and "02:13" from the other and failed. quotaCell now takes now. accountsCmd and quotaCmd take one time.Now() just before printing and pass it to every window's cell, so a listing's windows agree on what "today" is. The test passes a fixed 2026-09-30 12:00 local and expects "↻2h13m 14:13", and for a reset the next day "↻14h13m tomorrow 02:13"; no zone in tzdata 2026c changes its clock between those instants, so both read the same in any TZ. resetsCell's label, quotaReadingCell's expired check and quotaResetCmd's prompt still read time.Now(); no test compares them against a second clock. internal/tui's quotaCell and quotaLines already take now, and their tests pass a fixed one. Verified with at.sh (local time of day set by a zone): with a temporary 1s sleep between quotaCell and the check, the old test started at local 23:59:59.5 failed with "accounts_cli_test.go:128: \"5h 42% ↻2h13m tomorrow 02:13\"" and passed at 12:00:00; the new one passes at 23:59:59.5 (same sleep) and, without the sleep, at 23:59:59, 00:00:00 and 12:00:00. Putting any of quotaCell's three reads back on the wall clock fails the test ("--- FAIL: TestQuotaCell"). ResetClock's now alone fails the next-day case: "accounts_cli_test.go:134: tomorrow: \"7d 42% ↻14h13m 02:13\"". The passed check alone, or all three: "accounts_cli_test.go:129: \"5h 42% · reset time passed Sep 30 14:13\"". untilShort alone: "accounts_cli_test.go:129: \"5h 42% ↻now 14:13\"". go test -tags nogui -count=1 . passes in a sandbox HOME; -race -count=20 -run '^TestQuotaCell$' passes; gofmt -l and go vet -tags nogui . are clean. --- accounts_cli.go | 11 +- accounts_cli_test.go | 15 +- internal/davsync/archive_test.go | 4 +- internal/davsync/usage.go | 2 +- internal/davsync/usage_share_test.go | 7 +- internal/gateway/archive_test.go | 9 +- internal/gateway/history.go | 10 +- internal/gateway/history_test.go | 15 +- internal/gateway/key_limit.go | 9 +- internal/gateway/key_limit_test.go | 32 +++- internal/gateway/remote_group_served_test.go | 2 +- internal/gui/usage.go | 18 ++- internal/gui/usage_purpose_test.go | 2 +- internal/gui/usage_test.go | 82 ++++++++++- internal/gui/whatsnew_test.go | 4 + internal/provider/zcode_client_test.go | 7 +- internal/provider/zcode_start.go | 6 +- internal/tui/pages.go | 2 +- internal/tui/tui.go | 2 +- internal/tui/usage_test.go | 47 +++++- internal/usage/cache_bounds_test.go | 12 +- internal/usage/caller_provider_test.go | 4 +- internal/usage/clock_test.go | 147 +++++++++++++++++++ internal/usage/codex_cache_write_test.go | 7 +- internal/usage/direct.go | 12 +- internal/usage/direct_test.go | 3 +- internal/usage/growing_rewrite_test.go | 7 +- internal/usage/incremental_log_test.go | 16 +- internal/usage/ledger.go | 21 ++- internal/usage/ledger_test.go | 13 +- internal/usage/priced_blocks_test.go | 1 + internal/usage/purpose_test.go | 3 +- internal/usage/request_day_test.go | 2 +- internal/usage/request_index_review_test.go | 2 +- internal/usage/request_page.go | 29 ++-- internal/usage/request_page_test.go | 11 +- internal/usage/review_test.go | 2 +- internal/usage/summary_cache.go | 3 +- internal/usage/summary_cache_test.go | 10 +- internal/usage/usage.go | 4 +- internal/usage/usage_test.go | 7 +- quota_cli.go | 3 +- usage_cli.go | 9 +- usage_cli_test.go | 56 ++++++- 44 files changed, 551 insertions(+), 119 deletions(-) create mode 100644 internal/usage/clock_test.go diff --git a/accounts_cli.go b/accounts_cli.go index ed1d13de..7dd3c16a 100644 --- a/accounts_cli.go +++ b/accounts_cli.go @@ -169,6 +169,7 @@ func accountsCmd(args []string) error { for _, r := range rows { width = max(width, len(r.User)) } + now := time.Now() // one instant for every window's reset time for _, r := range rows { mark := " " switch { @@ -183,7 +184,7 @@ func accountsCmd(args []string) error { } line := fmt.Sprintf("%s%-7s %-*s %s", mark, r.Agent, width, r.User, muted.Render(fmt.Sprintf("%-8s", plan))) for _, w := range r.Windows { - line += " " + quotaCell(w) + line += " " + quotaCell(w, now) } if r.Balance != "" { line += " " + balanceCell(r.Balance, r.Agent, r.User) @@ -276,18 +277,18 @@ func accountRows(ls []provider.Login, now time.Time) []accountRow { return rows } -// quotaCell is one window in a line: "5h 42% ↻2h13m". -func quotaCell(w quotaSpan) string { +// quotaCell is one window in a line as of now: "5h 42% ↻2h13m 14:13". +func quotaCell(w quotaSpan, now time.Time) string { name := strings.NewReplacer(" hours", "h", " hour", "h", " days", "d", " day", "d", " · ", " ").Replace(w.Name) cell := fmt.Sprintf("%s %.0f%%", name, w.Used) if w.Display != "" { cell += " (" + w.Display + ")" } if w.ResetsAt != nil { - if !w.ResetsAt.After(time.Now()) { + if !w.ResetsAt.After(now) { cell += muted.Render(" · reset time passed " + w.ResetsAt.Local().Format("Jan 2 15:04")) } else { - cell += muted.Render(" ↻" + untilShort(time.Until(*w.ResetsAt)) + " " + provider.ResetClock(*w.ResetsAt, time.Now())) + cell += muted.Render(" ↻" + untilShort(w.ResetsAt.Sub(now)) + " " + provider.ResetClock(*w.ResetsAt, now)) } } return cell diff --git a/accounts_cli_test.go b/accounts_cli_test.go index fb03a2e8..19e20e59 100644 --- a/accounts_cli_test.go +++ b/accounts_cli_test.go @@ -121,14 +121,21 @@ func TestUntilShort(t *testing.T) { } func TestQuotaCell(t *testing.T) { - at := time.Now().Add(2*time.Hour + 13*time.Minute + 30*time.Second) - got := quotaCell(quotaSpan{Name: "5 hours", Used: 42, ResetsAt: &at}) - if !strings.HasPrefix(got, "5h 42%") || !strings.Contains(got, "↻2h13m "+provider.ResetClock(at, time.Now())) { + // a fixed now, so the reset reads the same day whenever the test runs + now := time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) + at := now.Add(2*time.Hour + 13*time.Minute + 30*time.Second) + got := quotaCell(quotaSpan{Name: "5 hours", Used: 42, ResetsAt: &at}, now) + if !strings.HasPrefix(got, "5h 42%") || !strings.Contains(got, "↻2h13m 14:13") { t.Fatalf("%q", got) } + // a reset on the next day reads "tomorrow" against the same now + next := now.Add(14*time.Hour + 13*time.Minute + 30*time.Second) + if got := quotaCell(quotaSpan{Name: "7 days", Used: 42, ResetsAt: &next}, now); !strings.Contains(got, "↻14h13m tomorrow 02:13") { + t.Fatalf("tomorrow: %q", got) + } // a pool's own window comes in named with its pool (PooledWindows) and // reads compactly, without the " · " - pooled := quotaCell(quotaSpan{Name: "Gemini · 7 days", Pool: "Gemini", Used: 80}) + pooled := quotaCell(quotaSpan{Name: "Gemini · 7 days", Pool: "Gemini", Used: 80}, now) if !strings.HasPrefix(pooled, "Gemini 7d 80%") { t.Fatalf("pooled: %q", pooled) } diff --git a/internal/davsync/archive_test.go b/internal/davsync/archive_test.go index 53821d21..2822a230 100644 --- a/internal/davsync/archive_test.go +++ b/internal/davsync/archive_test.go @@ -76,11 +76,13 @@ func TestRequestArchiveToS3(t *testing.T) { // on settings.Save(settings.Settings{RequestArchive: true}) - date := time.Now().UTC().Format("2006-01-02") id := post() if id == "" { t.Fatal("no archive id") } + // the date is the one the call carries, in UTC, not the clock read + // again here, which a UTC midnight can fall between + date := s.Recent()[0].Time.UTC().Format("2006-01-02") key := "team x+y/magpie/archive/" + date + "/" + id + ".json" deadline := time.Now().Add(5 * time.Second) for archived() == 0 && time.Now().Before(deadline) { diff --git a/internal/davsync/usage.go b/internal/davsync/usage.go index aa5340a6..0ec9468c 100644 --- a/internal/davsync/usage.go +++ b/internal/davsync/usage.go @@ -102,7 +102,7 @@ func shareUsage(ctx context.Context, c Config, st *state, force bool) { func shareWith(ctx context.Context, c Config, u *usageState, fs files) error { id, name := usage.Computer() - now := time.Now() + now := usage.Clock() today := time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, time.Local) first := today.AddDate(0, 0, 1-usage.SharedDays) from := first.Format(time.DateOnly) diff --git a/internal/davsync/usage_share_test.go b/internal/davsync/usage_share_test.go index 319e1ba9..22b0b2bd 100644 --- a/internal/davsync/usage_share_test.go +++ b/internal/davsync/usage_share_test.go @@ -112,7 +112,12 @@ func TestUsageSharedBetweenComputers(t *testing.T) { t.Helper() return usage.QueryPage(usage.All, f, 0, 100) } - now := time.Now() + // the usage clock held at noon, so that a's calls of today are of one + // day whenever the test runs + now := time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) + oldClock := usage.Clock + usage.Clock = func() time.Time { return now } + t.Cleanup(func() { usage.Clock = oldClock }) // a: two calls today, one two days ago, and one another magpie passed // on to it, which that one counts itself diff --git a/internal/gateway/archive_test.go b/internal/gateway/archive_test.go index 75151876..bbe77810 100644 --- a/internal/gateway/archive_test.go +++ b/internal/gateway/archive_test.go @@ -13,7 +13,6 @@ import ( "strings" "sync" "testing" - "time" "github.com/yetone/magpie/internal/settings" ) @@ -103,18 +102,20 @@ func TestArchiveOn(t *testing.T) { b := &memBucket{objs: map[string][]byte{}} archiveTo(t, b) s := New() - before := time.Now().UTC() rec := archivePost(t, s) id := rec.Header().Get(ArchiveHeader) if !regexp.MustCompile(`^\d{6}-[0-9a-f]{16}$`).MatchString(id) { t.Fatalf("id %q", id) } - name := before.Format("2006-01-02") + "/" + id + // the date is the one the call carries, in UTC, not the clock read + // again here, which a UTC midnight can fall between c := s.Recent()[0] + date := c.Time.UTC().Format("2006-01-02") + name := date + "/" + id if c.Archive != name || c.wire != nil { t.Fatalf("call archive %q, want %q", c.Archive, name) } - if p, ok := ArchiveName(before.Format("2006-01-02"), id); !ok || p != "archive/"+name+".json" { + if p, ok := ArchiveName(date, id); !ok || p != "archive/"+name+".json" { t.Fatalf("ArchiveName %q %v", p, ok) } data, ok := b.objs["archive/"+name+".json"] diff --git a/internal/gateway/history.go b/internal/gateway/history.go index 348bb322..e091a188 100644 --- a/internal/gateway/history.go +++ b/internal/gateway/history.go @@ -52,6 +52,10 @@ type counted struct { const dayForm = "2006-01-02" +// historyClock is the time saveRoute prunes the days by: which day is today, +// and which are over or too old. A variable for the tests. +var historyClock = time.Now + // saveRoute adds a done route to its day. Errors are swallowed: keeping // the history must never break a call. func saveRoute(r Route) { @@ -72,9 +76,9 @@ func saveRoute(r Route) { } f.Write(append(b, '\n')) f.Close() - if time.Since(history.pruned) > time.Hour { - history.pruned = time.Now() - pruneHistory(dir, time.Now()) + if now := historyClock(); now.Sub(history.pruned) > time.Hour { + history.pruned = now + pruneHistory(dir, now) } } diff --git a/internal/gateway/history_test.go b/internal/gateway/history_test.go index 0a3d08a0..6933dba1 100644 --- a/internal/gateway/history_test.go +++ b/internal/gateway/history_test.go @@ -9,9 +9,20 @@ import ( "time" ) +// historyNoon holds the history's clock at noon of a past day and returns +// it: a test's routes, a second apart, then fall on that one day, and +// saveRoute prunes by it rather than by the real day, which may have +// turned since the test began. +func historyNoon(t *testing.T) time.Time { + now := time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) + historyClock = func() time.Time { return now } + t.Cleanup(func() { historyClock = time.Now }) + return now +} + func TestHistoryKeepsSessionAndTokenTiers(t *testing.T) { t.Setenv("XDG_CONFIG_HOME", t.TempDir()) - now := time.Now() + now := historyNoon(t) records := routeUsage("relay", "m", Usage{Input: 20, Output: 5, CacheRead: 100, CacheWrite: 40}) saveRoute(Route{ID: 1, Time: now, Session: "conversation", ParentSession: "parent-conversation", Kind: "thread_title", Usage: records, Done: true}) saveRoute(Route{ID: 2, Time: now, Tokens: 1000, Done: true}) // legacy route @@ -29,7 +40,7 @@ func TestHistoryKeepsSessionAndTokenTiers(t *testing.T) { // still read, and a day too old or past the size kept dropped. func TestHistoryKeepsDaysAndDropsOld(t *testing.T) { t.Setenv("XDG_CONFIG_HOME", t.TempDir()) - now := time.Now() + now := historyNoon(t) yday := now.AddDate(0, 0, -1) saveRoute(Route{ID: 1, Time: yday, Model: "a", Done: true}) saveRoute(Route{ID: 2, Time: now, Model: "b", Done: true}) diff --git a/internal/gateway/key_limit.go b/internal/gateway/key_limit.go index 85d86391..fac71a27 100644 --- a/internal/gateway/key_limit.go +++ b/internal/gateway/key_limit.go @@ -14,6 +14,11 @@ import ( "github.com/yetone/magpie/internal/usage" ) +// limitClock is the time a gateway key's limit is checked at: the window +// a request counts in and when its 429 says the key resets. A variable for +// the tests. +var limitClock = time.Now + // keyLimited holds a gateway key's requests to its limit (#585, see // package budget for the rules): one that would go over is refused with a // 429 before any provider is asked, saying the key, the limit and when it @@ -37,7 +42,7 @@ func keyLimited(next http.Handler) http.Handler { r.Body = io.NopCloser(bytes.NewReader(b)) size, model = int64(len(b)), budget.ModelOf(b) } - now := time.Now() + now := limitClock() release, refused := budget.Reserve(who, size, model, now) if refused != nil { msg := refused.Error() @@ -78,6 +83,6 @@ func (s *Server) keyLimit(w http.ResponseWriter, r *http.Request) { writeJSON(w, 200, map[string]any{"limited": false, "key": who.KeyName}) return } - st := budget.Of(access.Key{ID: who.KeyID, Name: who.KeyName, Limit: who.Limit}, time.Now()) + st := budget.Of(access.Key{ID: who.KeyID, Name: who.KeyName, Limit: who.Limit}, limitClock()) writeJSON(w, 200, map[string]any{"limited": true, "key": who.KeyName, "limit": st}) } diff --git a/internal/gateway/key_limit_test.go b/internal/gateway/key_limit_test.go index 5d546921..cc9179ab 100644 --- a/internal/gateway/key_limit_test.go +++ b/internal/gateway/key_limit_test.go @@ -44,6 +44,18 @@ func setLimit(t *testing.T, id string, l *access.Limit) { } } +// pinLimitClock holds the gateway's limit checks at a fixed past noon, so +// a test can't see its calls split across a midnight, a Monday or a 1st. +// The calls are still recorded at the real time, later than that, and a +// window counts every call from its start, so they all count in its window. +func pinLimitClock(t *testing.T) time.Time { + t.Helper() + at := time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) + limitClock = func() time.Time { return at } + t.Cleanup(func() { limitClock = time.Now }) + return at +} + // A key past its limit is refused before any provider is asked, with a // 429 that names the key, the limit and when it resets; another key and a // keyless request from this computer go on; what was used survives a @@ -51,6 +63,7 @@ func setLimit(t *testing.T, id string, l *access.Limit) { func TestKeyLimitRefusesBeforeUpstream(t *testing.T) { fresh(t) budget.Forget() + now := pinLimitClock(t) calls := limitedUpstream(t, 0) keys, secrets := newCaller(t, "Capped", "Other") setLimit(t, keys[0].ID, &access.Limit{Period: "day", Tokens: 700}) @@ -88,7 +101,9 @@ func TestKeyLimitRefusesBeforeUpstream(t *testing.T) { if e.Error.Type != "rate_limit_error" || !strings.Contains(e.Error.Message, `"Capped"`) || !strings.Contains(e.Error.Message, "700 of its 700") || !strings.Contains(e.Error.Message, "resets at") { t.Fatal("refusal says", w.Body.String()) } - if ra, _ := strconv.Atoi(w.Header().Get("Retry-After")); ra <= 0 || ra > 86400+3600 || w.Header().Get("X-Should-Retry") != "false" { + // it resets at the next midnight after the check + _, reset := access.Window("day", now) + if ra := w.Header().Get("Retry-After"); ra != strconv.Itoa(int(reset.Sub(now).Seconds())) || w.Header().Get("X-Magpie-Limit-Reset") != reset.Format(time.RFC3339) || w.Header().Get("X-Should-Retry") != "false" { t.Fatal("headers", w.Header()) } rec := lastUsage(t) @@ -116,7 +131,7 @@ func TestKeyLimitRefusesBeforeUpstream(t *testing.T) { if w := call(secrets[0], "/v1/chat/completions", chatReq); w.Code != 429 { t.Fatal("a restart forgot what the key used", w.Code) } - st := budget.Of(access.Key{ID: keys[0].ID, Limit: &access.Limit{Period: "day", Tokens: 700}}, time.Now()) + st := budget.Of(access.Key{ID: keys[0].ID, Limit: &access.Limit{Period: "day", Tokens: 700}}, now) if st == nil || st.Tokens != 700 || st.Calls != 2 || !st.Spent || st.TokensLeft != 0 { t.Fatalf("status %+v", st) } @@ -139,7 +154,8 @@ func TestKeyLimitRefusesBeforeUpstream(t *testing.T) { Limit budget.Status } json.Unmarshal(lw.Body.Bytes(), &got) - if !got.Limited || got.Limit.Tokens != 1400 || got.Limit.TokensLeft != 3600 || got.Limit.Period != "week" { + monday, _ := access.Window("week", now) + if !got.Limited || got.Limit.Tokens != 1400 || got.Limit.TokensLeft != 3600 || got.Limit.Period != "week" || !got.Limit.Start.Equal(monday) { t.Fatal("limit endpoint", lw.Body.String()) } } @@ -150,6 +166,7 @@ func TestKeyLimitRefusesBeforeUpstream(t *testing.T) { func TestKeyLimitHoldsParallelRequests(t *testing.T) { fresh(t) budget.Forget() + now := pinLimitClock(t) calls := limitedUpstream(t, 80*time.Millisecond) keys, secrets := newCaller(t, "Busy") setLimit(t, keys[0].ID, &access.Limit{Period: "month", Tokens: 2000}) @@ -179,7 +196,7 @@ func TestKeyLimitHoldsParallelRequests(t *testing.T) { }) } wg.Wait() - st := budget.Of(access.Key{ID: keys[0].ID, Limit: &access.Limit{Period: "month", Tokens: 2000}}, time.Now()) + st := budget.Of(access.Key{ID: keys[0].ID, Limit: &access.Limit{Period: "month", Tokens: 2000}}, now) if st.Tokens > 2000+350 || refused.Load() == 0 || ok.Load()+refused.Load() != 20 { t.Fatalf("20 at once: %d let in, %d refused, %d tokens used of 2000, %d upstream calls", ok.Load(), refused.Load(), st.Tokens, calls.Load()) } @@ -196,12 +213,13 @@ func TestKeyLimitHoldsParallelRequests(t *testing.T) { func TestKeyLimitWindowResets(t *testing.T) { fresh(t) budget.Forget() + now := pinLimitClock(t) limitedUpstream(t, 0) keys, secrets := newCaller(t, "Daily") lim := &access.Limit{Period: "day", Tokens: 350} setLimit(t, keys[0].ID, lim) // yesterday's call - budget.Append(usage.Record{Time: time.Now().AddDate(0, 0, -1), Provider: "plan", Model: "m1", Input: 5000, Status: 200, CallerKeyID: keys[0].ID}) + budget.Append(usage.Record{Time: now.AddDate(0, 0, -1), Provider: "plan", Model: "m1", Input: 5000, Status: 200, CallerKeyID: keys[0].ID}) h := New().Handler() call := func() int { r := httptest.NewRequest("POST", "/v1/chat/completions", strings.NewReader(chatReq)) @@ -217,9 +235,11 @@ func TestKeyLimitWindowResets(t *testing.T) { t.Fatal("spent key let in") } who := access.Identity{KeyID: keys[0].ID, KeyName: "Daily", Limit: lim} - if _, refused := budget.Reserve(who, 10, "", time.Now()); refused == nil { + if _, refused := budget.Reserve(who, 10, "", now); refused == nil { t.Fatal("spent today") } + // the calls were recorded at the real time, so the next window that has + // none of them is the one after the real now _, reset := access.Window("day", time.Now()) release, refused := budget.Reserve(who, 10, "", reset.Add(time.Minute)) if refused != nil { diff --git a/internal/gateway/remote_group_served_test.go b/internal/gateway/remote_group_served_test.go index 30dddd98..b6cee520 100644 --- a/internal/gateway/remote_group_served_test.go +++ b/internal/gateway/remote_group_served_test.go @@ -132,7 +132,7 @@ func TestRemoteMagpieGroupLedgerRow(t *testing.T) { // routed; a real swap kept beside it is still one. func TestRemoteMagpieGroupHistory(t *testing.T) { t.Setenv("XDG_CONFIG_HOME", t.TempDir()) - now := time.Now() + now := historyNoon(t) saveRoute(Route{ID: 1, Time: now, Model: "office/group/auto-deepseek-v4-1-flash", Done: true, Status: 200, Tries: []Try{{ID: "office", Model: "group/auto-deepseek-v4-1-flash", Done: true, Status: 200, Served: "deepseek/deepseek-v4.1-flash", Swapped: true}}, Served: "deepseek/deepseek-v4.1-flash", Swapped: true}) diff --git a/internal/gui/usage.go b/internal/gui/usage.go index 7f72e3f2..8fbe3def 100644 --- a/internal/gui/usage.go +++ b/internal/gui/usage.go @@ -116,12 +116,13 @@ func periodOf(s string) usage.Period { return usage.Month } -// csvStamp names the selected day, or the period when no day is selected. -func csvStamp(p usage.Period, day string) string { +// csvStamp names the selected day, or, when no day is selected, the period +// and the day of now, the moment its rows were read at. +func csvStamp(p usage.Period, day string, now time.Time) string { if _, err := time.Parse(time.DateOnly, day); err == nil { return "magpie-requests-day-" + day } - return "magpie-requests-" + string(p) + "-" + time.Now().Format(time.DateOnly) + return "magpie-requests-" + string(p) + "-" + now.Format(time.DateOnly) } func ledgerFilter(q url.Values) usage.Filter { @@ -397,23 +398,26 @@ func usageRoutes(mux *http.ServeMux, w Windows) { mux.HandleFunc("GET /api/usage/requests.csv", func(rw http.ResponseWriter, r *http.Request) { q := r.URL.Query() p := periodOf(q.Get("period")) - rows, _, _ := usage.Ledger(p, ledgerFilter(q)) + // one moment for the rows and the day in the file's name + now := usage.Clock() + rows := usage.LedgerOfAt(p, ledgerFilter(q), now).Rows rw.Header().Set("Content-Type", "text/csv; charset=utf-8") - rw.Header().Set("Content-Disposition", `attachment; filename="`+csvStamp(p, q.Get("day"))+`.csv"`) + rw.Header().Set("Content-Disposition", `attachment; filename="`+csvStamp(p, q.Get("day"), now)+`.csv"`) usage.WriteCSV(rw, rows) }) // the rows the ledger shows, all its pages, as a CSV in Downloads mux.HandleFunc("POST /api/usage/requests/export", func(rw http.ResponseWriter, r *http.Request) { q := r.URL.Query() p := periodOf(q.Get("period")) - rows, _, _ := usage.Ledger(p, ledgerFilter(q)) + now := usage.Clock() + rows := usage.LedgerOfAt(p, ledgerFilter(q), now).Rows var b bytes.Buffer if err := usage.WriteCSV(&b, rows); err != nil { fail(rw, err) return } dir := downloads() - stamp := csvStamp(p, q.Get("day")) + stamp := csvStamp(p, q.Get("day"), now) name := filepath.Join(dir, stamp+".csv") for i := 2; ; i++ { // never over an earlier one if _, err := os.Stat(name); err != nil { diff --git a/internal/gui/usage_purpose_test.go b/internal/gui/usage_purpose_test.go index fc6301df..e62db0a6 100644 --- a/internal/gui/usage_purpose_test.go +++ b/internal/gui/usage_purpose_test.go @@ -21,7 +21,7 @@ func TestUsagePurposeRoutes(t *testing.T) { if err := os.MkdirAll(filepath.Join(home, "Downloads"), 0o755); err != nil { t.Fatal(err) } - start := usage.Today.Since(time.Now()).Add(time.Second) + start := usage.Today.Since(holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))).Add(time.Second) for i, kind := range []string{"thread_title", "thread_title_reconsideration", "review", "", "future_kind", "title_generation"} { usage.Append(usage.Record{Time: start.Add(time.Duration(i) * time.Second), Agent: "codex", Provider: "relay", Model: "m", Kind: kind, Input: 10, Output: 2, Status: 200}) } diff --git a/internal/gui/usage_test.go b/internal/gui/usage_test.go index ef543bc6..4385e0ae 100644 --- a/internal/gui/usage_test.go +++ b/internal/gui/usage_test.go @@ -9,6 +9,7 @@ import ( "os" "path/filepath" "strings" + "sync/atomic" "testing" "time" @@ -16,12 +17,23 @@ import ( "github.com/yetone/magpie/internal/usage" ) +// holdUsageClock stops usage.Clock at at for the test and gives at back, for +// the test to stamp its calls by: midnight then never falls between a call +// and the period it is asked for in. +func holdUsageClock(t *testing.T, at time.Time) time.Time { + t.Helper() + old := usage.Clock + usage.Clock = func() time.Time { return at } + t.Cleanup(func() { usage.Clock = old }) + return at +} + func TestUsageLedgerDayRoutes(t *testing.T) { home := sandboxHome(t) if err := os.MkdirAll(filepath.Join(home, "Downloads"), 0o755); err != nil { t.Fatal(err) } - start := usage.Today.Since(time.Now()).AddDate(0, 0, -1) + start := usage.Today.Since(holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))).AddDate(0, 0, -1) for i, at := range []time.Time{start.Add(-time.Second), start, start.Add(12 * time.Hour), start.AddDate(0, 0, 1)} { usage.Append(usage.Record{Time: at, Agent: "codex", Provider: "relay", Model: "m", Input: 10 + i, Output: 1, Status: 200}) } @@ -86,8 +98,8 @@ func TestUsageLedgerRoutes(t *testing.T) { if err := os.MkdirAll(filepath.Join(home, "Downloads"), 0o755); err != nil { t.Fatal(err) } - y, m, d := time.Now().Date() - at := time.Date(y, m, d, 0, 0, 1, 0, time.Local) // today, whenever the test runs + now := holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) + at := usage.Today.Since(now).Add(time.Second) for i, r := range []usage.Record{ {RouteID: 123, Agent: "codex", Provider: "relay", Model: "gpt-6-sol", Requested: "sol", Served: "gpt-6-luna", Input: 10, Output: 1, Status: 200}, {Agent: "claude", Provider: "anthropic", Model: "claude-sonnet-5", Requested: "sonnet", Input: 20, Output: 2, Status: 200}, @@ -184,7 +196,7 @@ func TestUsageLedgerRoutes(t *testing.T) { } p1, n := export() p2, _ := export() - day := time.Now().Format("2006-01-02") + day := now.Format("2006-01-02") if n != 2 || p1 != filepath.Join("~", "Downloads", "magpie-requests-today-"+day+".csv") || p2 != filepath.Join("~", "Downloads", "magpie-requests-today-"+day+"-2.csv") { t.Fatalf("export: %s %s %d", p1, p2, n) } @@ -269,11 +281,12 @@ func TestUsageRequestContent(t *testing.T) { // filters set. Calls without recorded routing are shown as local sessions. func TestLedgerSingleSnapshotAndLocalSession(t *testing.T) { sandboxHome(t) + now := holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) before := usage.LogCalls reads := 0 usage.LogCalls = func(time.Time) []sessions.Call { reads++ - return []sessions.Call{{Time: time.Now(), Agent: "claude", Session: "s", Model: "claude-sonnet-5", Tokens: sessions.Tokens{Input: 10, Output: 2}}} + return []sessions.Call{{Time: now, Agent: "claude", Session: "s", Model: "claude-sonnet-5", Tokens: sessions.Tokens{Input: 10, Output: 2}}} } t.Cleanup(func() { usage.LogCalls = before }) l := ledgerPage(usage.Today, usage.Filter{Provider: usage.UnknownProvider, Agent: "claude"}, 0, 1) @@ -292,9 +305,10 @@ func TestLedgerSingleSnapshotAndLocalSession(t *testing.T) { // one model's speed at each provider reads apart (inaction on Discord). func TestLedgerNamesModelAtProvider(t *testing.T) { sandboxHome(t) + now := holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) before := usage.LogCalls usage.LogCalls = func(time.Time) []sessions.Call { - return []sessions.Call{{Time: time.Now(), Agent: "claude", Session: "s", Model: "claude-sonnet-5", Tokens: sessions.Tokens{Input: 10, Output: 2}}} + return []sessions.Call{{Time: now, Agent: "claude", Session: "s", Model: "claude-sonnet-5", Tokens: sessions.Tokens{Input: 10, Output: 2}}} } t.Cleanup(func() { usage.LogCalls = before }) l := ledgerPage(usage.Today, usage.Filter{}, 0, 1) @@ -305,10 +319,62 @@ func TestLedgerNamesModelAtProvider(t *testing.T) { } func TestCSVStamp(t *testing.T) { + now := time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) for _, day := range []string{"", "2026-02-30", "../../other", "2026-09-30\""} { - want := "magpie-requests-7d-" + time.Now().Format(time.DateOnly) - if got := csvStamp(usage.Period("7d"), day); got != want { + want := "magpie-requests-7d-2026-09-30" + if got := csvStamp(usage.Period("7d"), day, now); got != want { t.Fatalf("%q: %s", day, got) } } } + +// midnightUsageClock sets usage.Clock to read a tenth of a second before +// midnight the first time and a tenth of a second after it from then on, as +// when midnight falls while an answer is worked out. It is set again for +// each answer. +func midnightUsageClock(t *testing.T, midnight time.Time) { + t.Helper() + var read atomic.Bool + old := usage.Clock + usage.Clock = func() time.Time { + if read.Swap(true) { + return midnight.Add(100 * time.Millisecond) + } + return midnight.Add(-100 * time.Millisecond) + } + t.Cleanup(func() { usage.Clock = old }) +} + +// A period's CSV asked for as midnight falls is named for the day of the +// calls in it, downloaded or saved to Downloads: its rows and its name are +// read at one moment, not the rows of one day under the next day's name. +func TestUsageCSVAtMidnight(t *testing.T) { + home := sandboxHome(t) + if err := os.MkdirAll(filepath.Join(home, "Downloads"), 0o755); err != nil { + t.Fatal(err) + } + midnight := time.Date(2026, 10, 1, 0, 0, 0, 0, time.Local) + usage.Append(usage.Record{Time: midnight.Add(-time.Minute), Agent: "codex", Provider: "relay", Model: "m", Input: 10, Output: 1, Status: 200}) + mux := http.NewServeMux() + usageRoutes(mux, folderOnly{}) + want := "magpie-requests-today-2026-09-30.csv" + + midnightUsageClock(t, midnight) + w := httptest.NewRecorder() + mux.ServeHTTP(w, httptest.NewRequest("GET", "/api/usage/requests.csv?period=today", nil)) + rows, err := csv.NewReader(w.Body).ReadAll() + if got := w.Header().Get("Content-Disposition"); w.Code != 200 || err != nil || len(rows) != 2 || got != `attachment; filename="`+want+`"` { + t.Errorf("download: %d, %s with %d rows (%v), want %s with 2", w.Code, got, len(rows), err, want) + } + + midnightUsageClock(t, midnight) + w = httptest.NewRecorder() + mux.ServeHTTP(w, httptest.NewRequest("POST", "/api/usage/requests/export?period=today", nil)) + var out struct { + Path string + Rows int + } + if err := json.Unmarshal(w.Body.Bytes(), &out); w.Code != 200 || err != nil || out.Rows != 1 || out.Path != filepath.Join("~", "Downloads", want) { + t.Errorf("export: %d %s, want %s with 1 row", w.Code, w.Body, want) + } +} diff --git a/internal/gui/whatsnew_test.go b/internal/gui/whatsnew_test.go index a0197d00..ebadfa46 100644 --- a/internal/gui/whatsnew_test.go +++ b/internal/gui/whatsnew_test.go @@ -224,6 +224,10 @@ func TestWhatsNewQuietAfterRestartToUpdate(t *testing.T) { func TestWhatsNewTodayRoute(t *testing.T) { home := t.TempDir() t.Setenv("XDG_CONFIG_HOME", home) + // one day for the post and the check, so a run across midnight agrees + oldToday := today + t.Cleanup(func() { today = oldToday }) + today = func() string { return "2026-09-30" } mux := http.NewServeMux() whatsNewRoutes(mux) post := func(body string) int { diff --git a/internal/provider/zcode_client_test.go b/internal/provider/zcode_client_test.go index 14fbadd4..ed11fe5a 100644 --- a/internal/provider/zcode_client_test.go +++ b/internal/provider/zcode_client_test.go @@ -86,6 +86,10 @@ func TestZCodeStartSentAsTheApp(t *testing.T) { t.Setenv("LC_MESSAGES", "") t.Setenv("TZ", "Asia/Shanghai") t.Setenv("SHELL", "/bin/zsh") + // the day the context prefix gives, the same whenever the test runs + oldClock := zcodeClock + t.Cleanup(func() { zcodeClock = oldClock }) + zcodeClock = func() time.Time { return time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) } jwt := zcodeTestJWT(time.Now().Add(24 * time.Hour)) u := newZCodeStartUpstream(t, jwt) u.balance = zcodeActiveStart(time.Now(), "active") @@ -187,8 +191,7 @@ func TestZCodeStartSentAsTheApp(t *testing.T) { } var prefix []block json.Unmarshal(got.Messages[0].Content, &prefix) - want := "As you answer the user's questions, you can use the following context:\n# currentDate\nToday's date is " + - time.Now().Format("2006-01-02") + ".\n\n IMPORTANT: this context may or may not be relevant to your tasks. You should not respond to this context unless it is highly relevant to your task." + want := "As you answer the user's questions, you can use the following context:\n# currentDate\nToday's date is 2026-09-30.\n\n IMPORTANT: this context may or may not be relevant to your tasks. You should not respond to this context unless it is highly relevant to your task." if got.Messages[0].Role != "user" || len(prefix) != 1 || prefix[0].Type != "text" || prefix[0].Text != want || prefix[0].Cache != nil { t.Fatalf("the context prefix: %s", got.Messages[0].Content) } diff --git a/internal/provider/zcode_start.go b/internal/provider/zcode_start.go index aa4852f2..5bcbc6fe 100644 --- a/internal/provider/zcode_start.go +++ b/internal/provider/zcode_start.go @@ -273,6 +273,10 @@ func zcodeTimezone() string { return "UTC" } +// zcodeClock is the time a Start Plan request's context prefix gives the +// day of (zcodeDateReminder); tests set it. +var zcodeClock = time.Now + // zcodeStartRequest makes req, a request to the Start Plan, ZCode's own: // its headers, and a model request's body shaped as ZCode's // (zcodeStartBody) for an account on base. @@ -281,7 +285,7 @@ func zcodeStartRequest(req *http.Request, base string, body []byte) { if len(body) == 0 || !strings.HasSuffix(req.URL.Path, "/v1/messages") { return } - nb := zcodeStartBody(body, zcodeStartProvider(base), time.Now()) + nb := zcodeStartBody(body, zcodeStartProvider(base), zcodeClock()) req.Body = io.NopCloser(bytes.NewReader(nb)) req.ContentLength = int64(len(nb)) req.GetBody = func() (io.ReadCloser, error) { return io.NopCloser(bytes.NewReader(nb)), nil } diff --git a/internal/tui/pages.go b/internal/tui/pages.go index e84d932b..0c8cf43d 100644 --- a/internal/tui/pages.go +++ b/internal/tui/pages.go @@ -786,7 +786,7 @@ func (m model) updateUsage(msg tea.KeyMsg) (tea.Model, tea.Cmd) { default: return m, nil } - m.sum, m.direct = usage.Summarize(m.period), usage.Direct(m.period) + m.sum, m.direct = usage.Summaries(m.period) return m, nil } diff --git a/internal/tui/tui.go b/internal/tui/tui.go index 638f76da..f7051a66 100644 --- a/internal/tui/tui.go +++ b/internal/tui/tui.go @@ -199,7 +199,7 @@ func (m *model) reload() { m.gsel = clamp(m.gsel, len(g.Members)+len(g.Rules)) } case pageUsage: - m.sum, m.direct = usage.Summarize(m.period), usage.Direct(m.period) + m.sum, m.direct = usage.Summaries(m.period) case pageSessions: m.reloadSessions() case pageLibrary: diff --git a/internal/tui/usage_test.go b/internal/tui/usage_test.go index 4c7eb91a..ef4f9a26 100644 --- a/internal/tui/usage_test.go +++ b/internal/tui/usage_test.go @@ -5,6 +5,7 @@ import ( "os" "path/filepath" "strings" + "sync/atomic" "testing" "time" @@ -124,7 +125,12 @@ func TestUnlimitedQuotaCell(t *testing.T) { // TUI). func TestUsagePageShowsCallsNotThroughMagpie(t *testing.T) { home(t) - now := time.Now() + // the usage clock held at noon, so that the calls a minute or two + // before it are today's whenever the test runs + now := time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local) + oldClock := usage.Clock + usage.Clock = func() time.Time { return now } + t.Cleanup(func() { usage.Clock = oldClock }) usage.Append(usage.Record{Time: now.Add(-time.Minute), Agent: "claude", Provider: "relay", Model: "m", Input: 5, Status: 200}) old := usage.LogCalls usage.LogCalls = func(time.Time) []sessions.Call { @@ -142,6 +148,45 @@ func TestUsagePageShowsCallsNotThroughMagpie(t *testing.T) { } } +// The Usage page asked for as midnight falls shows the calls through magpie +// and those not through it of one day, the day it was asked on, when a +// period is picked and when the page is read again. +func TestUsagePageAtMidnight(t *testing.T) { + home(t) + midnight := time.Date(2026, 10, 1, 0, 0, 0, 0, time.Local) + usage.Append(usage.Record{Time: midnight.Add(-time.Minute), Agent: "claude", Provider: "relay", Model: "m", Input: 5, Status: 200}) + old := usage.LogCalls + usage.LogCalls = func(time.Time) []sessions.Call { + return []sessions.Call{{Time: midnight.Add(-2 * time.Minute), Agent: "codex", Session: "c1", Model: "gpt-6-luna", Tokens: sessions.Tokens{Input: 1200, Output: 300}}} + } + t.Cleanup(func() { usage.LogCalls = old }) + // the usage clock reads a tenth of a second before midnight the first + // time and a tenth of a second after it from then on, as when midnight + // falls while the page is worked out + var read atomic.Bool + oldClock := usage.Clock + usage.Clock = func() time.Time { + if read.Swap(true) { + return midnight.Add(100 * time.Millisecond) + } + return midnight.Add(-100 * time.Millisecond) + } + t.Cleanup(func() { usage.Clock = oldClock }) + both := func(how string, m model) { + t.Helper() + v := m.viewUsage() + gw, own, ok := strings.Cut(v, "not through magpie") + if !ok || !strings.Contains(gw, "relay/m") || !strings.Contains(own, "gpt-6-luna") { + t.Errorf("%s:\n%s", how, v) + } + } + m := press(t, model{w: 160, h: 60, page: pageUsage}, "t") + both("today picked", m) + read.Store(false) + m.reload() + both("read again", m) +} + // A Codex account set not to spend its credits says so beside them. func TestQuotaLinesCreditsNotSpent(t *testing.T) { home(t) diff --git a/internal/usage/cache_bounds_test.go b/internal/usage/cache_bounds_test.go index 7238251b..36516afa 100644 --- a/internal/usage/cache_bounds_test.go +++ b/internal/usage/cache_bounds_test.go @@ -12,6 +12,7 @@ func TestUsageSameSizeAndMtimeRewrite(t *testing.T) { for _, appendAfter := range []bool{false, true} { t.Run(fmt.Sprint("append=", appendAfter), func(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) historyLog(t, 1034) Summarize(All) QueryPage(All, Filter{}, 0, 100) @@ -34,9 +35,9 @@ func TestUsageSameSizeAndMtimeRewrite(t *testing.T) { t.Fatal(err) } if appendAfter { - Append(Record{Time: time.Now(), Agent: "codex", Provider: "relay", Model: "m", Input: 19}) + Append(Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Input: 19}) } - got, want := Summarize(All), summarize(All, time.Now(), Load(time.Time{})) + got, want := Summarize(All), summarize(All, now, Load(time.Time{})) if got.Totals != want.Totals { t.Fatalf("same-stat summary stale: got %+v want %+v", got.Totals, want.Totals) } @@ -54,13 +55,14 @@ func cacheBudget(t *testing.T, n int64) { func TestUsageRawCacheBudget(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) cacheBudget(t, 128) historyLog(t, 1034) assertFresh := func() { t.Helper() cold := Load(time.Time{}) for _, p := range []Period{Today, Week, Month, All} { - got, want := Summarize(p), summarize(p, time.Now(), cold) + got, want := Summarize(p), summarize(p, now, cold) if got.Totals != want.Totals { t.Fatalf("uncached %s summary stale: %+v / %+v", p, got.Totals, want.Totals) } @@ -80,7 +82,7 @@ func TestUsageRawCacheBudget(t *testing.T) { } } assertFresh() - Append(Record{Time: time.Now(), Agent: "codex", Provider: "relay", Model: "m", Input: 11}) + Append(Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Input: 11}) assertFresh() historyLog(t, 20) // rewrite/truncate after the oversized metadata-only index assertFresh() @@ -88,6 +90,7 @@ func TestUsageRawCacheBudget(t *testing.T) { func TestUsageRawAndPricedChunksShareBudget(t *testing.T) { pageHome(t) + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) historyLog(t, 1034) snapshot := readLogSnapshot() cacheBudget(t, snapshot.bytes+1) @@ -127,6 +130,7 @@ func TestUsageLargeSummaryIsCompleteButNotCached(t *testing.T) { // page key. The preceding query must leave an initialized page map to write. func TestUsagePageCacheAfterUncachedQuery(t *testing.T) { pageHome(t) + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) historyLog(t, 1034) normalBudget := requestCacheBytes cacheBudget(t, 128) diff --git a/internal/usage/caller_provider_test.go b/internal/usage/caller_provider_test.go index cde1d8ce..085a48ce 100644 --- a/internal/usage/caller_provider_test.go +++ b/internal/usage/caller_provider_test.go @@ -97,7 +97,7 @@ func TestProviderAndCallerIdentitiesRemainIndependent(t *testing.T) { func TestPackedRequestPageCallerAndRouteIdentity(t *testing.T) { pageHome(t) - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) for i := 0; i < 80; i++ { caller := "desk" if i%2 != 0 { @@ -143,7 +143,7 @@ func TestPackedRequestPageCallerAndRouteIdentity(t *testing.T) { func TestCallerPageKeepsUnattributedSessionsSeparate(t *testing.T) { pageHome(t) - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) recs := []Record{ {Time: now, Agent: "codex", Provider: "relay", Model: "m", CallerKeyID: "desk", CallerKeyName: "Desk", Input: 10, Status: 200}, {Time: now, Agent: "codex", Provider: "relay", Model: "m", CallerKeyID: "server", CallerKeyName: "Server", Input: 20, Status: 200}, diff --git a/internal/usage/clock_test.go b/internal/usage/clock_test.go new file mode 100644 index 00000000..8278b251 --- /dev/null +++ b/internal/usage/clock_test.go @@ -0,0 +1,147 @@ +package usage + +import ( + "os" + "path/filepath" + "sync/atomic" + "testing" + "time" + + "github.com/yetone/magpie/internal/sessions" +) + +// holdClock stops Clock at at for the test and gives at back, for the test +// to stamp its calls by: midnight then never falls between a call and the +// period it is asked for in. +func holdClock(t *testing.T, at time.Time) time.Time { + t.Helper() + old := Clock + Clock = func() time.Time { return at } + t.Cleanup(func() { Clock = old }) + return at +} + +// Every period is read by Clock, not by the machine's own time: a call made +// on a day Clock is held at is that day's in Summarize, the Requests page and +// its chart, the ledger and Direct, and the next day's Today has none of it. +// A path that reads time.Now itself fails here on any run. +func TestPeriodsReadTheClock(t *testing.T) { + pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) + Append(Record{Agent: "claude", Provider: "openai", Model: "m", Input: 10, Status: 200}) // stamped by Clock + calls := func(pts []SeriesPoint) (n int) { + for _, p := range pts { + n += p.Calls + } + return n + } + if s := Summarize(Today); s.Calls != 1 { + t.Errorf("Summarize(Today): %d calls, want 1", s.Calls) + } + if p := QueryPage(Today, Filter{}, 0, 10); p.Total != 1 || calls(p.Series) != 1 { + t.Errorf("QueryPage(Today): %d rows, %d in the chart, want 1 and 1", p.Total, calls(p.Series)) + } + + old := LogCalls + LogCalls = func(time.Time) []sessions.Call { + return []sessions.Call{{Time: now.Add(-time.Minute), Agent: "codex", Session: "c1", Model: "m", Tokens: sessions.Tokens{Input: 20}}} + } + t.Cleanup(func() { LogCalls = old }) + l := LedgerOf(Today, Filter{}) + if len(l.Rows) != 2 { + t.Errorf("LedgerOf(Today): %d rows, want 2", len(l.Rows)) + } + if _, pts := LedgerSeries(Today, l.Rows); calls(pts) != 2 { + t.Errorf("LedgerSeries(Today): %d calls, want 2", calls(pts)) + } + if d := Direct(Today); d.Calls != 1 || !d.Since.Equal(Today.Since(now)) { + t.Errorf("Direct(Today): %d calls since %v, want 1 since %v", d.Calls, d.Since, Today.Since(now)) + } + + // the next day, today has none of it, though the answers for the day + // before are cached + LogCalls = old + holdClock(t, now.AddDate(0, 0, 1)) + if s := Summarize(Today); s.Calls != 0 { + t.Errorf("Summarize(Today) the next day: %d calls, want 0", s.Calls) + } + if p := QueryPage(Today, Filter{}, 0, 10); p.Total != 0 { + t.Errorf("QueryPage(Today) the next day: %d rows, want 0", p.Total) + } +} + +// midnightClock sets Clock to read a tenth of a second before midnight the +// first time and a tenth of a second after it from then on, as when midnight +// falls while an answer is worked out. It is set again for each answer. +func midnightClock(t *testing.T, midnight time.Time) { + t.Helper() + var read atomic.Bool + old := Clock + Clock = func() time.Time { + if read.Swap(true) { + return midnight.Add(100 * time.Millisecond) + } + return midnight.Add(-100 * time.Millisecond) + } + t.Cleanup(func() { Clock = old }) +} + +// An answer reads the time once. A Requests page asked for as midnight falls +// is of the day it was asked on: its rows, a session file written that day +// among them, are under that day's chart, whether the page comes from the +// indexed log or from the ledger, and it is kept for that day only. Direct's +// period starts on the day of the calls it counts. Read more than once, the +// rows were of one day and the chart or the period of the next. +func TestAnswerReadsTheClockOnce(t *testing.T) { + pageHome(t) + midnight := time.Date(2026, 10, 1, 0, 0, 0, 0, time.Local) + day := midnight.AddDate(0, 0, -1) + for _, at := range []time.Time{day.Add(12 * time.Hour), midnight.Add(-time.Second)} { + Append(Record{Time: at, Agent: "claude", Provider: "openai", Model: "m", Input: 10, Status: 200}) + } + // a session file last written at 23:00, with a call of that time + at := day.Add(23 * time.Hour) + path := filepath.Join(sessions.ClaudeDir(), "projects", "p", "s.jsonl") + if err := os.MkdirAll(filepath.Dir(path), 0700); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(path, []byte("{}\n"), 0600); err != nil { + t.Fatal(err) + } + if err := os.Chtimes(path, at, at); err != nil { + t.Fatal(err) + } + call := []sessions.Call{{Time: at, Agent: "codex", Session: "s", Model: "m", Tokens: sessions.Tokens{Input: 20}}} + page := func(want int, from time.Time) { + t.Helper() + p := queryPage(Today, Filter{}, 0, 10, func(sessions.CallSource) []sessions.Call { return call }) + var calls int + var first time.Time + for i, pt := range p.Series { + if i == 0 { + first = pt.Time + } + calls += pt.Calls + } + if p.Total != want || calls != want || !first.Equal(from) { + t.Errorf("QueryPage(Today): %d rows, %d in a chart from %v; want %d under one from %v", p.Total, calls, first, want, from) + } + } + midnightClock(t, midnight) + page(3, day) + // asked again after midnight, the next day's page, not the one kept for + // the day before + page(0, midnight) + + // the same page from the ledger + old := LogCalls + LogCalls = func(time.Time) []sessions.Call { return call } + t.Cleanup(func() { LogCalls = old }) + midnightClock(t, midnight) + page(3, day) + + midnightClock(t, midnight) + if d := Direct(Today); d.Calls != 1 || !d.Since.Equal(day) { + t.Errorf("Direct(Today): %d calls since %v, want 1 since %v", d.Calls, d.Since, day) + } +} diff --git a/internal/usage/codex_cache_write_test.go b/internal/usage/codex_cache_write_test.go index c37af3b4..d0a47d3f 100644 --- a/internal/usage/codex_cache_write_test.go +++ b/internal/usage/codex_cache_write_test.go @@ -18,10 +18,7 @@ import ( // gateway's record didn't, so their token counts never matched. However each // side splits the write out of the input, a call is the gateway's alone. func TestCodexCacheWriteMatchesGatewayCall(t *testing.T) { - end := time.Now().Truncate(time.Second).Add(-time.Minute) - if end.Before(Today.Since(time.Now())) { - end = Today.Since(time.Now()).Add(10 * time.Minute) - } + end := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)).Add(-time.Minute) // the upstream's usage for the two calls: the second wrote 9000 to its cache type call struct{ in, cached, write, out int } calls := []call{{120000, 113000, 0, 300}, {130000, 113000, 9000, 400}} @@ -95,7 +92,7 @@ func TestCodexCacheWriteNotInInput(t *testing.T) { pageHome(t) path := filepath.Join(sessions.CodexDir(), "sessions", "rollout-2026-09-30T00-00-00-w.jsonl") os.MkdirAll(filepath.Dir(path), 0700) - at := time.Now().Add(-time.Minute).Format(time.RFC3339Nano) + at := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)).Add(-time.Minute).Format(time.RFC3339Nano) u := `{"input_tokens":130000,"cached_input_tokens":113000,"cache_write_input_tokens":9000,"output_tokens":400}` os.WriteFile(path, []byte(`{"type":"session_meta","payload":{"id":"w"}}`+"\n"+ `{"timestamp":"`+at+`","type":"event_msg","payload":{"type":"token_count","info":{"total_token_usage":`+u+`,"last_token_usage":`+u+`}}}`+"\n"), 0600) diff --git a/internal/usage/direct.go b/internal/usage/direct.go index 94b08924..bd30aaf1 100644 --- a/internal/usage/direct.go +++ b/internal/usage/direct.go @@ -13,7 +13,17 @@ import ( // their own (Kumo31 on Discord: Codex used outside magpie was on the // window's Usage tab but not in magpie usage). func Direct(p Period) Summary { - return direct(p, time.Now(), LedgerOf(p, Filter{}).Rows) + now := Clock() + return direct(p, now, LedgerOfAt(p, Filter{}, now).Rows) +} + +// Summaries is Summarize(p) and Direct(p) asked at one moment, for a page +// that shows the two together: asked one after the other, midnight could +// fall between them and set one day's calls through magpie beside the next +// day's calls not through it. +func Summaries(p Period) (Summary, Summary) { + now := Clock() + return indexedSummary(p, now), direct(p, now, LedgerOfAt(p, Filter{}, now).Rows) } func direct(p Period, now time.Time, rows []Row) Summary { diff --git a/internal/usage/direct_test.go b/internal/usage/direct_test.go index 850d9c2f..e99e74fe 100644 --- a/internal/usage/direct_test.go +++ b/internal/usage/direct_test.go @@ -26,8 +26,7 @@ func TestDirectCountsOnlySessionFileCalls(t *testing.T) { catalog.Reset() t.Cleanup(catalog.Reset) - t0 := time.Now() - now := time.Date(t0.Year(), t0.Month(), t0.Day(), 12, 0, 0, 0, t0.Location()) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) Append(Record{Time: now.Add(-10 * time.Minute), Agent: "claude", Provider: "relay", Model: "m", Input: 5, Output: 5, Status: 200, Session: "g1"}) // a client built on Codex, which the gateway logs under its own name // while its Codex session file names Codex: the same call, not one of diff --git a/internal/usage/growing_rewrite_test.go b/internal/usage/growing_rewrite_test.go index 994e6035..c4937d23 100644 --- a/internal/usage/growing_rewrite_test.go +++ b/internal/usage/growing_rewrite_test.go @@ -13,6 +13,7 @@ func TestLogGrowingRewriteThenAppend(t *testing.T) { for _, writer := range []string{"this process", "another writer"} { t.Run(writer, func(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) historyLog(t, logBlockRows*2+10) for _, period := range []Period{Today, Week, Month, All} { Summarize(period) @@ -30,7 +31,7 @@ func TestLogGrowingRewriteThenAppend(t *testing.T) { } // Change an early record and grow the same inode. Treating this as an // append would reuse stale blocks and seek into the rewritten prefix. - edited := Record{Time: time.Now(), Agent: "codex", Provider: "relay", Model: "m", Session: "edited-prefix", Input: 73, Status: 200, RequestID: strings.Repeat("r", 2048)} + edited := Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Session: "edited-prefix", Input: 73, Status: 200, RequestID: strings.Repeat("r", 2048)} first, err := json.Marshal(edited) if err != nil { t.Fatal(err) @@ -42,7 +43,7 @@ func TestLogGrowingRewriteThenAppend(t *testing.T) { if err := os.WriteFile(Path(), rewritten, 0600); err != nil { t.Fatal(err) } - added := Record{Time: time.Now(), Agent: "codex", Provider: "relay", Model: "m", Session: "appended-tail", Input: 19, Status: 200} + added := Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Session: "appended-tail", Input: 19, Status: 200} if writer == "this process" { Append(added) } else { @@ -64,7 +65,7 @@ func TestLogGrowingRewriteThenAppend(t *testing.T) { t.Fatalf("fixture rows: %d", len(cold)) } for _, period := range []Period{Today, Week, Month, All} { - got, want := Summarize(period), summarize(period, time.Now(), cold) + got, want := Summarize(period), summarize(period, now, cold) if got.Totals != want.Totals { t.Fatalf("%s summary stale: got %+v want %+v", period, got.Totals, want.Totals) } diff --git a/internal/usage/incremental_log_test.go b/internal/usage/incremental_log_test.go index 9576d4fc..e4260c64 100644 --- a/internal/usage/incremental_log_test.go +++ b/internal/usage/incremental_log_test.go @@ -10,6 +10,8 @@ import ( "github.com/yetone/magpie/internal/testenv" ) +// historyLog writes n calls of 90 days ago, a second apart, and one at +// Clock's time. func historyLog(t testing.TB, n int) { t.Helper() if err := os.MkdirAll(filepath.Dir(Path()), 0700); err != nil { @@ -20,11 +22,12 @@ func historyLog(t testing.TB, n int) { t.Fatal(err) } enc := json.NewEncoder(f) - old := time.Now().AddDate(0, 0, -90) + now := Clock() + old := now.AddDate(0, 0, -90) for i := 0; i < n; i++ { r := Record{Time: old.Add(time.Duration(i) * time.Second), Agent: "codex", Provider: "relay", Model: "m", Session: "s", Input: 10, Status: 200} if i == n-1 { - r.Time = time.Now() + r.Time = now } if err := enc.Encode(r); err != nil { f.Close() @@ -38,6 +41,7 @@ func historyLog(t testing.TB, n int) { func TestUsageOverviewDoesNotReparseHistory(t *testing.T) { pageHome(t) + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) historyLog(t, 4000) if s := Summarize(Today); s.Calls != 1 { t.Fatal(s.Calls) @@ -61,6 +65,7 @@ func TestUsageViasSkipsOldHistory(t *testing.T) { func TestUsageOverviewRefreshesAfterAppendAndReplacement(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) Append(Record{Agent: "codex", Provider: "relay", Model: "m", Input: 2, Status: 200}) if s := Summarize(Today); s.Input != 2 { t.Fatal(s) @@ -70,7 +75,7 @@ func TestUsageOverviewRefreshesAfterAppendAndReplacement(t *testing.T) { t.Fatal(s) } f := filepath.Join(filepath.Dir(Path()), "replacement.jsonl") - b, _ := json.Marshal(Record{Time: time.Now(), Agent: "codex", Provider: "relay", Input: 7, Status: 200}) + b, _ := json.Marshal(Record{Time: now, Agent: "codex", Provider: "relay", Input: 7, Status: 200}) if err := os.WriteFile(f, append(b, '\n'), 0600); err != nil { t.Fatal(err) } @@ -112,9 +117,10 @@ func TestLogAppendReusesSealedBlocks(t *testing.T) { func TestLogPartialLineAndTruncation(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) Append(Record{Agent: "codex", Input: 2, Status: 200}) Summarize(Today) - b, _ := json.Marshal(Record{Time: time.Now(), Agent: "codex", Input: 7, Status: 200}) + b, _ := json.Marshal(Record{Time: now, Agent: "codex", Input: 7, Status: 200}) f, e := os.OpenFile(Path(), os.O_APPEND|os.O_WRONLY, 0600) if e != nil { t.Fatal(e) @@ -143,6 +149,7 @@ func TestLogPartialLineAndTruncation(t *testing.T) { func TestCachedSummaryRemainsCallerOwned(t *testing.T) { pageHome(t) + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) Append(Record{Agent: "codex", Input: 3, Status: 200}) s := Summarize(Today) s.Series[0].Calls = 999 @@ -184,6 +191,7 @@ func BenchmarkIncrementalUsage(b *testing.B) { func TestAppendDoesNotWaitForIndexBuild(t *testing.T) { pageHome(t) + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) logIndex.Lock() done := make(chan struct{}) go func() { Append(Record{Agent: "codex", Input: 1, Status: 200}); close(done) }() diff --git a/internal/usage/ledger.go b/internal/usage/ledger.go index 027f614b..67b1a3e6 100644 --- a/internal/usage/ledger.go +++ b/internal/usage/ledger.go @@ -134,6 +134,12 @@ func (p Period) Since(now time.Time) time.Time { // ledger adds to those the gateway logged. A variable for the tests. var LogCalls func(time.Time) []sessions.Call +// Clock is the time the periods are read by: when today began, the hours +// or days of the chart, the day a cached answer is for. A variable for the +// tests, which hold it still so that midnight never falls between a call +// they log and the period they ask for. +var Clock = time.Now + // Ledgered is a period's calls that a filter keeps, newest first, with their // sum, and the agents and providers that made any call in the period (their // ids, for a filter to offer). @@ -148,7 +154,13 @@ type Ledgered struct { // comes with the calls the agents' session files record that the gateway did // not see. func LedgerOf(p Period, f Filter) Ledgered { - since := p.Since(time.Now()) + return LedgerOfAt(p, f, Clock()) +} + +// LedgerOfAt is LedgerOf with the period read at now, for an answer that +// names that moment elsewhere too, as an exported CSV's name does. +func LedgerOfAt(p Period, f Filter, now time.Time) Ledgered { + since := p.Since(now) gatewaySince := since if !since.IsZero() { gatewaySince = since.Add(-24 * time.Hour) @@ -654,7 +666,12 @@ const seriesKeep = 24 // hour, day or week, for the chart over them. A row is of the point its // time falls in; the rows are in any order. func LedgerSeries(p Period, rows []Row) (bucket string, pts []SeriesPoint) { - now := time.Now() + return ledgerSeriesAt(p, rows, Clock()) +} + +// ledgerSeriesAt is LedgerSeries with the period read at now, the moment the +// rows were read at, so that the chart is of the rows' day. +func ledgerSeriesAt(p Period, rows []Row, now time.Time) (bucket string, pts []SeriesPoint) { var first time.Time for _, r := range rows { if r.IsRejected() { diff --git a/internal/usage/ledger_test.go b/internal/usage/ledger_test.go index ec1a3e65..5c1058be 100644 --- a/internal/usage/ledger_test.go +++ b/internal/usage/ledger_test.go @@ -184,10 +184,9 @@ func TestLedgerWithSessionLogCalls(t *testing.T) { catalog.Reset() t.Cleanup(catalog.Reset) - // noon today, so that what the test lists a few hours before it is still today, - // whenever the test runs - t0 := time.Now() - now := time.Date(t0.Year(), t0.Month(), t0.Day(), 12, 0, 0, 0, t0.Location()) + // noon of the day Clock is held at, so that what the test lists a few + // hours before it is that day's + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) // the gateway's: an answered request of session s1 that began at -10m and // took 20 s, and a failure of another with what the vendor said Append(Record{Time: now.Add(-10 * time.Minute), Agent: "claude", Provider: "claude", Model: "claude-sonnet-5", Input: 5, Output: 5, @@ -274,7 +273,7 @@ func TestLedgerWithSessionLogCalls(t *testing.T) { // with its calls, failures, tokens and cost; a row of before the period is // in none. func TestLedgerSeries(t *testing.T) { - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) midnight := time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, now.Location()) row := func(at time.Time, in, out, cr, cw int, cost float64, priced bool, status int, errText string) Row { return Row{Record: Record{Time: at, Provider: "p", Input: in, Output: out, CacheRead: cr, CacheWrite: cw, Status: status, Error: errText}, Cost: cost, Priced: priced} @@ -331,7 +330,7 @@ func TestLedgerSeries(t *testing.T) { // as the point's own sums do, for a chart of speed to tell the models // apart (#860): a failed call and one too fast to time count in neither. func TestLedgerSeriesSpeed(t *testing.T) { - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) at := time.Date(now.Year(), now.Month(), now.Day(), 0, 10, 0, 0, now.Location()) row := func(model string, out int, ms, ttft int64, status int) Row { return Row{Record: Record{Time: at, Provider: "p", Model: model, Output: out, Millis: ms, TTFT: ttft, Status: status}} @@ -363,7 +362,7 @@ func TestLedgerSeriesSpeed(t *testing.T) { // timeline for a chart to stack — the ones with the most tokens over the // period, the rest left to the point's own sums. func TestLedgerByProvider(t *testing.T) { - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) at := time.Date(now.Year(), now.Month(), now.Day(), 0, 10, 0, 0, now.Location()) rec := func(agent, prov, model string, in, cw int, mins int) Record { return Record{Time: at.Add(time.Duration(mins) * time.Minute), Agent: agent, Provider: prov, Model: model, Input: in, CacheRead: cw, Output: 1, Status: 200} diff --git a/internal/usage/priced_blocks_test.go b/internal/usage/priced_blocks_test.go index c1695d8c..a0608a3b 100644 --- a/internal/usage/priced_blocks_test.go +++ b/internal/usage/priced_blocks_test.go @@ -24,6 +24,7 @@ func appendAndQueryAllocs(t *testing.T, n int) float64 { } func TestRequestPageAppendDoesNotRepriceHistory(t *testing.T) { + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) // A query costs a fixed number of allocations that depends on the // machine (on Windows, provider sign-in lookups read the environment and // registry), so the budget is what 7990 more records of history add: diff --git a/internal/usage/purpose_test.go b/internal/usage/purpose_test.go index 4c14400f..53621737 100644 --- a/internal/usage/purpose_test.go +++ b/internal/usage/purpose_test.go @@ -41,7 +41,8 @@ func TestPurposeFilter(t *testing.T) { func TestPurposeRequestPages(t *testing.T) { pageHome(t) - start := Today.Since(time.Now()).Add(time.Second) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) + start := Today.Since(now).Add(time.Second) kinds := []string{"thread_title", "review", "thread_title_reconsideration", "future_kind", "", "title_generation", "unmarked"} for i, kind := range kinds { Append(Record{Time: start.Add(time.Duration(i) * time.Second), Agent: "codex", Provider: "openai", Model: "m", diff --git a/internal/usage/request_day_test.go b/internal/usage/request_day_test.go index b84842cd..1a3bcbf8 100644 --- a/internal/usage/request_day_test.go +++ b/internal/usage/request_day_test.go @@ -9,7 +9,7 @@ import ( func TestRequestPageDay(t *testing.T) { pageHome(t) - start := Today.Since(time.Now()).AddDate(0, 0, -1) + start := Today.Since(holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))).AddDate(0, 0, -1) end := start.AddDate(0, 0, 1) day := start.Format(time.DateOnly) gateway := &rowChunk{} diff --git a/internal/usage/request_index_review_test.go b/internal/usage/request_index_review_test.go index f991b6d9..1cc8b187 100644 --- a/internal/usage/request_index_review_test.go +++ b/internal/usage/request_index_review_test.go @@ -60,7 +60,7 @@ func TestQueryPageIOOutsideCacheLock(t *testing.T) { path := filepath.Join(sessions.ClaudeDir(), "projects", "p", "yesterday.jsonl") os.MkdirAll(filepath.Dir(path), 0700) os.WriteFile(path, []byte("{}\n"), 0600) - at := time.Now().Add(-48 * time.Hour) + at := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)).Add(-48 * time.Hour) os.Chtimes(path, at, at) entered, release, done := make(chan struct{}), make(chan struct{}), make(chan struct{}) go func() { diff --git a/internal/usage/request_page.go b/internal/usage/request_page.go index be2e1cfe..7560de7a 100644 --- a/internal/usage/request_page.go +++ b/internal/usage/request_page.go @@ -214,9 +214,12 @@ func queryPage(p Period, f Filter, offset, limit int, readSource func(sessions.C } limit = min(limit, 500) offset = max(0, offset) + // The time is read once, so that the rows, the chart and the day the page + // is kept for are of one day when midnight falls while it is worked out. + now := Clock() // A replacement reader remains useful to callers supplying synthetic logs. if LogCalls != nil { - return pageFromLedger(p, f, offset, limit, LedgerOf(p, Filter{})) + return pageFromLedgerAt(p, f, offset, limit, LedgerOfAt(p, Filter{}, now), now) } sources := sessions.CallSources() slices.SortFunc(sources, func(a, b sessions.CallSource) int { @@ -248,7 +251,7 @@ func queryPage(p Period, f Filter, offset, limit int, readSource func(sessions.C h.Reset() snapshot := logSnapshotFor(true) version := snapshot.version - fmt.Fprint(h, meta, version, time.Now().Format("2006-01-02 MST")) + fmt.Fprint(h, meta, version, now.Format("2006-01-02 MST")) for _, s := range sources { fmt.Fprintf(h, "%s:%d:%d;", s.Path, s.Size, s.Modified.UnixNano()) } @@ -301,7 +304,7 @@ func queryPage(p Period, f Filter, offset, limit int, readSource func(sessions.C row.Agent = AgentOf(r.Agent) return row } - since := p.Since(time.Now()) + since := p.Since(now) gatewaySince := since if !since.IsZero() { gatewaySince = since.Add(-24 * time.Hour) @@ -444,7 +447,7 @@ func queryPage(p Period, f Filter, offset, limit int, readSource func(sessions.C if someShared { names = sharedNames() } - page := buildRequestBlocks(p, f, offset, limit, gateways, chunks, others, names) + page := buildRequestBlocks(p, f, offset, limit, now, gateways, chunks, others, names) shared.Lock() defer shared.Unlock() // A query for an older filesystem snapshot may finish after a newer one. @@ -724,13 +727,15 @@ func sharesOf(m map[string]*Share) []Share { return out } func buildRequestPage(p Period, f Filter, offset, limit int, gateway *rowChunk, chunks []*rowChunk) RequestPage { - return buildRequestBlocks(p, f, offset, limit, []*rowChunk{gateway}, chunks, nil, nil) + return buildRequestBlocks(p, f, offset, limit, Clock(), []*rowChunk{gateway}, chunks, nil, nil) } // Shared days are never matched to this computer's gateway or session calls. -func buildRequestBlocks(p Period, f Filter, offset, limit int, gateways, chunks, others []*rowChunk, names map[string]string) RequestPage { +// now is the moment the page is asked at: its period and its chart's hours or +// days are read from it. +func buildRequestBlocks(p Period, f Filter, offset, limit int, now time.Time, gateways, chunks, others []*rowChunk, names map[string]string) RequestPage { skip := visibleLocal(chunks) - since := p.Since(time.Now()) + since := p.Since(now) matched := matchedBlocks(gateways, chunks, skip, since, true) all := append(append(slices.Clone(gateways), chunks...), others...) visit := func(fn func(rowRef, Row)) { @@ -897,7 +902,7 @@ func buildRequestBlocks(p Period, f Filter, offset, limit int, gateways, chunks, out.Computers, out.Names = computerShares(computers, names) var base []Point chartSince := since - chartSince, out.Bucket, base = timeline(p, time.Now(), first) + chartSince, out.Bucket, base = timeline(p, now, first) out.Series = make([]SeriesPoint, len(base)) for i := range base { out.Series[i] = SeriesPoint{Point: base[i], By: map[string]map[string]Part{}} @@ -945,6 +950,12 @@ func buildRequestBlocks(p Period, f Filter, offset, limit int, gateways, chunks, return out } func pageFromLedger(p Period, f Filter, offset, limit int, all Ledgered) RequestPage { + return pageFromLedgerAt(p, f, offset, limit, all, Clock()) +} + +// pageFromLedgerAt is the page of a ledger read at now, its chart over the +// period read at the same moment. +func pageFromLedgerAt(p Period, f Filter, offset, limit int, all Ledgered, now time.Time) RequestPage { l := all.Filtered(f) out := RequestPage{Sum: l.Sum, Total: len(l.Rows), Agents: l.Agents, Providers: l.Providers, Purposes: []string{}, By: map[string][]Share{}} callers, accounts := map[string]*Group{}, map[string]*Group{} @@ -969,7 +980,7 @@ func pageFromLedger(p Period, f Filter, offset, limit int, all Ledgered) Request chartRows = all.Filtered(chartFilter).Rows out.ChartBy = map[string][]Share{} } - out.Bucket, out.Series = LedgerSeries(p, chartRows) + out.Bucket, out.Series = ledgerSeriesAt(p, chartRows, now) for _, d := range Dimensions { g := f if d == "provider" { diff --git a/internal/usage/request_page_test.go b/internal/usage/request_page_test.go index 266ff923..c7d0b790 100644 --- a/internal/usage/request_page_test.go +++ b/internal/usage/request_page_test.go @@ -67,7 +67,7 @@ func equalPage(t *testing.T, got, want RequestPage) { func TestCompactPageMatchesLedger(t *testing.T) { pageHome(t) - now := time.Now().Truncate(time.Second) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) var recs []Record var logs []sessions.Call for i := 0; i < 180; i++ { @@ -147,7 +147,7 @@ func TestCompactPageMatchesLedger(t *testing.T) { func TestRequestPageModelRankingKeepsAlternatives(t *testing.T) { pageHome(t) - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) records := []Record{ {Time: now, Provider: "a", Agent: "codex", Model: "gpt-5", Input: 10}, {Time: now, Provider: "a", Agent: "codex", Model: "gpt-5-mini", Input: 20}, @@ -204,11 +204,12 @@ func TestQueryPageSourceAndIdentityInvalidation(t *testing.T) { provider.ForgetAccounts() provider.Accounts() sessionAuth(t, sessions.CodexDir(), "a", "u", "one@example.com") + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) path := filepath.Join(sessions.CodexDir(), "sessions", "rollout-2026-09-30T00-00-00-test.jsonl") os.MkdirAll(filepath.Dir(path), 0700) meta := `{"type":"session_meta","payload":{"id":"test","model_provider":"custom","creator_account_id":"a","creator_user_id":"u"}}` + "\n" + `{"type":"turn_context","payload":{"model":"m","effort":"high"}}` + "\n" line := func(n int) string { - return fmt.Sprintf(`{"timestamp":%q,"type":"event_msg","payload":{"type":"token_count","info":{"total_token_usage":{"input_tokens":%d,"output_tokens":%d},"last_token_usage":{"input_tokens":10,"output_tokens":1}}}}`+"\n", time.Now().Format(time.RFC3339Nano), n*10, n) + return fmt.Sprintf(`{"timestamp":%q,"type":"event_msg","payload":{"type":"token_count","info":{"total_token_usage":{"input_tokens":%d,"output_tokens":%d},"last_token_usage":{"input_tokens":10,"output_tokens":1}}}}`+"\n", now.Format(time.RFC3339Nano), n*10, n) } os.WriteFile(path, []byte(meta+line(1)), 0600) check := func(n int, account string, official bool) { @@ -245,7 +246,7 @@ func TestQueryPageSourceAndIdentityInvalidation(t *testing.T) { sessionAuth(t, sessions.CodexDir(), "other", "u", "wrong@example.com") check(2, "", false) os.MkdirAll(filepath.Dir(Path()), 0700) - r, _ := json.Marshal(Record{Time: time.Now(), Model: "m", Agent: "opencode", Input: 10, Output: 1}) + r, _ := json.Marshal(Record{Time: now, Model: "m", Agent: "opencode", Input: 10, Output: 1}) os.WriteFile(Path(), r, 0600) check(2, "", false) // partial gateway line appendFile(Path(), "\n") @@ -270,7 +271,7 @@ func TestQueryPageSourceAndIdentityInvalidation(t *testing.T) { // (inaction on Discord). func TestRequestPageRanksModelAtEachProvider(t *testing.T) { pageHome(t) - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) records := []Record{ {Time: now, Provider: "zhipu", Agent: "claude", Model: "glm-5.3", Output: 1000, Millis: 2200, TTFT: 200}, {Time: now, Provider: "zhipu", Agent: "claude", Model: "glm-5.3", Output: 1000, Millis: 2200, TTFT: 200}, diff --git a/internal/usage/review_test.go b/internal/usage/review_test.go index d94da5fe..bcdfe2ed 100644 --- a/internal/usage/review_test.go +++ b/internal/usage/review_test.go @@ -51,7 +51,7 @@ func TestRejectedOnlyInRequestRows(t *testing.T) { t.Setenv("XDG_CONFIG_HOME", t.TempDir()) catalog.Reset() t.Cleanup(catalog.Reset) - now := time.Now() + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) recs := []Record{{Time: now, Agent: "codex", Provider: "relay", Model: "m", Status: 200, Input: 2}, {Time: now, Agent: "codex", Status: 404, Error: "unknown model", Rejected: true}, {Time: now, Agent: "codex", Status: 400}} rows, sum, _ := ledger(time.Time{}, Filter{}, recs) if len(rows) != 3 || sum.Calls != 1 || sum.Errors != 0 { diff --git a/internal/usage/summary_cache.go b/internal/usage/summary_cache.go index 3eb211e0..c110d8a0 100644 --- a/internal/usage/summary_cache.go +++ b/internal/usage/summary_cache.go @@ -26,11 +26,10 @@ var summaries struct { entries map[Period]summaryEntry } -func indexedSummary(p Period) Summary { +func indexedSummary(p Period, now time.Time) Summary { if p != Today && p != Week && p != Month { p = All } - now := time.Now() snapshot := logSnapshotFor(true) _, offset := now.Zone() meta := fmt.Sprintf("%s|%s|%s|%s|%s|%s|%d", statKey(settings.Path()), statKey(provider.Path()), statKey(catalog.CachePath()), statKey(catalog.LivePath("antigravity")), now.Format("2006-01-02"), now.Location(), offset) diff --git a/internal/usage/summary_cache_test.go b/internal/usage/summary_cache_test.go index 0154a86a..7fc6fd47 100644 --- a/internal/usage/summary_cache_test.go +++ b/internal/usage/summary_cache_test.go @@ -11,10 +11,11 @@ import ( func TestSummaryInvalidatesLiveFreePrice(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) if err := provider.Save(provider.Provider{ID: "cline-relay", Chat: "https://api.cline.bot/v1", Key: "x", Catalog: "openai"}); err != nil { t.Fatal(err) } - Append(Record{Time: time.Now(), Agent: "codex", Provider: "cline-relay", Model: "m", Input: 1000000, Status: 200}) + Append(Record{Time: now, Agent: "codex", Provider: "cline-relay", Model: "m", Input: 1000000, Status: 200}) if err := catalog.SaveLive("cline-relay", "https://api.cline.bot/v1", []catalog.Model{{ID: "m", Free: false}}); err != nil { t.Fatal(err) } @@ -25,7 +26,7 @@ func TestSummaryInvalidatesLiveFreePrice(t *testing.T) { if err := catalog.SaveLive("cline-relay", "https://api.cline.bot/v1", []catalog.Model{{ID: "m", Free: true}}); err != nil { t.Fatal(err) } - direct := summarize(Today, time.Now(), Load(time.Time{})) + direct := summarize(Today, now, Load(time.Time{})) if direct.Cost != 0 { t.Fatalf("need free direct summary: %#v", direct.Totals) } @@ -36,12 +37,13 @@ func TestSummaryInvalidatesLiveFreePrice(t *testing.T) { func TestSummaryInvalidatesSameStampPrice(t *testing.T) { pageHome(t) + now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) s := settings.Load() s.ModelPrices = map[string]settings.ModelPrice{"*/m": {Input: new(2.0), Output: new(8.0), CacheRead: new(0.0), CacheWrite: new(0.0)}} if err := settings.Save(s); err != nil { t.Fatal(err) } - Append(Record{Time: time.Now(), Agent: "codex", Provider: "relay", Model: "m", Input: 1000000, Status: 200}) + Append(Record{Time: now, Agent: "codex", Provider: "relay", Model: "m", Input: 1000000, Status: 200}) first := Summarize(Today) if first.Cost != 2 { t.Fatalf("need paid baseline: %#v", first.Totals) @@ -58,7 +60,7 @@ func TestSummaryInvalidatesSameStampPrice(t *testing.T) { if err := os.Chtimes(settings.Path(), old.ModTime(), old.ModTime()); err != nil { t.Fatal(err) } - direct := summarize(Today, time.Now(), Load(time.Time{})) + direct := summarize(Today, now, Load(time.Time{})) if direct.Cost != 4 { t.Fatalf("direct failed coarse-stamp guard: %#v", direct.Totals) } diff --git a/internal/usage/usage.go b/internal/usage/usage.go index a3750cff..ab3d5ff2 100644 --- a/internal/usage/usage.go +++ b/internal/usage/usage.go @@ -146,7 +146,7 @@ var mu sync.Mutex // break a call. func Append(r Record) { if r.Time.IsZero() { - r.Time = time.Now() + r.Time = Clock() } offerOTel(r) b, err := json.Marshal(r) @@ -492,7 +492,7 @@ type Summary struct { // Summarize caches the four periods over an indexed log snapshot. Callers // receive their own result slices, without retaining historical Records. func Summarize(p Period) Summary { - return indexedSummary(p) + return indexedSummary(p, Clock()) } func summarize(p Period, now time.Time, recs []Record) Summary { diff --git a/internal/usage/usage_test.go b/internal/usage/usage_test.go index 12bcd54f..d45cd237 100644 --- a/internal/usage/usage_test.go +++ b/internal/usage/usage_test.go @@ -233,11 +233,12 @@ func TestReasoningReplyTimedByItsAnswer(t *testing.T) { } var rows Totals var lr []Row + held := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) for _, r := range recs { rows.addRow(Row{Record: r}) - // LedgerSeries buckets today by the clock, so the timeline's rows - // are made now - r.Time = time.Now() + // LedgerSeries buckets today by Clock, so the timeline's rows are + // made at the time it is held at + r.Time = held lr = append(lr, Row{Record: r}) } if rows.Timed != 6 || rows.DecodeMs != ms || rows.DecodeOut != out { diff --git a/quota_cli.go b/quota_cli.go index 2b4b1532..bfcf050c 100644 --- a/quota_cli.go +++ b/quota_cli.go @@ -127,10 +127,11 @@ func quotaCmd(args []string) error { for _, q := range qs { width = max(width, len([]rune(quotaTitle(q)))) } + now := time.Now() // one instant for every window's reset time for _, q := range qs { line := fmt.Sprintf("%-*s %s", width, quotaTitle(q), muted.Render(fmt.Sprintf("%-12s", q.Kind))) for _, w := range q.Windows { - line += " " + quotaCell(w) + line += " " + quotaCell(w, now) } if q.Balance != "" { line += " " + balanceCell(q.Balance, q.Provider, q.User) diff --git a/usage_cli.go b/usage_cli.go index 614d80fd..f6b9a043 100644 --- a/usage_cli.go +++ b/usage_cli.go @@ -80,10 +80,11 @@ func usageTo(out io.Writer, args []string) error { return stats.WriteCSV(out, rows) } loadCostCurrency() - s := stats.Summarize(period) - // the calls the agents made on their own, read from their session files: - // the window's Requests tab counts them too (Kumo31 on Discord) - d := stats.Direct(period) + // s is the calls through magpie, d the calls the agents made on their + // own, read from their session files: the window's Requests tab counts + // them too (Kumo31 on Discord). Asked together, both are of one day when + // midnight falls while they are read. + s, d := stats.Summaries(period) title := map[stats.Period]string{stats.Today: "today", stats.Week: "last 7 days", stats.Month: "last 30 days", stats.All: "all time"}[s.Period] if s.Calls == 0 && d.Calls == 0 { fmt.Fprintln(out, muted.Render("no calls "+title+" ·"), "route an agent through magpie and its usage shows up here") diff --git a/usage_cli_test.go b/usage_cli_test.go index 76657cd5..56ea6998 100644 --- a/usage_cli_test.go +++ b/usage_cli_test.go @@ -3,6 +3,7 @@ package main import ( "encoding/csv" "strings" + "sync/atomic" "testing" "time" @@ -11,12 +12,38 @@ import ( stats "github.com/yetone/magpie/internal/usage" ) +// holdUsageClock stops the usage clock at at for the test and gives at back, +// for the test to stamp its calls by: midnight then never falls between a +// call and the period it is asked for in. +func holdUsageClock(t *testing.T, at time.Time) time.Time { + t.Helper() + old := stats.Clock + stats.Clock = func() time.Time { return at } + t.Cleanup(func() { stats.Clock = old }) + return at +} + +// midnightUsageClock sets the usage clock to read a tenth of a second before +// midnight the first time and a tenth of a second after it from then on, as +// when midnight falls while magpie usage is worked out. +func midnightUsageClock(t *testing.T, midnight time.Time) { + t.Helper() + var read atomic.Bool + old := stats.Clock + stats.Clock = func() time.Time { + if read.Swap(true) { + return midnight.Add(100 * time.Millisecond) + } + return midnight.Add(-100 * time.Millisecond) + } + t.Cleanup(func() { stats.Clock = old }) +} + // magpie usage --csv writes the period's requests, newest first, one row // each, with the model asked for, sent and served. func TestUsageCSV(t *testing.T) { groupsHome(t) - y, m, d := time.Now().Date() - day := time.Date(y, m, d, 0, 0, 0, 0, time.Local) // today's, whenever this runs + day := stats.Today.Since(holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local))) stats.Append(stats.Record{Time: day.Add(time.Second), Agent: "codex", Provider: "a", Model: "m", Requested: "fast", Served: "m-mini", Input: 10, Output: 2, Millis: 700, Status: 200}) stats.Append(stats.Record{Time: day.Add(2 * time.Second), Agent: "claude", Provider: "b", Model: "gpt-5.5", Requested: "b/gpt-5.5", Millis: 30, Status: 502}) stats.Append(stats.Record{Time: day.AddDate(0, 0, -3), Agent: "pi", Provider: "a", Model: "m", Input: 1, Status: 200}) @@ -78,7 +105,7 @@ func TestUsageProviderKeys(t *testing.T) { // does (Kumo31 on Discord: Codex used outside magpie wasn't in it). func TestUsageShowsCallsNotThroughMagpie(t *testing.T) { groupsHome(t) - now := time.Now() + now := holdUsageClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) stats.Append(stats.Record{Time: now.Add(-time.Minute), Agent: "claude", Provider: "relay", Model: "m", Input: 5, Status: 200}) old := stats.LogCalls stats.LogCalls = func(time.Time) []sessions.Call { @@ -104,3 +131,26 @@ func TestUsageShowsCallsNotThroughMagpie(t *testing.T) { t.Fatal(b.String(), err) } } + +// magpie usage asked as midnight falls shows the calls through magpie and +// those not through it of one day, the day it was asked on. Asked apart, +// the calls not through magpie were the next day's, none yet, and left out. +func TestUsageAskedAtMidnight(t *testing.T) { + groupsHome(t) + midnight := time.Date(2026, 10, 1, 0, 0, 0, 0, time.Local) + stats.Append(stats.Record{Time: midnight.Add(-time.Minute), Agent: "claude", Provider: "relay", Model: "m", Input: 5, Status: 200}) + old := stats.LogCalls + stats.LogCalls = func(time.Time) []sessions.Call { + return []sessions.Call{{Time: midnight.Add(-2 * time.Minute), Agent: "codex", Session: "c1", Model: "gpt-6-luna", Tokens: sessions.Tokens{Input: 1200, Output: 300}}} + } + t.Cleanup(func() { stats.LogCalls = old }) + midnightUsageClock(t, midnight) + var b strings.Builder + if err := usageTo(&b, []string{"usage", "today"}); err != nil { + t.Fatal(err) + } + gw, own, ok := strings.Cut(b.String(), "not through magpie") + if !ok || !strings.Contains(gw, "relay/m") || !strings.Contains(own, "gpt-6-luna") { + t.Fatal(b.String()) + } +}