diff --git a/daemon/main.ts b/daemon/main.ts index 3de202b2b..e4427b093 100644 --- a/daemon/main.ts +++ b/daemon/main.ts @@ -33,16 +33,21 @@ import { } from "./monitor.ts"; import { downloadCache } from "./cache.ts"; import { createAIHandlers } from "./ai/handlers.ts"; +import { phaseEnd, phaseStart, phaseSummary } from "./phases.ts"; import { createSandboxHandlers, type DeployParams } from "./sandbox.ts"; import { register, type TunnelConnection } from "./tunnel.ts"; import { createWorker, + isWorkerEverReady, resetWorkerState, + waitForFirstReady, worker, type WorkerOptions, } from "./worker.ts"; import { portPool } from "./workers/portpool.ts"; +phaseStart("daemon_boot"); + const parsedArgs = parseArgs(Deno.args, { string: ["build-cmd"], }); @@ -283,6 +288,7 @@ const createDeps = ( throw new Error("Cannot initialize deps: site name not set"); } let start = performance.now(); + phaseStart("git_setup"); try { await ensureGit({ site: siteName, @@ -291,9 +297,11 @@ const createDeps = ( }); readyResolve(); } catch (err) { + phaseEnd("git_setup", "fail"); readyReject(err); throw err; } + phaseEnd("git_setup"); logs.push({ level: "info", message: `${colors.bold("[step 1/4]")}: Git setup took ${ @@ -305,9 +313,11 @@ const createDeps = ( if (SANDBOX_MODE) { start = performance.now(); + phaseStart("cache_download"); await downloadCache(siteName).catch((err) => { console.warn(`[cache] Failed to download build cache: ${err.message}`); }); + phaseEnd("cache_download"); logs.push({ level: "info", message: `${colors.bold("[step 1.5/4]")}: Cache download took ${ @@ -317,7 +327,9 @@ const createDeps = ( } start = performance.now(); + phaseStart("manifest_gen"); await genManifestTS(); + phaseEnd("manifest_gen"); logs.push({ level: "info", message: `${colors.bold("[step 2/4]")}: Manifest generation took ${ @@ -328,7 +340,9 @@ const createDeps = ( }); start = performance.now(); + phaseStart("blocks_metadata"); await genBlocksJSON(); + phaseEnd("blocks_metadata"); logs.push({ level: "info", message: `${colors.bold("[step 3/4]")}: Blocks metadata generation took ${ @@ -550,6 +564,54 @@ app.get("/_healthcheck", (c) => { }, }); }); + +/** + * /_ready waits server-side until the inner worker has actually responded + * to traffic (dispatchWorkerState("ready") fires after meta.ts's first + * successful /deco/meta fetch). Unlike /_healthcheck — which goes 200 the + * moment the daemon's Hono server binds — this is a true readiness signal + * for the user-facing Fresh app. + * + * Returns { ready, version, phases } so the admin can record startup + * timings without parsing logs. Honors ?timeout= (default 30s). + */ +const READY_DEFAULT_TIMEOUT_MS = 30_000; +const READY_MAX_TIMEOUT_MS = 120_000; + +app.get("/_ready", async (c) => { + const requested = Number(c.req.query("timeout")); + const timeoutMs = Number.isFinite(requested) && requested > 0 + ? Math.min(requested, READY_MAX_TIMEOUT_MS) + : READY_DEFAULT_TIMEOUT_MS; + + const headers = { + "Access-Control-Allow-Origin": "*", + "Access-Control-Allow-Methods": "GET", + "Access-Control-Allow-Headers": "Content-Type", + "Cache-Control": "no-store", + "Content-Type": "application/json", + }; + + const respond = (ready: boolean) => + new Response( + JSON.stringify({ + ready, + version: denoJSON.version, + phases: phaseSummary(), + }), + { status: ready ? 200 : 503, headers }, + ); + + if (isWorkerEverReady()) return respond(true); + + const ready = await Promise.race([ + waitForFirstReady().then(() => true as const), + delay(timeoutMs).then(() => false as const), + ]); + + return respond(ready); +}); + // k8s liveness probe app.get("/deco/_liveness", () => new Response("OK", { status: 200 })); @@ -844,6 +906,7 @@ Deno.serve( { port, onListen: async (addr) => { + phaseEnd("daemon_boot"); try { const siteName = !SANDBOX_MODE ? getSiteName() : undefined; const tunnel = siteName ? await registerTunnel(siteName) : null; diff --git a/daemon/phases.ts b/daemon/phases.ts new file mode 100644 index 000000000..cce8c7c28 --- /dev/null +++ b/daemon/phases.ts @@ -0,0 +1,95 @@ +/** + * Tracks daemon startup phases with millisecond timestamps and emits a single + * `[phase] phase= event=start|end ts= [duration_ms=] [...]` + * log line per transition. The same line format is used by the env app + * container's startup script in deco-sites/admin, so a single grep across + * pod logs reconstructs the full timeline. + * + * Phase data is also exposed through the daemon's /_ready endpoint so the + * admin can record per-startup timings without parsing logs. + */ + +interface PhaseRecord { + startMs: number; + endMs?: number; + durationMs?: number; + outcome?: string; +} + +const phases: Record = {}; +const bootStartMs = Date.now(); + +const formatExtra = (extra?: Record): string => { + if (!extra) return ""; + const parts: string[] = []; + for (const [k, v] of Object.entries(extra)) { + if (v === undefined || v === null) continue; + parts.push(`${k}=${v}`); + } + return parts.length > 0 ? " " + parts.join(" ") : ""; +}; + +export const phaseStart = ( + name: string, + extra?: Record, +): void => { + const ts = Date.now(); + phases[name] = { startMs: ts }; + console.log( + `[phase] phase=${name} event=start ts=${ts}${formatExtra(extra)}`, + ); +}; + +export const phaseEnd = ( + name: string, + outcome: "ok" | "fail" | "skipped" = "ok", + extra?: Record, +): void => { + const ts = Date.now(); + const rec = phases[name]; + if (!rec) { + phases[name] = { + startMs: ts, + endMs: ts, + durationMs: 0, + outcome, + }; + console.log( + `[phase] phase=${name} event=end ts=${ts} duration_ms=0 outcome=${outcome}${ + formatExtra(extra) + }`, + ); + return; + } + rec.endMs = ts; + rec.durationMs = ts - rec.startMs; + rec.outcome = outcome; + console.log( + `[phase] phase=${name} event=end ts=${ts} duration_ms=${rec.durationMs} outcome=${outcome}${ + formatExtra(extra) + }`, + ); +}; + +export interface PhaseSummary { + bootStartMs: number; + uptimeMs: number; + phases: Record< + string, + { durationMs?: number; outcome?: string; pending?: boolean } + >; +} + +export const phaseSummary = (): PhaseSummary => { + const out: PhaseSummary["phases"] = {}; + for (const [name, rec] of Object.entries(phases)) { + out[name] = rec.endMs === undefined + ? { pending: true } + : { durationMs: rec.durationMs, outcome: rec.outcome }; + } + return { + bootStartMs, + uptimeMs: Date.now() - bootStartMs, + phases: out, + }; +}; diff --git a/daemon/worker.ts b/daemon/worker.ts index cd2201ce6..c6f8209be 100644 --- a/daemon/worker.ts +++ b/daemon/worker.ts @@ -1,4 +1,5 @@ import { Hono } from "@hono/hono"; +import { phaseEnd } from "./phases.ts"; import { broadcast } from "./sse/channel.ts"; import { DenoRun } from "./workers/denoRun.ts"; @@ -21,9 +22,29 @@ export type WorkerStatus = { state: "updating" | "ready" }; const workerState: WorkerStatus = { state: "updating" }; +const firstReady = Promise.withResolvers(); +// Prevent unhandled rejection if the daemon shuts down before the worker +// ever becomes ready — callers handle the race against their own timeouts. +firstReady.promise.catch(() => {}); +let everReady = false; + +/** + * Resolves the first time the worker is observed serving traffic + * (dispatchWorkerState("ready") fired by meta.ts after a successful + * /deco/meta fetch). Subsequent transitions don't re-resolve. + */ +export const waitForFirstReady = (): Promise => firstReady.promise; + +export const isWorkerEverReady = (): boolean => everReady; + export const dispatchWorkerState = (state: "ready" | "updating") => { workerState.state = state; broadcast({ type: "worker-status", detail: workerState }); + if (state === "ready" && !everReady) { + everReady = true; + phaseEnd("worker_ready"); + firstReady.resolve(); + } }; export const start = (): WorkerStatusEvent => ({