Public: anyone can read this; the crew can change it.
`after the push` means after the push: measure from the push and say the wait #90
Check · Review · Land · Live done — Landed and live in production.
torque/forge:torque/80-after-the-push-means-after-the-push-meas → main 1 commit fork
5 files
changed +232
−13
docs/APPS.md +8 −1
| @@ -83,7 +83,14 @@ around it. None is advisory. | ||
| 83 | 83 | `servingAt` is stamped once, at the swap-in, distinct from `startedAt` |
| 84 | 84 | (the deploy's own start) and `finishedAt` (which waits on `test` |
| 85 | 85 | beside it) — so how long a change took to reach its preview is a |
| 86 | number the forge can read back, not a line buried in the log. | |
| 86 | number the forge can read back, not a line buried in the log. A page | |
| 87 | words that number from `createdAt`, the instant the push created the | |
| 88 | run, because the deploy may have waited on the concurrency gate for a | |
| 89 | permit first: `servedPhrase` (`web/ui.ts`) says `6.1s after the push · | |
| 90 | 2.4s queued` and is the only place it is worded. The deploy's own log | |
| 91 | line stays measured from `startedAt` and says `after the deploy | |
| 92 | started`; a deploy no push asked for — a redeploy someone pressed, a | |
| 93 | boot reconcile — is worded the same way and never claims a push. | |
| 87 | 94 | 5. **A private app answers only to someone the forge vouches for.** An app's |
| 88 | 95 | `access` is `public` or `private` (defaulting to the repository's |
| 89 | 96 | visibility), and it is set apart from the repository's own: the code can |
src/apps/runtime.ts +33 −3
| @@ -93,7 +93,14 @@ export interface EnvStatus { | ||
| 93 | 93 | readonly since?: string | undefined; |
| 94 | 94 | /** The instant this deployment started serving, set once at the swap-in. */ |
| 95 | 95 | readonly servingAt?: string | undefined; |
| 96 | /** The deploy run's own start — the reference `servingAt` is measured from. */ | |
| 96 | /** | |
| 97 | * The instant the push created this deploy run — what a person means by | |
| 98 | * "after the push", and the reference `servedPhrase` measures from. Unset | |
| 99 | * for a deploy no push asked for (a redeploy someone pressed, a boot | |
| 100 | * reconcile), so the words for those never claim a push that never was. | |
| 101 | */ | |
| 102 | readonly createdAt?: string | undefined; | |
| 103 | /** The deploy run's own start — after however long it waited for a permit. */ | |
| 97 | 104 | readonly deployStartedAt?: string | undefined; |
| 98 | 105 | readonly error?: string | undefined; |
| 99 | 106 | /** |
| @@ -120,10 +127,20 @@ interface Live { | ||
| 120 | 127 | * unset on the value `bringUp` returns, which does not yet know it. |
| 121 | 128 | */ |
| 122 | 129 | readonly servingAt?: string | undefined; |
| 123 | /** The deploy run's own start — the reference `servingAt` is measured from. */ | |
| 130 | /** The instant the push created this deploy run, when a push did. */ | |
| 131 | readonly createdAt?: string | undefined; | |
| 132 | /** The deploy run's own start — the reference the deploy log measures from. */ | |
| 124 | 133 | readonly deployStartedAt?: string | null | undefined; |
| 125 | 134 | } |
| 126 | 135 | |
| 136 | /** | |
| 137 | * The deploy reasons a ref moving created: for these the run's `createdAt` | |
| 138 | * is the instant of the push that asked for the deploy, so the wait for a | |
| 139 | * permit sits inside the number the studio prints. A redeploy someone | |
| 140 | * pressed, a crash restart, and a boot or enable reconcile are not pushes. | |
| 141 | */ | |
| 142 | const PUSH_REASONS: readonly string[] = ["push", "opened", "merge"]; | |
| 143 | ||
| 127 | 144 | /** How long between two instants, in seconds to one decimal place: `3.4s`. */ |
| 128 | 145 | function elapsedSeconds(fromIso: string, toIso: string): string { |
| 129 | 146 | const ms = Math.max(0, Date.parse(toIso) - Date.parse(fromIso)); |
| @@ -266,6 +283,7 @@ export class AppsRuntime { | ||
| 266 | 283 | port: state.live.handle.port, |
| 267 | 284 | since: state.live.since, |
| 268 | 285 | servingAt: state.live.servingAt, |
| 286 | createdAt: state.live.createdAt, | |
| 269 | 287 | ...(state.live.deployStartedAt === null |
| 270 | 288 | ? {} |
| 271 | 289 | : { deployStartedAt: state.live.deployStartedAt }), |
| @@ -283,6 +301,7 @@ export class AppsRuntime { | ||
| 283 | 301 | runId: swapped ? state.deploying!.run.id : state.live.runId, |
| 284 | 302 | since: state.live.since, |
| 285 | 303 | servingAt: state.live.servingAt, |
| 304 | createdAt: state.live.createdAt, | |
| 286 | 305 | ...(state.live.deployStartedAt === null |
| 287 | 306 | ? {} |
| 288 | 307 | : { deployStartedAt: state.live.deployStartedAt }), |
| @@ -656,7 +675,18 @@ export class AppsRuntime { | ||
| 656 | 675 | const served = markServing(this.app.db, run.id); |
| 657 | 676 | const servingAt = served?.servingAt ?? new Date().toISOString(); |
| 658 | 677 | const deployStartedAt = claimed.startedAt; |
| 659 | const live: Live = { ...outcome.value, servingAt, deployStartedAt }; | |
| 678 | // The run was created the instant the push asked for it; it started when | |
| 679 | // the gate handed it a permit. Both travel with the deployment: the log | |
| 680 | // below is measured from the start, the studio's phrase from the push. | |
| 681 | const createdAt = PUSH_REASONS.includes(run.reason) | |
| 682 | ? run.createdAt | |
| 683 | : undefined; | |
| 684 | const live: Live = { | |
| 685 | ...outcome.value, | |
| 686 | servingAt, | |
| 687 | createdAt, | |
| 688 | deployStartedAt, | |
| 689 | }; | |
| 660 | 690 | state.live = live; |
| 661 | 691 | state.lastError = undefined; |
| 662 | 692 | if (previous !== undefined) { |
src/web/ui.ts +33 −8
| @@ -51,18 +51,43 @@ export function time(iso: string): Html { | ||
| 51 | 51 | >`; |
| 52 | 52 | } |
| 53 | 53 | |
| 54 | /** Seconds to one decimal: `3.4s`. A clock that ran backwards reads `0.0s`. */ | |
| 55 | function seconds(ms: number): string { | |
| 56 | return `${(Math.max(0, ms) / 1000).toFixed(1)}s`; | |
| 57 | } | |
| 58 | ||
| 59 | /** The wait a phrase bothers to name: under this it is noise, not news. */ | |
| 60 | const QUEUED_FLOOR_MS = 1_000; | |
| 61 | ||
| 54 | 62 | /** |
| 55 | 63 | * How long a deployment took to start serving, worded for a person: |
| 56 | * `3.4s after the push`. Undefined until it has — never a zero. | |
| 64 | * `3.4s after the push` — measured from the instant the push created the | |
| 65 | * deploy run, so however long it waited for a permit is inside the number. | |
| 66 | * When that wait was a second or more it is named too, because the number | |
| 67 | * is otherwise a puzzle: `6.1s after the push · 2.4s queued`. | |
| 68 | * | |
| 69 | * A deploy no push asked for (a redeploy someone pressed, a boot reconcile) | |
| 70 | * has no push to measure from: it is measured from its own start and says | |
| 71 | * so, the same sentence its log makes. Undefined until it serves — never a | |
| 72 | * zero, and never a negative when two clocks disagree. | |
| 57 | 73 | */ |
| 58 | 74 | export function servedPhrase(env: EnvStatus): string | undefined { |
| 59 | if (env.servingAt === undefined || env.deployStartedAt === undefined) | |
| 60 | return undefined; | |
| 61 | const ms = Math.max( | |
| 62 | 0, | |
| 63 | Date.parse(env.servingAt) - Date.parse(env.deployStartedAt), | |
| 64 | ); | |
| 65 | return `${(ms / 1000).toFixed(1)}s after the push`; | |
| 75 | if (env.servingAt === undefined) return undefined; | |
| 76 | const servedAt = Date.parse(env.servingAt); | |
| 77 | const pushedAt = env.createdAt === undefined ? NaN : Date.parse(env.createdAt); | |
| 78 | const startedAt = | |
| 79 | env.deployStartedAt === undefined ? NaN : Date.parse(env.deployStartedAt); | |
| 80 | const pushed = Number.isFinite(pushedAt); | |
| 81 | const from = pushed ? pushedAt : startedAt; | |
| 82 | if (!Number.isFinite(servedAt) || !Number.isFinite(from)) return undefined; | |
| 83 | const phrase = `${seconds(servedAt - from)} ${ | |
| 84 | pushed ? "after the push" : "after the deploy started" | |
| 85 | }`; | |
| 86 | if (!pushed || !Number.isFinite(startedAt)) return phrase; | |
| 87 | const queued = startedAt - pushedAt; | |
| 88 | return queued >= QUEUED_FLOOR_MS | |
| 89 | ? `${phrase} · ${seconds(queued)} queued` | |
| 90 | : phrase; | |
| 66 | 91 | } |
| 67 | 92 | |
| 68 | 93 | /** |
test/apps.test.ts +13
| @@ -558,6 +558,14 @@ describe("apps: production, previews, data, gates, crew", () => { | ||
| 558 | 558 | // finished, so `servingAt` is already recorded on the still-open run. |
| 559 | 559 | expect(run?.servingAt).not.toBeNull(); |
| 560 | 560 | |
| 561 | // The pull's push created this run: the status carries that instant, so | |
| 562 | // the words a page prints measure from the push and not from the permit | |
| 563 | // the gate handed out however much later. | |
| 564 | expect(status?.createdAt).toBe(run!.createdAt); | |
| 565 | expect(Date.parse(status!.deployStartedAt!)).toBeGreaterThanOrEqual( | |
| 566 | Date.parse(status!.createdAt!), | |
| 567 | ); | |
| 568 | ||
| 561 | 569 | // `app.serving` published the same instant, with the tests it started |
| 562 | 570 | // beside still going — this is what a preview's look is taken from. |
| 563 | 571 | const serving = listEvents(app.db, { repoId: repo.id, limit: 200 }).find( |
| @@ -851,6 +859,11 @@ describe("apps: production, previews, data, gates, crew", () => { | ||
| 851 | 859 | ); |
| 852 | 860 | expect(production.state).toBe("ok"); |
| 853 | 861 | expect((await viaHost(`hello.${DOMAIN}`)).status).toBe(200); |
| 862 | // No push asked for this one, so it carries no push instant to claim: | |
| 863 | // a boot reconcile is worded from the deploy's own start. | |
| 864 | const booted = runtime.envStatus(record, "production"); | |
| 865 | expect(booted?.createdAt).toBeUndefined(); | |
| 866 | expect(booted?.deployStartedAt).toBeDefined(); | |
| 854 | 867 | const openPreviews = listRuns(app.db, repo.id, { kind: "deploy" }).filter( |
| 855 | 868 | (r) => r.reason === "boot" && r.env !== "production", |
| 856 | 869 | ); |
test/studio.test.ts +145 −1
| @@ -10,7 +10,7 @@ import { dirname, join } from "node:path"; | ||
| 10 | 10 | import { createApp, type App } from "../src/app.ts"; |
| 11 | 11 | import { enableApp } from "../src/actions/apps.ts"; |
| 12 | 12 | import { previewEnv, type EnvName } from "../src/apps/data.ts"; |
| 13 | import { AppsRuntime } from "../src/apps/runtime.ts"; | |
| 13 | import { AppsRuntime, type EnvStatus } from "../src/apps/runtime.ts"; | |
| 14 | 14 | import { getAppByRepo, type AppRecord } from "../src/core/apps.ts"; |
| 15 | 15 | import { addToCrew, createAgent } from "../src/actions/crew.ts"; |
| 16 | 16 | import { linkIssue } from "../src/actions/dependencies.ts"; |
| @@ -43,6 +43,7 @@ import type { Decider } from "../src/crew/decide.ts"; | ||
| 43 | 43 | import { CHECK_FAILED_LIMIT } from "../src/crew/dispatch.ts"; |
| 44 | 44 | import { serve, type Servers } from "../src/http/server.ts"; |
| 45 | 45 | import { pendingLeans, pullWord, runWord, type WordCtx } from "../src/web/pages/studio.ts"; |
| 46 | import { servedPhrase } from "../src/web/ui.ts"; | |
| 46 | 47 | import { repoDir } from "../src/git/repos.ts"; |
| 47 | 48 | |
| 48 | 49 | /** One transparent pixel, dropped where a look would sit. */ |
| @@ -1468,6 +1469,69 @@ describe("the app's live fragment: /:owner/:name/app/state", () => { | ||
| 1468 | 1469 | expect(live).toContain(link); |
| 1469 | 1470 | }); |
| 1470 | 1471 | |
| 1472 | test("the head measures from the push, not from the permit it waited for: a deploy queued 5s reads 6.0s after the push and names the wait", async () => { | |
| 1473 | const createdAt = new Date(Date.now() - 20_000).toISOString(); | |
| 1474 | const deployStartedAt = new Date(Date.parse(createdAt) + 5_000).toISOString(); | |
| 1475 | const servingAt = new Date(Date.parse(deployStartedAt) + 1_000).toISOString(); | |
| 1476 | const deployRun = createRun(app.db, { | |
| 1477 | repoId: repo.id, | |
| 1478 | kind: "deploy", | |
| 1479 | env: "production", | |
| 1480 | commitOid: "cafebabe", | |
| 1481 | reason: "push", | |
| 1482 | }); | |
| 1483 | claimRun(app.db, deployRun.id); | |
| 1484 | finishRun(app.db, deployRun.id, { state: "ok", summary: "deploy" }); | |
| 1485 | putEnv("production", { | |
| 1486 | live: { | |
| 1487 | commitOid: "cafebabe", | |
| 1488 | handle: { port: 4322 }, | |
| 1489 | runId: deployRun.id, | |
| 1490 | since: servingAt, | |
| 1491 | servingAt, | |
| 1492 | createdAt, | |
| 1493 | deployStartedAt, | |
| 1494 | }, | |
| 1495 | }); | |
| 1496 | ||
| 1497 | const head = await (await get("/alice/vault/app/state", owner)).text(); | |
| 1498 | expect(head).toContain("live 6.0s after the push · 5.0s queued"); | |
| 1499 | expect(head).not.toContain("1.0s after the push"); | |
| 1500 | ||
| 1501 | // The same deployment with no wait for a permit says only the one | |
| 1502 | // number, exactly as it always has. | |
| 1503 | putEnv("production", { | |
| 1504 | live: { | |
| 1505 | commitOid: "cafebabe", | |
| 1506 | handle: { port: 4322 }, | |
| 1507 | runId: deployRun.id, | |
| 1508 | since: servingAt, | |
| 1509 | servingAt, | |
| 1510 | createdAt: deployStartedAt, | |
| 1511 | deployStartedAt, | |
| 1512 | }, | |
| 1513 | }); | |
| 1514 | const prompt = await (await get("/alice/vault/app/state", owner)).text(); | |
| 1515 | expect(prompt).toContain("live 1.0s after the push"); | |
| 1516 | expect(prompt).not.toContain("queued"); | |
| 1517 | ||
| 1518 | // A deploy no push asked for — a redeploy someone pressed — carries no | |
| 1519 | // push instant, and its words never claim one. | |
| 1520 | putEnv("production", { | |
| 1521 | live: { | |
| 1522 | commitOid: "cafebabe", | |
| 1523 | handle: { port: 4322 }, | |
| 1524 | runId: deployRun.id, | |
| 1525 | since: servingAt, | |
| 1526 | servingAt, | |
| 1527 | deployStartedAt, | |
| 1528 | }, | |
| 1529 | }); | |
| 1530 | const pressed = await (await get("/alice/vault/app/state", owner)).text(); | |
| 1531 | expect(pressed).toContain("live 1.0s after the deploy started"); | |
| 1532 | expect(pressed).not.toContain("after the push"); | |
| 1533 | }); | |
| 1534 | ||
| 1471 | 1535 | test("app.serving reaches the repo's stream with the shape the live client keys on, the instant the swap-in happens — before its run has finished", async () => { |
| 1472 | 1536 | const deployRun = createRun(app.db, { |
| 1473 | 1537 | repoId: repo.id, |
| @@ -1992,3 +2056,83 @@ describe("working: a run's own page in the studio", () => { | ||
| 1992 | 2056 | expect(page).not.toContain(">Cancel run<"); |
| 1993 | 2057 | }); |
| 1994 | 2058 | }); |
| 2059 | ||
| 2060 | /** | |
| 2061 | * The one function every page words a deployment's speed with. The pages | |
| 2062 | * above prove it reaches the studio; these prove what it says at the edges, | |
| 2063 | * where a real deploy is awkward to arrange. | |
| 2064 | */ | |
| 2065 | describe("servedPhrase", () => { | |
| 2066 | const env = (extra: Partial<EnvStatus>): EnvStatus => ({ | |
| 2067 | env: "production", | |
| 2068 | state: "running", | |
| 2069 | commitOid: "cafebabe", | |
| 2070 | url: "http://vault.apps.test", | |
| 2071 | ...extra, | |
| 2072 | }); | |
| 2073 | ||
| 2074 | test("says nothing at all until the deployment serves", () => { | |
| 2075 | expect( | |
| 2076 | servedPhrase( | |
| 2077 | env({ | |
| 2078 | createdAt: "2026-01-01T00:00:00.000Z", | |
| 2079 | deployStartedAt: "2026-01-01T00:00:02.000Z", | |
| 2080 | }), | |
| 2081 | ), | |
| 2082 | ).toBeUndefined(); | |
| 2083 | }); | |
| 2084 | ||
| 2085 | test("clocks that disagree clamp to zero rather than printing a negative", () => { | |
| 2086 | expect( | |
| 2087 | servedPhrase( | |
| 2088 | env({ | |
| 2089 | createdAt: "2026-01-01T00:00:00.300Z", | |
| 2090 | deployStartedAt: "2026-01-01T00:00:00.300Z", | |
| 2091 | servingAt: "2026-01-01T00:00:00.000Z", | |
| 2092 | }), | |
| 2093 | ), | |
| 2094 | ).toBe("0.0s after the push"); | |
| 2095 | // A start before the push it answers is skew too: no negative wait. | |
| 2096 | expect( | |
| 2097 | servedPhrase( | |
| 2098 | env({ | |
| 2099 | createdAt: "2026-01-01T00:00:05.000Z", | |
| 2100 | deployStartedAt: "2026-01-01T00:00:00.000Z", | |
| 2101 | servingAt: "2026-01-01T00:00:06.000Z", | |
| 2102 | }), | |
| 2103 | ), | |
| 2104 | ).toBe("1.0s after the push"); | |
| 2105 | }); | |
| 2106 | ||
| 2107 | test("a wait under a second is noise: the phrase reads as it always has", () => { | |
| 2108 | expect( | |
| 2109 | servedPhrase( | |
| 2110 | env({ | |
| 2111 | createdAt: "2026-01-01T00:00:00.000Z", | |
| 2112 | deployStartedAt: "2026-01-01T00:00:00.900Z", | |
| 2113 | servingAt: "2026-01-01T00:00:04.300Z", | |
| 2114 | }), | |
| 2115 | ), | |
| 2116 | ).toBe("4.3s after the push"); | |
| 2117 | }); | |
| 2118 | ||
| 2119 | test("a push with no start recorded is still measured from the push", () => { | |
| 2120 | expect( | |
| 2121 | servedPhrase( | |
| 2122 | env({ | |
| 2123 | createdAt: "2026-01-01T00:00:00.000Z", | |
| 2124 | servingAt: "2026-01-01T00:00:02.500Z", | |
| 2125 | }), | |
| 2126 | ), | |
| 2127 | ).toBe("2.5s after the push"); | |
| 2128 | }); | |
| 2129 | ||
| 2130 | test("a deployment with neither instant, and an unreadable one, say nothing", () => { | |
| 2131 | expect(servedPhrase(env({ servingAt: "2026-01-01T00:00:02.500Z" }))).toBeUndefined(); | |
| 2132 | expect( | |
| 2133 | servedPhrase( | |
| 2134 | env({ createdAt: "not a time", servingAt: "2026-01-01T00:00:02.500Z" }), | |
| 2135 | ), | |
| 2136 | ).toBeUndefined(); | |
| 2137 | }); | |
| 2138 | }); |
new above
offline