diff --git a/AGENTS.md b/AGENTS.md index ae40731..a9e8ad8 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -16,7 +16,7 @@ before relying on memory. Don't guess commands, flags or file locations: they ar | Dev server | `bun run dev`, then http://127.0.0.1:5173 (`.dev.vars` holds throwaway local values only) | | Before every commit | `bun run check` (format, lint, types, unit tests; the pre-commit hook adds gitleaks) | | Unit tests | `bun run test:unit`, port tools `bun run test:port` | -| Smoke test | `bun run test` (needs the dev server running) | +| Smoke test | `bun run test` (needs the dev server) | | Everything | `bun run test:all` (unit, builds, workerd upload, browser tests, local e2e duel) | | Deploy to staging | `bunx cf deploy --mode test --secrets-file ~/.pixfray/secrets.test.json` | | Deploy to production | `bunx cf deploy --secrets-file ~/.pixfray/secrets.json` | @@ -95,11 +95,11 @@ Each one has happened here. Check for it by name before calling work done. |DEVTOOLS.md: test-site tools (bot fighters, scripted duels, alt account in real chat, OBS) |LIVE_FIX.md: release flow, owner page fix/deploy/rollback, backups |ASSET_LICENSES.md, CHARACTER_RESERVE.md: character and font sources|PROGRESSION_PLAN.md: historical -[Code]|server/: worker.ts routes, auth glue|channel.ts ChannelRoom DO (state, bot commands, alarms, broadcast)|game.ts rules, DEFAULT_CONFIG, validateConfigPatch|eventsub.ts webhooks, slimEvent, sendChat|auth.ts sessions, Helix mod checks|channels.ts registry|botcommands.ts|streamelements.ts|uploads.ts|sprites.ts|developer.ts|security.ts|ratelimit.ts|dedupe.ts|upgrades.ts pets.ts cosmetics.ts +[Code]|server/: worker.ts routes|channel.ts ChannelRoom DO (state, bot commands, alarms)|game.ts rules, DEFAULT_CONFIG, validateConfigPatch|eventsub.ts webhooks, slimEvent, sendChat|auth.ts sessions, Helix mod checks|channels.ts registry|botcommands.ts|streamelements.ts|uploads.ts|sprites.ts|developer.ts|security.ts|ratelimit.ts|dedupe.ts|tracker.ts logs, counters|upgrades.ts pets.ts cosmetics.ts |src/: admin.ts mod page|dashboard.ts channel page|start.ts sign-up|setup.ts|intro/ home page 3D|scrub.ts|sprite-maker.ts spritify.ts autosprite.ts|fighter3d.ts voxthumb.ts |src/served/: overlay.ts|arena-client.ts|chat.ts IRC|public/: overlay.html|dashboard.css tokens |tests/: *.test.ts unit|fakes.ts doubles|port/ port tools|smoke.ts|ui.ts arena-browser.ts|e2e-local.ts|chrome.ts -|scripts/: port-check.ts port-rename.ts lib/port.ts|devtools.ts|release.ts|live-chat-e2e.ts|test-all.ts|configure-twitch.ps1 +|scripts/: port-check.ts port-rename.ts lib/port.ts|devtools.ts|logs.ts|release.ts|live-chat-e2e.ts|test-all.ts|configure-twitch.ps1 ``` ## Changing this file diff --git a/admin/dev/index.html b/admin/dev/index.html index 692a0c8..4dc40e3 100644 --- a/admin/dev/index.html +++ b/admin/dev/index.html @@ -111,14 +111,24 @@

Error log, newest first

- +
TimeSourceMessageContext
-

The newest 100 of up to 200 stored rows per channel.

+

The newest 100 rows. Each channel keeps the last 500 rows per source (200 for alarms, duels and chat delivery, which also stop storing after 300 a day). Every line also goes to Workers Logs in the Cloudflare dashboard for 3 days.

+ + +
+

Room counters by day

+

For the channel picked in the log above, newest UTC day first. A jump in alarms or requests points to a loop; bot_failed or bot_held point to chat delivery.

+
+ + +
Counter
+

Counts reach storage at least every 30 seconds while the room is busy, so the last few seconds before it goes idle can be missing. Days older than 14 are dropped.

diff --git a/docs/CONTRACTS.md b/docs/CONTRACTS.md index d9dfbfa..4460c40 100644 --- a/docs/CONTRACTS.md +++ b/docs/CONTRACTS.md @@ -108,7 +108,8 @@ everything else is revalidated. | GET, POST | `/api/dev/restore` | owner | POST `{channel, at:ms}` or `{channel, undo:true}` | Point-in-time restore of one channel's room (Cloudflare keeps 30 days of every SQLite Durable Object). `at` must be between 30 days and 1 minute ago. The Worker calls the room's internal `POST /dev/restore` (arms the restore point, returns the undo point and the revision), `POST /dev/restart` (`ctx.abort()`, so the next session loads it) and `POST /dev/restored` (revision = max(old, restored) + 1, broadcast, looks reset), then keeps `{at, restoredAt, by, undo}` in AuthStore `restore:` for 30 days. `undo:true` restores to that undo point and drops the record. Answers `{ok, channel, at, undone, undoSaved, players, profiles}`. GET `?channel=` answers `{channel, last:{at, restoredAt, by}\|null, windowDays:30}`. Only that room goes back; the channel registry, sessions and other channels don't. | 400 `invalid_restore_time`/`channel_required`, 400 `invalid_body` (`channel` not text, `undo` not a boolean), 404 `unknown_channel`, 409 `nothing_to_undo`, 501 `restore_unavailable` (local dev), 502 `room_unavailable`/`restart_pending` | | GET, POST | `/api/dev/backups?channel=[&day=YYYY-MM-DD[&user=]]` | owner | POST `{channel?}` | Daily backups (`server/backups.ts`). A cron trigger at 09:00 UTC calls each channel's room (built-in and signed up, paused too) at its internal `POST /dev/backup {at, status}`; the room gzips its `/dev/export` JSON, with the export head, into the `BACKUPS` D1 database: `backups(channel, day, at, bytes, data BLOB)`, one row per channel per UTC day, a second run that day replaces it. Rows older than 90 days are dropped after each run. A room that fails is logged as a Worker error and the rest still run. GET `?channel=` answers `{channel, keepDays:90, backups:[{day, at, bytes}]}` newest first; `&day=` downloads that day's export as `mini-chat---backup.json` (same shape as `/api/dev/export`); `&user=` answers `{channel, day, exportedAt, profile, purchases[], builds[]}` for one fighter. POST backs up one channel (or all) now: `{day, channels:[{channel, ok, bytes\|reason}]}`. | 503 `upstream_error` (`&day=` or `&user=` on a stored backup that is not gzip of an export with `exportedAt` text and `profiles`/`purchases`/`builds` rows with a `userId`), 400 `channel_required`/`invalid_day`, 400 `invalid_body` (POST `channel` not text), 404 `no_backup`/`fighter_not_in_backup`/`unknown_channel`, 501 `backups_unavailable` (no D1 bound, local dev), 401, 403 | | GET | `/api/dev/ranks?channel=&user=[&limit=1..500]` | owner | none | The fighter's rank history, newest first (default 100 rows): `[{at, userId, username, elo, wins, losses}]`. The room keeps a `rank_log` row each time a stored profile's elo, wins or losses changes (SQLite triggers on `profiles`, `server/ranklog.ts`), so duels, resets, restores and saves all land there. Rows are kept 365 days; a room's first rows are its fighters' ranks when the table was created. | 400 `invalid_user`, 401, 403 | -| GET, DELETE | `/api/dev/logs[?source=room\|worker&limit=1..100]` | owner | none | GET: log rows `[{id,at,source,message,context}]`, newest first, last 500 kept. Holds error rows (`room`, `worker`), `command` rows (chat commands, purchases, gifts, profile saves) and `warn` rows (refused profile saves with the reason, from the room or, for `invalid_fields`, `unknown_character` and `sprite_not_owned`, from the Worker; bot replies held back). DELETE clears them. | 401, 403 | +| GET, DELETE | `/api/dev/logs[?channel=&source=room\|worker\|command\|warn\|alarm\|duel\|chat&limit=1..100]` | owner | none | GET: log rows `[{id,at,source,message,context}]`, newest first. Each source keeps its own tail: 200 rows for `alarm`, `duel` and `chat`, 500 for the rest, and the busy three stop storing after 300 rows a UTC day (still counted). Holds error rows (`room`, `worker`), `command` rows (chat commands, purchases, gifts, profile saves), `warn` rows (refused profile saves with the reason, bot replies held back, alarm bursts, a day past 25,000 or 50,000 requests and alarms), `alarm` rows (each alarm set, cleared and run, with the reasons due), `duel` rows (challenge, duel, rank and pair events) and `chat` rows (EventSub non-notification messages, chat connect events, bot replies sent). Every trace is also one JSON console line `{log, message, ...context}` in Workers Logs (3 days), including lines never stored here: each chat line heard (first word and length only), held bot replies and other room events (`log` `event`); `node scripts/logs.ts` reads them. DELETE clears the rows. | 401, 403 | +| GET | `/api/dev/stats?channel=[&days=1..14]` | owner | none | `{channel, days:[{day:"YYYY-MM-DD", counts:{name:n}}]}`, newest UTC day first, 14 days kept. Counters include `requests`, `ws_messages`, `alarms`, `alarms_idle`, `rows_written` (SQLite rows the tracker wrote), `bot_sent`, `bot_failed`, `bot_held[_]`, `eventsub_`, `event_` and `log_`. The room adds in memory and saves after every alarm (only every 10 s during an alarm burst of 20 or more alarms under a second apart), on each read, after a request once 10 s have passed since the last save, and at least every 30 s while busy, so a room that hibernates loses at most the last 10 s of request counts. | 401, 403 | | GET, POST | `/api/dev/settings` | owner | POST `{action:"config"\|"rollbackConfig", payload}` or `{action:"connectChat"\|"disconnectChat", takeover?:true}` | The same versioned config as `/api/admin` (history rows carry the owner's actorName); chat actions answer like the admin ones | 400 (`invalid_body` when `takeover` is not a boolean), 403 `reconnect`, 409, 502 | | GET, POST | `/api/dev/channels` | owner | POST `{action:"pause"\|"resume", login}` | `{builtin:[login], max, channels:[{login,enabledAt,pausedAt,pausedBy,review?}], progressBatch:40}`. GET no longer returns setup progress; the owner page reads it from `/api/dev/progress` in batches of `progressBatch` after the list renders | 400 `builtin`/`unknown_action`, 400 `invalid_body` (`login` not text), 404 `not_found`, 403 `full` (resuming past 200 channels on), 503 `upstream_error` (AuthStore unreachable or its list not an array; a single registry record of the wrong shape is left out of every list and logged as `registry records skipped `) | | GET | `/api/dev/progress?logins=a,b,c` | owner | `logins`: comma-separated, lowercased and de-duplicated, at most 40 (one room read each, within the Free plan's 50 subrequests per request). Each must be a built-in or a turned-on channel (a paused one is `unknown_channel`). POST gets 405. | `{progress:{login:{overlays,source,commandsWorking,commands,duelCommands,duelModuleOff,lastCommandAt,rejectedAt,lastChatAt,players}}}`. `source` is `""` while chat isn't connected. A login whose room read fails is left out. Read only: it never creates a StreamElements key. | 400 `logins_required`, 400 `too_many_logins` `{max:40}`, 400 `unknown_channel` `{invalid:[...]}`, 401, 403 | @@ -562,7 +563,7 @@ export async function mountUpload(root, {channel, usage, limits, items, refresh} // server/developer.ts (Lane E) export async function handleDeveloper(request, env, c) // c = {user, owner, url, path, bodyJson, roomFetch(channel, path, init?), chatAction(channel, action), waitUntil(promise)} -export async function handleRoomDeveloper(room, request, {path, channel}) // DO: /dev/diagnostics, /dev/logs, POST /dev/log +export async function handleRoomDeveloper(room, request, {path, channel}) // DO: /dev/diagnostics, /dev/logs, /dev/stats, POST /dev/log export function ensureDeveloperSchema(sql) export function logRoomError(room, error, context) // never throws export async function logWorkerError(env, error, context) // never throws diff --git a/docs/LIVE_FIX.md b/docs/LIVE_FIX.md index d32d98c..11157cd 100644 --- a/docs/LIVE_FIX.md +++ b/docs/LIVE_FIX.md @@ -46,6 +46,20 @@ Merge that PR afterwards, or the next promote from `main` will undo the hotfix. Recent runs and the versions now serving are listed on the page. Every run name ends with a request id (`r` + 10 hex digits), so a click can be matched to its run. +## Logs and counters + +The owner page's **Room log** filters by source (errors, commands, warnings, alarms, duels, chat delivery), and +**Room counters by day** shows each channel's daily counts, up to 10 seconds behind. Every log line also goes to +Workers Logs for 3 days, with more detail than the room keeps. Read them from a terminal: + +``` +node scripts/logs.ts --mode test --channel nesszers --source alarm --hours 6 +node scripts/logs.ts --channel miolafff --source duel --limit 300 +``` + +Without `--mode test` it reads production. It needs `bunx cf` signed in, and prints only the log fields. +The routes and every counter name are in [CONTRACTS.md](CONTRACTS.md) §2. + ## Backups Cloudflare keeps 30 days of every change to each channel's storage (point-in-time recovery on SQLite diff --git a/scripts/logs.ts b/scripts/logs.ts new file mode 100644 index 0000000..d3adc51 --- /dev/null +++ b/scripts/logs.ts @@ -0,0 +1,82 @@ +#!/usr/bin/env node +// Reads the room and Worker debug lines from Workers Logs (server/tracker.ts prints each as JSON). See docs/LIVE_FIX.md. +// Usage: node scripts/logs.ts [--mode test] [--channel nesszers] [--source alarm] [--hours 6] [--limit 100] +// Needs `bunx cf` signed in to the account. Prints only the log fields, never account or request metadata. +import { execFileSync } from "node:child_process"; +import siteConfig from "../site.config.js"; + +/** One Workers Logs event, as far as this script reads it. JSON console lines arrive parsed under `source`. */ +type LogEvent = { timestamp?: number; source?: { [field: string]: unknown }; $workers?: { scriptName?: string } }; +type Filter = { key: string; operation: string; type: string; value?: string }; + +const argv = process.argv.slice(2); +const flags: Record = {}; +for (let i = 0; i < argv.length; i++) { + const m = /^--([a-z]+)(?:=(.*))?$/.exec(argv[i]!); // !: i < argv.length + // !: group 1 always matches; a flag without "=" takes the next argument + if (m) flags[m[1]!] = m[2] ?? argv[++i] ?? ""; +} +if ("help" in flags || argv[0] === "help") { + console.log("node scripts/logs.ts [--mode test] [--channel ] [--source ] [--hours 6] [--limit 100]"); + console.log("sources: room worker command warn alarm duel chat event (event and 'heard' lines are only here)"); + process.exit(0); +} +const script = flags.mode === "test" ? siteConfig.workers.test : siteConfig.workers.production; +const hours = Math.min(72, Math.max(0.1, Number(flags.hours) || 6)); // Workers Logs keeps 3 days +const limit = Math.min(2000, Math.max(1, Number(flags.limit) || 100)); + +const filters: Filter[] = [ + { key: "$workers.scriptName", operation: "eq", type: "string", value: script }, + // the bare field name matches the parsed JSON field (checked on staging: "source.log" matches nothing) + flags.source + ? { key: "log", operation: "eq", type: "string", value: flags.source } + : { key: "log", operation: "exists", type: "string" }, +]; +if (flags.channel) filters.push({ key: "channel", operation: "eq", type: "string", value: flags.channel }); + +const to = Date.now(), + from = to - hours * 3_600_000, + events: LogEvent[] = []; +let offset: string | undefined; +while (events.length < limit) { + const body = { + queryId: "pixfray-logs", + timeframe: { from, to }, + view: "events", + dry: true, + parameters: { datasets: ["cloudflare-workers"], filters, limit: Math.min(200, limit - events.length) }, + ...(offset ? { offset } : {}), + }; + let out: string; + try { + out = execFileSync("bunx", ["cf", "observability", "telemetry", "query", "--body", JSON.stringify(body)], { + encoding: "utf8", + maxBuffer: 100_000_000, + stdio: ["ignore", "pipe", "pipe"], + }); + } catch (e) { + // the CLI's own message names what to fix (signed out, wrong account); the body never holds a secret + console.error("cf observability query failed:", String((e as { stderr?: unknown }).stderr || e).slice(0, 400)); // as: execFileSync errors carry stderr + process.exit(1); + } + // as: the query answer; only events.events is read, and each field below is checked where it is printed + const page = ( + JSON.parse(out.slice(out.indexOf("{"))) as { events?: { events?: (LogEvent & { $metadata?: { id?: string } })[] } } + ).events?.events; + if (!page?.length) break; + events.push(...page); + if (page.length < 200) break; + offset = page.at(-1)?.$metadata?.id; + if (!offset) break; +} + +events.sort((a, b) => (a.timestamp || 0) - (b.timestamp || 0)); +for (const e of events) { + const { log, message, ...rest } = e.source || {}; + const at = new Date(e.timestamp || 0).toISOString().replace("T", " ").slice(0, 19); + const extra = Object.keys(rest).length ? " " + JSON.stringify(rest) : ""; + console.log(`${at} ${String(log).padEnd(7)} ${String(message ?? "")}${extra}`); +} +console.error( + `${events.length} lines from ${script}, last ${hours} h${flags.channel ? ", channel " + flags.channel : ""}`, +); diff --git a/server/channel.ts b/server/channel.ts index a3e4234..d1a387e 100644 --- a/server/channel.ts +++ b/server/channel.ts @@ -16,6 +16,7 @@ import { import { handleRoomAssets, ensureUploadSchema, customUsage } from "./uploads.ts"; import { ensureRankLogSchema, rankBefore } from "./ranklog.ts"; import { handleRoomDeveloper, ensureDeveloperSchema, logRoomError, logRoomEvent } from "./developer.ts"; +import { count, ensureTrackerSchema, noteAlarm, settleCounts, trace } from "./tracker.ts"; import { checkChatSubscription, liveStream, sendChatMessage, botDropText } from "./eventsub.ts"; import { accountCreatedAt } from "./accounts.ts"; import { EVENTSUB_DEDUPE_MS, claimMessage, releaseMessage } from "./dedupe.ts"; @@ -534,6 +535,8 @@ export class ChannelRoom extends DurableObject { /** Duel ids whose expired-challenge line went out. */ declare expiredSaid: Set | undefined; declare postingResults: Promise | null | undefined; + /** The alarm this instance last set (null: none), undefined until it sets or clears one. */ + declare alarmAt: number | null | undefined; constructor(ctx: DurableObjectState<{}>, env: Env) { super(ctx, env); @@ -646,6 +649,7 @@ export class ChannelRoom extends DurableObject { sql.exec("ALTER TABLE config_history ADD COLUMN actor_name TEXT NOT NULL DEFAULT ''"); ensureUploadSchema(sql); ensureDeveloperSchema(sql); + ensureTrackerSchema(sql); sql.exec( "CREATE TABLE IF NOT EXISTS se_settings (id INTEGER PRIMARY KEY CHECK (id = 1), secret TEXT NOT NULL, names TEXT NOT NULL)", ); @@ -678,11 +682,14 @@ export class ChannelRoom extends DurableObject { async fetch(request: Request): Promise { if (!this.authorized(request)) return json({ error: "internal authorization required" }, 403); + count(this, "requests"); try { return await this.route(request); } catch (error) { logRoomError(this, error, { path: new URL(request.url).pathname, method: request.method }); return json({ error: "room error" }, 500); + } finally { + settleCounts(this); } } @@ -1257,8 +1264,10 @@ export class ChannelRoom extends DurableObject { } advance(channel: string, event: RoomEvent, now: number): ReduceOutput { - return this.ctx.storage.transactionSync(() => { + let since = 0; + const out = this.ctx.storage.transactionSync(() => { const state = this.readState(channel); + since = state.revision; if (event.type === "admin" && event.action === "config") this.seedConfigHistory(state); const result = reduceGame(state, event, now); for (const userId of result.dirtyProfileIds) { @@ -1310,6 +1319,23 @@ export class ChannelRoom extends DurableObject { } return result; }); + // after the commit, so a rolled-back reduce logs nothing it didn't do (its error is logged by fetch or alarm) + this.traceEvents(channel, out.state, since); + return out; + } + + // Each new game event: counted, printed to Workers Logs, and duel and chat events kept in the room log (server/tracker.ts). + traceEvents(channel: string, state: GameState, since: number): void { + for (const e of state.events) { + if (Number(e.id) <= since) continue; + count(this, "event_" + e.type); + const source = /^(challenge|duel|rank|pair)_/.test(e.type) + ? "duel" + : e.type.startsWith("chat_") + ? "chat" + : "event"; + trace(this, source, e.type, { channel, ...e }, source !== "event"); + } } // Config history keeps every version so mods can review and roll back (see docs/CONTRACTS.md). @@ -1366,8 +1392,10 @@ export class ChannelRoom extends DurableObject { } const now = Date.now(); - return this.ctx.storage.transactionSync((): SaveResult => { + let since = 0; + const out = this.ctx.storage.transactionSync((): SaveResult => { const state = this.readState(channel); + since = state.revision; const existing = this.getProfile(userId, state.config); // Upgrades and hat: optional in the request (left out = keep the saved ones), checked against the wins the stream // has shown, so a save can't reveal a duel result the overlay hasn't played yet. @@ -1469,6 +1497,8 @@ export class ChannelRoom extends DurableObject { }; return { ok: true, profile: saved, state: result.state }; }); + if (out.ok) this.traceEvents(channel, out.state, since); + return out; } // An approved viewer sprite goes on its uploader's saved fighter, and replaces their previous sprite in every build @@ -1780,6 +1810,7 @@ export class ChannelRoom extends DurableObject { async webSocketMessage(ws: WebSocket): Promise { // Overlay sockets are read-only snapshots. "ping" never reaches here: the auto-response in the constructor answers it. + count(this, "ws_messages"); try { ws.close(1008, "Read-only socket"); } catch {} @@ -1814,6 +1845,30 @@ export class ChannelRoom extends DurableObject { async handleEventsub(channel: string, msg: BotMessage, origin: string, kind: string, now: number): Promise { const subscriptionId = String(msg.subscription?.id || ""); + count(this, msg.bot === true ? "eventsub_bot" : "eventsub_" + (kind || "unknown")); + if (kind !== "notification") + trace(this, "chat", "eventsub " + (kind || "unknown"), { + channel, + subscriptionId: subscriptionId.slice(0, 64), + status: String(msg.subscription?.status || ""), + }); + else { + // every chat line, to Workers Logs only: the first word (a command name) and who, never the whole line + const text = String(msg.event?.message?.text || ""); + trace( + this, + "chat", + "heard", + { + channel, + via: msg.bot === true ? "bot" : origin || "eventsub", + user: normalizeUsername(msg.event?.chatter_user_login) || "?", + first: text.trim().startsWith("!") ? text.trim().split(/\s+/)[0]!.slice(0, 32) : "", // split always has one item + length: text.length, + }, + false, + ); + } let result: ChatOutcome; if (kind === "webhook_callback_verification") result = this.advance(channel, { type: "chat_verified", subscriptionId }, now); @@ -3008,6 +3063,9 @@ export class ChannelRoom extends DurableObject { const now = Date.now(), last = (this.heldLogged ||= {}); this.ctx.storage.sql.exec("UPDATE bot_status SET held_at = ?, held_reason = ? WHERE id = 1", now, reason); + count(this, "bot_held"); + count(this, "bot_held_" + reason); + trace(this, "chat", "bot held: " + reason, { channel, reason, ...context }, false); if (!log || now - (last[reason] || 0) < 60_000) return; last[reason] = now; logRoomEvent(this, "warn", "bot reply held back: " + reason, { channel, via: "bot", reason, ...context }); @@ -3022,8 +3080,11 @@ export class ChannelRoom extends DurableObject { for (const r of ([] as (Partial | null | undefined)[]).concat(results || [])) { if (r?.sent === true) { sql.exec("UPDATE bot_status SET sent_at = ?, sent_total = sent_total + 1 WHERE id = 1", now); + count(this, "bot_sent"); + trace(this, "chat", "bot " + via + " sent", { channel, via }); continue; } + count(this, "bot_failed"); const reason = String(r?.reason || "unknown").slice(0, 200); sql.exec( "UPDATE bot_status SET failed_at = ?, failed_total = failed_total + 1, failed_reason = ? WHERE id = 1", @@ -3294,8 +3355,10 @@ export class ChannelRoom extends DurableObject { const textValue = String(ev.message?.text || "").slice(0, 512); const color = /^#[0-9a-f]{6}$/i.test(ev.color || "") ? ev.color!.toUpperCase() : ""; // test() passed, so it is set const subscriptionId = String(msg.subscription?.id || ""); - return this.ctx.storage.transactionSync((): ChatOutcome => { + let since = 0; + const outcome = this.ctx.storage.transactionSync((): ChatOutcome => { let state = this.readState(channel); + since = state.revision; const none = (reason: string): ChatOutcome => ({ state, result: { ok: false, reason }, @@ -3396,6 +3459,8 @@ export class ChannelRoom extends DurableObject { visible: steps.some((r) => r.visible), }; }); + if (outcome.changed) this.traceEvents(channel, outcome.state, since); + return outcome; } async webSocketError(ws: WebSocket): Promise { @@ -3414,27 +3479,49 @@ export class ChannelRoom extends DurableObject { } } - async scheduleAlarm(state: GameState): Promise { - const due: number[] = []; + // Every time the room has work to do, with why. scheduleAlarm sets the earliest; alarm() names the ones it ran for. + alarmDue(state: GameState, now: number): { at: number; why: string }[] { + const due: { at: number; why: string }[] = []; const chatDue = chatCheckDue(state); - if (chatDue !== null) due.push(chatDue); + if (chatDue !== null) due.push({ at: chatDue, why: "chat_check" }); for (const duel of state.duels) { - if (duel.status === "pending") due.push(duel.expiresAt + 1); + if (duel.status === "pending") due.push({ at: duel.expiresAt + 1, why: "challenge_expiry" }); else if (duel.status === "active") - due.push(duel.lastActionAt! + (duel.rules?.inactivityMs || state.config.inactivityMs) + 1); // set when a duel starts + due.push({ + at: duel.lastActionAt! + (duel.rules?.inactivityMs || state.config.inactivityMs) + 1, // set when a duel starts + why: "duel_inactivity", + }); } - for (const profile of state.players) if (profile.respawnAt > 0) due.push(profile.respawnAt); - for (const lock of state.rematchLocks) due.push(lock.until); + for (const profile of state.players) if (profile.respawnAt > 0) due.push({ at: profile.respawnAt, why: "respawn" }); + for (const lock of state.rematchLocks) due.push({ at: lock.until, why: "rematch_lock" }); // a bot channel announces each duel's result once the stream has played it if (this.botSource(state) && state.config.botEnabled !== false) for (const duel of state.duels) // revealAt! : set when a duel completes - if (duel.status === "completed" && duel.revealAt! > Date.now()) due.push(duel.revealAt! + 1); - if (this.dueResults(state, Date.now()).length) due.push(Date.now() + RESULT_RETRY_MS); // one that couldn't go out yet + if (duel.status === "completed" && duel.revealAt! > now) + due.push({ at: duel.revealAt! + 1, why: "result_reveal" }); + if (this.dueResults(state, now).length) due.push({ at: now + RESULT_RETRY_MS, why: "result_retry" }); // one that couldn't go out yet const reminder = this.reminderDue(state); - if (reminder) due.push(reminder); - if (due.length) await this.ctx.storage.setAlarm(Math.max(Date.now() + 1, Math.min(...due))); - else await this.ctx.storage.deleteAlarm(); + if (reminder) due.push({ at: reminder, why: "reminder" }); + return due; + } + + async scheduleAlarm(state: GameState): Promise { + const now = Date.now(), + due = this.alarmDue(state, now); + if (!due.length) { + if (this.alarmAt !== null) trace(this, "alarm", "cleared", { channel: state.channel }); + this.alarmAt = null; + await this.ctx.storage.deleteAlarm(); + return; + } + const next = due.reduce((a, b) => (b.at < a.at ? b : a)), + at = Math.max(now + 1, next.at); + // traced only when the target moves; the same alarm set again by every command would flood the log + if (at !== this.alarmAt) + trace(this, "alarm", "set " + next.why, { channel: state.channel, inMs: at - now, due: due.length }); + this.alarmAt = at; + await this.ctx.storage.setAlarm(at); } // Errors are logged (owner diagnostics) and the next alarm is always set, so one failure can't stall result lines. @@ -3443,12 +3530,23 @@ export class ChannelRoom extends DurableObject { if (!row) return; const channel = normalizeChannel(row.channel); if (!channel) return; + // why it ran, from the state itself: a woken room has none of the reasons scheduleAlarm saw + const now = Date.now(), + ran = this.alarmDue(this.readState(channel), now).filter((d) => d.at <= now); + this.alarmAt = undefined; + noteAlarm( + this, + [...new Set(ran.map((d) => d.why))], + ran.length ? now - Math.min(...ran.map((d) => d.at)) : null, + channel, + ); try { await this.alarmTasks(channel); } catch (error) { logRoomError(this, error, { path: "alarm", method: "ALARM" }); } await this.scheduleAlarm(this.readState(channel)); + settleCounts(this, true); } async alarmTasks(channel: string): Promise { diff --git a/server/developer.ts b/server/developer.ts index 15786e1..0583ca0 100644 --- a/server/developer.ts +++ b/server/developer.ts @@ -4,6 +4,7 @@ import { CHANNELS, record } from "./auth.ts"; import { channelState, overview, listRecords, setPaused, LOGIN } from "./channels.ts"; import { SE_ACTIONS, DEFAULT_SE_NAMES } from "./streamelements.ts"; import { rankHistory } from "./ranklog.ts"; +import { LOG_SOURCES, readCounts, trace } from "./tracker.ts"; import { ignoreAnswer, isObject, @@ -99,7 +100,6 @@ export type DevRoom = { looksReset: boolean; flushLooksSoon(): void; }; -const MAX_LOG_ROWS = 500; const VERSION = "0.2.0"; const DAILY_REQUEST_LIMIT = 100000; const SCRIPTS = site.workers; @@ -188,6 +188,7 @@ const ROUTES: { [op: string]: { [method: string]: Handler } } = { DELETE: ({ room }) => room("/dev/logs", { method: "DELETE" }), }, backups: { GET: backupsRead, POST: backupsRun }, + stats: { GET: ({ room, query }) => room("/dev/stats?" + new URLSearchParams({ days: query.get("days") || "" })) }, ranks: { GET: ({ room, query }) => room("/dev/ranks?" + new URLSearchParams({ user: query.get("user") || "", limit: query.get("limit") || "" })), @@ -471,7 +472,7 @@ function logQuery(query: URLSearchParams): string { const out = new URLSearchParams(), source = query.get("source"), limit = Number(query.get("limit")); - if (source === "room" || source === "worker") out.set("source", source); + if (source && LOG_SOURCES.includes(source)) out.set("source", source); if (Number.isInteger(limit) && limit >= 1 && limit <= 100) out.set("limit", String(limit)); return out.toString(); } @@ -1072,7 +1073,7 @@ export async function handleRoomDeveloper( source = q.searchParams.get("source"), limit = Math.min(100, Math.max(1, Number(q.searchParams.get("limit")) || 100)); // includes() is false for a missing source (null) - const rows = ["room", "worker", "command", "warn"].includes(source as string) + const rows = LOG_SOURCES.includes(source as string) ? sql .exec( "SELECT id, at, source, message, context FROM error_log WHERE source = ? ORDER BY id DESC LIMIT ?", @@ -1098,14 +1099,29 @@ export async function handleRoomDeveloper( return json({ ok: true }); } if (path === "/dev/log" && method === "POST") { - // Any JSON: insertLog stringifies and clips every field + // Any JSON: trace stringifies and clips every field const body = await request .json<{ source?: unknown; message?: unknown; context?: unknown } | null>() .catch((): { source?: unknown; message?: unknown; context?: unknown } => ({})); // The Worker logs errors here, and as "warn" the profile saves it refuses before they reach the room. - insertLog(sql, body?.source === "warn" ? "warn" : "worker", body?.message, body?.context); + const context = body?.context; + trace( + room, + body?.source === "warn" ? "warn" : "worker", + String(body?.message || "unknown"), + // a JSON object from the Worker's own logWorkerError; anything else is kept as one value + context && typeof context === "object" && !Array.isArray(context) + ? (context as JsonObject) + : { value: context ?? null }, + ); return json({ ok: true }); } + // Per-day counters, newest first: ?days=1..14 (default 7). Flushes today's first, so the numbers are current. + if (path === "/dev/stats" && method === "GET") { + const q = url || new URL(request.url), + days = Math.min(14, Math.max(1, Number(q.searchParams.get("days")) || 7)); + return json({ channel, days: readCounts(room, days) }); + } // Setup progress for the owner's Channels table: read only, so it never creates a StreamElements key. if (path === "/dev/progress" && method === "GET") { const state = room.readState(channel), @@ -1202,33 +1218,32 @@ export function ensureDeveloperSchema(sql: SqlStorage): void { export function logRoomError(room: { ctx: DurableObjectState }, error: unknown, context: JsonObject = {}): void { try { // anything can be thrown; an Error's message reads best - insertLog( - room.ctx.storage.sql, - "room", - (error as { message?: unknown } | null | undefined)?.message || String(error), - context, - ); + const thrown = error as { message?: unknown; stack?: unknown } | null | undefined; + trace(room, "room", String(thrown?.message || error), { + ...context, + stack: String(thrown?.stack || "").slice(0, 600), + }); } catch {} } // One line per chat command (source 'command') or a broken invariant (source 'warn'), so a wrong reply -// can be traced without a crash. Also printed for `wrangler tail`. Must never throw. +// can be traced without a crash. Also printed to Workers Logs (server/tracker.ts). Must never throw. export function logRoomEvent( room: { ctx: DurableObjectState }, source: string, message: string, context: JsonObject = {}, ): void { - try { - console.log(JSON.stringify({ log: source, message, ...context })); - } catch {} - try { - insertLog(room.ctx.storage.sql, source, message, context); - } catch {} + trace(room, source, message, context); } // Called by the Worker's top-level catch (through ctx.waitUntil). Must never throw. export async function logWorkerError(env: Env, error: unknown, context: JsonObject = {}): Promise { + try { + // anything can be thrown; an Error's message reads best + const message = String((error as { message?: unknown } | null | undefined)?.message || error); + console.error(JSON.stringify({ log: "worker", message, ...context })); + } catch {} try { if (!env.INTERNAL_SECRET || !env.ROOMS) return; await env.ROOMS.get(env.ROOMS.idFromName(site.defaultChannel)).fetch("https://room/dev/log", { @@ -1369,19 +1384,6 @@ function roomExport(room: DevRoom, channel: string) { }; } -function insertLog(sql: SqlStorage, source: string, message: unknown, context: unknown): void { - let ctx = JSON.stringify(context ?? {}) || "{}"; - if (ctx.length > 2000) ctx = JSON.stringify({ truncated: ctx.slice(0, 1900) }); - sql.exec( - "INSERT INTO error_log (at, source, message, context) VALUES (?, ?, ?, ?)", - Date.now(), - source, - String(message || "unknown").slice(0, 500), - ctx, - ); - sql.exec("DELETE FROM error_log WHERE id <= (SELECT MAX(id) FROM error_log) - ?", MAX_LOG_ROWS); -} - // T is the shape the caller stored; null when the value is missing or not JSON. function safeParse(value: string | undefined): T | null { try { diff --git a/server/tracker.ts b/server/tracker.ts new file mode 100644 index 0000000..e05bb6d --- /dev/null +++ b/server/tracker.ts @@ -0,0 +1,209 @@ +// Debug traces and per-room daily counters (docs/CONTRACTS.md §2, owner logs and stats). +// Every trace prints one JSON line to Workers Logs (free, 3 days). SQLite rows are the scarce budget (100k writes a +// day for the whole account), so the room keeps only a capped tail of the busy sources and one counter row per day. +import type { JsonObject } from "./parse.ts"; + +type Room = { ctx: DurableObjectState }; + +/** Every source the room log stores; the owner page filters by these. */ +export const LOG_SOURCES = ["room", "worker", "command", "warn", "alarm", "duel", "chat"]; +/** Rows kept per source in error_log. Busy trace sources keep a shorter tail. */ +export const KEEP_ROWS: { [source: string]: number } = { alarm: 200, duel: 200, chat: 200 }; +const KEEP_DEFAULT = 500; +/** Busy sources store at most this many rows a day; the rest go to Workers Logs only. */ +export const DAILY_STORE_CAP = 300; +const TRIM_EVERY = 25; +/** Counters reach SQLite at least this often while a room is busy. */ +export const FLUSH_MS = 30_000; +/** A request, or an alarm in a burst, flushes dirty counters once this long has passed since the last write. */ +export const SETTLE_MS = 10_000; +const KEEP_DAYS = 14; +/** A run of this many alarms each under BURST_GAP_MS apart logs a warning (at most every BURST_ALERT_MS). */ +export const BURST_RUN = 20; +const BURST_GAP_MS = 1000; +const BURST_ALERT_MS = 10 * 60_000; +/** Requests plus alarms in one room and day that log a warning, once each (the Free plan allows 100k a day). */ +export const DAILY_ALERTS = [25_000, 50_000]; + +type Counts = { [name: string]: number }; +type Tracker = { + day: string; + counts: Counts; + dirty: boolean; + flushedAt: number; + sinceTrim: Counts; + lastAlarmAt: number; + alarmRun: number; + burstAlertAt: number; +}; + +const trackers = new WeakMap(); + +export function ensureTrackerSchema(sql: SqlStorage): void { + sql.exec("CREATE TABLE IF NOT EXISTS daily_stats (day TEXT PRIMARY KEY, data TEXT NOT NULL)"); +} + +const utcDay = (at: number) => new Date(at).toISOString().slice(0, 10); + +function tracker(room: Room, now: number): Tracker { + let t = trackers.get(room.ctx); + const day = utcDay(now); + if (t && t.day === day) return t; + if (t) flush(room, t); + const sql = room.ctx.storage.sql; + // a restarted room keeps counting where the last flush left today + const row = sql.exec<{ data: string }>("SELECT data FROM daily_stats WHERE day = ?", day).toArray()[0]; + let counts: Counts = {}; + try { + if (row) counts = JSON.parse(row.data); + } catch {} + if (!t) sql.exec("DELETE FROM daily_stats WHERE day < ?", utcDay(now - KEEP_DAYS * 86_400_000)); + t = { + day, + counts, + dirty: false, + // 0, so the first request or alarm after a wake writes what it counted before the room can sleep again + flushedAt: 0, + sinceTrim: t?.sinceTrim || {}, + lastAlarmAt: t?.lastAlarmAt || 0, + alarmRun: t?.alarmRun || 0, + burstAlertAt: t?.burstAlertAt || 0, + }; + trackers.set(room.ctx, t); + return t; +} + +function flush(room: Room, t: Tracker): void { + if (!t.dirty) return; + t.dirty = false; + t.flushedAt = Date.now(); + t.counts.rows_written = (t.counts.rows_written || 0) + 1; + room.ctx.storage.sql.exec( + "INSERT INTO daily_stats (day, data) VALUES (?, ?) ON CONFLICT(day) DO UPDATE SET data = excluded.data", + t.day, + JSON.stringify(t.counts), + ); +} + +/** Adds to today's counter. Counts reach SQLite at most every FLUSH_MS and at the end of each request and alarm (settleCounts). Never throws. */ +export function count(room: Room, name: string, n = 1): void { + try { + const now = Date.now(), + t = tracker(room, now); + t.counts[name] = (t.counts[name] || 0) + n; + t.dirty = true; + if (name === "requests" || name === "alarms") { + const load = (t.counts.requests || 0) + (t.counts.alarms || 0); + for (const at of DAILY_ALERTS) + if (load >= at && !t.counts["alert_" + at]) { + t.counts["alert_" + at] = 1; + trace(room, "warn", `room load passed ${at} requests and alarms today`, { + requests: t.counts.requests || 0, + alarms: t.counts.alarms || 0, + }); + } + } + if (now - t.flushedAt >= FLUSH_MS) flush(room, t); + } catch {} +} + +/** + * Called at the end of every request (`always` false) and alarm (`always` true): a room idle for seconds hibernates and + * drops what is only in memory. An alarm already writes state, so its counters go with it; a request (or an alarm in a + * burst) writes them once SETTLE_MS has passed, which bounds the rows a chatty channel or a runaway alarm adds. Never throws. + */ +export function settleCounts(room: Room, always = false): void { + try { + const now = Date.now(), + t = tracker(room, now); + // during an alarm burst (the runaway loop) an alarm saves like a request, so the counters never double its writes + if ((always && t.alarmRun < BURST_RUN) || now - t.flushedAt >= SETTLE_MS) flush(room, t); + } catch {} +} + +/** Writes today's counters now (the stats route and tests read them straight after). Never throws. */ +export function flushCounts(room: Room): void { + try { + flush(room, tracker(room, Date.now())); + } catch {} +} + +/** The last `days` days of counters, newest first. */ +export function readCounts(room: Room, days = 7): { day: string; counts: Counts }[] { + flushCounts(room); + return room.ctx.storage.sql + .exec<{ day: string; data: string }>("SELECT day, data FROM daily_stats ORDER BY day DESC LIMIT ?", days) + .toArray() + .map((r) => { + let counts: Counts = {}; + try { + counts = JSON.parse(r.data); + } catch {} + return { day: r.day, counts }; + }); +} + +/** + * One debug line. Always printed to Workers Logs as JSON ({log, message, ...context}). Stored in the room's log + * unless `store` is false; the busy sources (KEEP_ROWS) store at most DAILY_STORE_CAP rows a day. Never throws. + */ +export function trace(room: Room, source: string, message: string, context: JsonObject = {}, store = true): void { + try { + const line = JSON.stringify({ log: source, message, ...context }); + if (source === "room" || source === "worker") console.error(line); + else if (source === "warn") console.warn(line); + else console.log(line); + } catch {} + try { + count(room, "log_" + source); + const t = tracker(room, Date.now()); + if (!store || (source in KEEP_ROWS && (t.counts["log_" + source] || 0) > DAILY_STORE_CAP)) return; + storeLog(room, t, source, message, context); + } catch {} +} + +function storeLog(room: Room, t: Tracker, source: string, message: string, context: JsonObject): void { + const sql = room.ctx.storage.sql; + let ctx = JSON.stringify(context ?? {}) || "{}"; + if (ctx.length > 2000) ctx = JSON.stringify({ truncated: ctx.slice(0, 1900) }); + sql.exec( + "INSERT INTO error_log (at, source, message, context) VALUES (?, ?, ?, ?)", + Date.now(), + source, + String(message || "unknown").slice(0, 500), + ctx, + ); + t.counts.rows_written = (t.counts.rows_written || 0) + 1; + // Trimming scans the table, so it runs every TRIM_EVERY rows per source: each source keeps its own tail, and a burst + // of traces never pushes the errors out. + t.sinceTrim[source] = (t.sinceTrim[source] || 0) + 1; + if (t.sinceTrim[source] < TRIM_EVERY) return; + t.sinceTrim[source] = 0; + const cut = sql.exec( + "DELETE FROM error_log WHERE source = ? AND id <= (SELECT id FROM error_log WHERE source = ? ORDER BY id DESC LIMIT 1 OFFSET ?)", + source, + source, + KEEP_ROWS[source] ?? KEEP_DEFAULT, + ); + t.counts.rows_written += cut.rowsWritten ?? 0; +} + +/** + * Counts one alarm run, traces why it ran and how late, and warns on a burst: BURST_RUN alarms in a row, each under a + * second after the last, is the loop that once spent the request budget. Never throws. + */ +export function noteAlarm(room: Room, reasons: string[], lateMs: number | null, channel: string): void { + try { + const now = Date.now(), + t = tracker(room, now); + t.alarmRun = now - t.lastAlarmAt < BURST_GAP_MS ? t.alarmRun + 1 : 1; + t.lastAlarmAt = now; + count(room, "alarms"); + if (!reasons.length) count(room, "alarms_idle"); + trace(room, "alarm", "ran " + (reasons.join(",") || "nothing due"), { channel, reasons, lateMs, run: t.alarmRun }); + if (t.alarmRun >= BURST_RUN && now - t.burstAlertAt >= BURST_ALERT_MS) { + t.burstAlertAt = now; + trace(room, "warn", `alarm burst: ${t.alarmRun} alarms under a second apart`, { channel, reasons }); + } + } catch {} +} diff --git a/src/dev.ts b/src/dev.ts index 1288771..0c1874b 100644 --- a/src/dev.ts +++ b/src/dev.ts @@ -8,6 +8,7 @@ import { parseRuns, parseSession, parseSettings, + parseStats, parseVersions, } from "./parse.ts"; import type { Channel, Channels, Progress, TargetVersions } from "./parse.ts"; @@ -172,7 +173,7 @@ async function start() { if (!($("#branch") as HTMLInputElement).value) // element type from the page HTML ($("#branch") as HTMLInputElement).value = "live-fix/" + new Date().toISOString().slice(0, 10); - await Promise.all([loadDiagnostics(), loadConfig(), loadLogs(), loadChannels()]); + await Promise.all([loadDiagnostics(), loadConfig(), loadLogs(), loadStats(), loadChannels()]); loadRuns(); loadVersions(); } @@ -1013,9 +1014,17 @@ async function loadLogs() { "td", {}, // indexed by any stored source; one this page doesn't name falls back to the raw text - ({ room: "Durable Object", worker: "Worker", command: "Chat command", warn: "Warning" } as SourceLabels)[ - x.source - ] || x.source, + ( + { + room: "Durable Object", + worker: "Worker", + command: "Chat command", + warn: "Warning", + alarm: "Alarm", + duel: "Duel", + chat: "Chat delivery", + } as SourceLabels + )[x.source] || x.source, ), h("td", { class: "wrap" }, x.message), h("td", { class: "wrap ctx" }, h("code", {}, x.context ? JSON.stringify(x.context) : "–")), @@ -1025,10 +1034,45 @@ async function loadLogs() { 4, ); } +// The counters that answer "is something looping or stuck" lead the table; the rest follow by name. +const LEAD_COUNTERS = ["requests", "alarms", "alarms_idle", "rows_written", "bot_sent", "bot_failed", "bot_held"]; +async function loadStats() { + // element type from the page HTML + const channel = ($("#log-channel") as HTMLSelectElement).value, + r = parseAnswer(await api("/api/dev/stats?days=7&channel=" + channel), parseStats, "the counters"); + const days = r.ok ? r.data : []; + // element type from the page HTML + ($("#stats-head") as HTMLTableRowElement).replaceChildren( + h("th", {}, "Counter"), + ...days.map((d) => h("th", { class: "num" }, d.day.slice(5))), + ); + if (!r.ok) return rows("#stats", [], errorText(r, "Counters unavailable"), 1); + const names = new Set(days.flatMap((d) => Object.keys(d.counts))); + const order = [ + ...LEAD_COUNTERS.filter((n) => names.has(n)), + ...[...names].filter((n) => !LEAD_COUNTERS.includes(n)).sort(), + ]; + rows( + "#stats", + order.map((name) => + h( + "tr", + {}, + h("td", {}, h("code", {}, name)), + ...days.map((d) => h("td", { class: "num" }, name in d.counts ? fmtNum(d.counts[name]) : "–")), + ), + ), + "Nothing counted yet for " + channel + ".", + days.length + 1, + ); +} // element type from the page HTML ($("#log-source") as HTMLSelectElement).addEventListener("change", loadLogs); // element type from the page HTML -($("#log-channel") as HTMLSelectElement).addEventListener("change", loadLogs); +($("#log-channel") as HTMLSelectElement).addEventListener("change", () => { + loadLogs(); + loadStats(); +}); // element type from the page HTML ($("#clear-logs") as HTMLButtonElement).addEventListener("click", (e) => // the listener sits on a button @@ -1054,7 +1098,7 @@ async function loadLogs() { ($("#refresh") as HTMLButtonElement).addEventListener("click", (e) => // the listener sits on a button busy(e.currentTarget as HTMLButtonElement, async () => { - await Promise.all([loadDiagnostics(), loadLogs(), loadChannels()]); + await Promise.all([loadDiagnostics(), loadLogs(), loadStats(), loadChannels()]); loadRuns(); loadVersions(); }), diff --git a/src/parse.ts b/src/parse.ts index 0438e7d..3d06674 100644 --- a/src/parse.ts +++ b/src/parse.ts @@ -676,3 +676,11 @@ const parseLogRow = shape({ at: num, source: str, message: str }, "log r export function parseLogs(value: unknown): Parsed { return Array.isArray(value) ? ok(keepGood(value, "a log row", parseLogRow)) : bad("logs is not a list"); } + +/** One UTC day of a room's counters (GET /api/dev/stats), newest day first. */ +export type StatsDay = { day: string; counts: Record }; +const parseStatsDay = shape({ day: str, counts: numMap }, "stats day"); +export function parseStats(value: unknown): Parsed { + if (!isObject(value) || !Array.isArray(value.days)) return bad("stats.days is not a list"); + return ok(keepGood(value.days, "a stats day", parseStatsDay)); +} diff --git a/tests/browser-parse.test.ts b/tests/browser-parse.test.ts index da0d6f0..7906b08 100644 --- a/tests/browser-parse.test.ts +++ b/tests/browser-parse.test.ts @@ -24,6 +24,7 @@ import { parseSettings, parseShop, parseStateConfig, + parseStats, parseVersions, } from "../src/parse.ts"; import { @@ -363,9 +364,15 @@ test("owner page: runs, versions, settings, channels, progress and logs", (t) => const log = { at: 1, source: "chat", message: "hi", context: { a: 1 } }; assert.deepEqual(parseLogs([log, { at: 1 }]), { ok: true, value: [log] }); + const day = { day: "2026-10-16", counts: { requests: 40, alarms: 3 } }; + assert.deepEqual(parseStats({ channel: "ann", days: [day, { day: "2026-10-15", counts: { alarms: "3" } }] }), { + ok: true, + value: [day], + }); + assert.deepEqual(parseStats({ channel: "ann" }), { ok: false, error: "stats.days is not a list" }); assert.equal( warn.mock.callCount(), - 6, - "one warning per list kind: runs, targets, config versions, channels, progress, logs", + 7, + "one warning per list kind: runs, targets, config versions, channels, progress, logs, stats", ); }); diff --git a/tests/channel.test.ts b/tests/channel.test.ts index b8cb4c8..261ed54 100644 --- a/tests/channel.test.ts +++ b/tests/channel.test.ts @@ -516,6 +516,34 @@ test("an expired rematch lock is saved away, so the alarm doesn't re-arm for now assert.ok(next === null || next > Date.now() + 1000, "no alarm due again right away"); }); +test("the room log says why each alarm ran, and keeps duel events and chat counts", async (t) => { + for (const level of ["log", "warn", "error"] as const) t.mock.method(console, level, () => {}); + const r = room(); + await r.save("u1", "alice"); + await r.save("u2", "bob"); + await r.connectChat(); + await r.chat("u1", "alice", "!challenge @bob"); + const s = r.readState("nesszerra"); + s.rematchLocks = [{ pair: "u1:u3", until: Date.now() - 1 }]; + r.writeState(s); + await r.alarm(); + const log = (source: string) => + r.ctx.storage.sql + .exec<{ message: string }>("SELECT message FROM error_log WHERE source = ? ORDER BY id", source) + .toArray() + .map((x) => x.message); + assert.ok(log("alarm").includes("ran rematch_lock"), log("alarm").join(" | ")); + assert.ok(log("alarm").some((m) => m.startsWith("set challenge_expiry"))); + assert.ok(log("duel").includes("challenge_created")); + assert.ok(log("chat").includes("chat_connected")); + const stats = (await r.call("/dev/stats")).body; + const today = stats.days[0].counts; + assert.equal(today.eventsub_notification, 1); + assert.equal(today.event_challenge_created, 1); + assert.equal(today.alarms, 1); + assert.ok(today.requests >= 5); +}); + test("versioned config editor: history, optimistic version check, rollback", async () => { const r = room(); const a = await r.call("/admin", { diff --git a/tests/dev-api.test.ts b/tests/dev-api.test.ts index afd2d4a..838a787 100644 --- a/tests/dev-api.test.ts +++ b/tests/dev-api.test.ts @@ -876,6 +876,29 @@ test("error log: worker errors land in the room, can be filtered, and cleared", assert.equal((await call(f, "/api/dev/logs", "GET", undefined, owner)).body.length, 0); }); +test("owner logs filter by every stored source, and stats show today's counters", async (t) => { + for (const level of ["log", "warn", "error"] as const) t.mock.method(console, level, () => {}); + const f = environment(), + owner = await cookieFor(f, true); + f.env.ROOMS.get("nesszerra"); + const r = must(f.rooms.get("nesszerra")); + logRoomEvent(r, "command", "alice challenge @bob -> challenge"); + logRoomEvent(r, "warn", "slow"); + logRoomEvent(r, "alarm", "ran rematch_lock"); + for (const source of ["command", "warn", "alarm"]) { + const logs = await call(f, "/api/dev/logs?source=" + source, "GET", undefined, owner); + assert.deepEqual( + logs.body.map((l: { source: string }) => l.source), + [source], + ); + } + const stats = await call(f, "/api/dev/stats?channel=nesszerra&days=3", "GET", undefined, owner); + assert.equal(stats.status, 200); + assert.equal(stats.body.channel, "nesszerra"); + assert.equal(stats.body.days[0].counts.log_warn, 1); + assert.equal(stats.body.days[0].counts.log_alarm, 1); +}); + test("live settings passthrough edits the versioned config as the session user", async () => { const f = environment(), owner = await cookieFor(f, true); diff --git a/tests/dev-ui.ts b/tests/dev-ui.ts index 12f0d28..cee36fa 100644 --- a/tests/dev-ui.ts +++ b/tests/dev-ui.ts @@ -137,6 +137,14 @@ async function stub(page: Page, { configured, calls = { progress: [] } }: StubOp ], }); if (op === "settings") return json(r, { ok: true }); + if (op === "stats") + return json(r, { + channel: "nesszerra", + days: [ + { day: "2026-10-16", counts: { requests: 1840, alarms: 212, event_challenge_created: 9, bot_sent: 31 } }, + { day: "2026-10-15", counts: { requests: 2310, alarms: 260, bot_sent: 44 } }, + ], + }); if (op === "logs") return json(r, [ { @@ -289,6 +297,12 @@ for (const size of sizes) { assert.match((await page.textContent("#summary-title"))!, /chat offline/); // !: the element is on the page, so its textContent is a string assert.match((await page.textContent("#github-missing"))!, /GITHUB_TOKEN, GITHUB_REPO/); + // lead counters first, then the rest by name; a day without a counter shows a dash + assert.deepEqual( + await page.$$eval("#stats tr", (trs: HTMLTableRowElement[]) => trs.map((t) => t.innerText.split(" ").join(" "))), + ["requests 1,840 2,310", "alarms 212 260", "bot_sent 31 44", "event_challenge_created 9 –"], + ); + assert.equal(await page.textContent("#stats-head"), "Counter10-1610-15"); assert.equal(await page.isDisabled("#deploy-test"), true); assert.equal(await page.isDisabled("#save-file"), true); assert.deepEqual(await page.$$eval("#sec-code, #sec-release", (s: HTMLElement[]) => s.map((x) => x.hidden)), [ diff --git a/tests/fakes.ts b/tests/fakes.ts index 856f41f..566579e 100644 --- a/tests/fakes.ts +++ b/tests/fakes.ts @@ -12,7 +12,7 @@ import type { Stats } from "../server/upgrades.ts"; export type Loose = any; /** A cursor like SqlStorageCursor: the rows of one statement, read whole or iterated. */ -export type FakeCursor = { toArray(): Loose[]; [Symbol.iterator](): Iterator }; +export type FakeCursor = { toArray(): Loose[]; [Symbol.iterator](): Iterator; rowsWritten?: number }; export type FakeSql = { exec(query: string, ...params: SQLInputValue[]): FakeCursor }; /** `ctx.storage.sql` over an in-memory SQLite database. Rows come back as plain objects, as SqlStorage returns them. */ @@ -24,7 +24,11 @@ export function fakeSql(): FakeSql & SqlStorage { .prepare(query) .all(...params) .map((r) => ({ ...r })); - return { toArray: () => rows, [Symbol.iterator]: () => rows[Symbol.iterator]() }; + // like SqlStorageCursor.rowsWritten, without the index entries Cloudflare also counts + const rowsWritten = /^\s*(INSERT|UPDATE|DELETE|REPLACE)/i.test(query) + ? Number(db.prepare("SELECT changes() AS n").get()?.n) + : 0; + return { toArray: () => rows, [Symbol.iterator]: () => rows[Symbol.iterator](), rowsWritten }; }, }; return sql as FakeSql & SqlStorage; // the fake has only exec, the one SqlStorage call the server makes diff --git a/tests/tracker.test.ts b/tests/tracker.test.ts new file mode 100644 index 0000000..489eb46 --- /dev/null +++ b/tests/tracker.test.ts @@ -0,0 +1,143 @@ +import test from "node:test"; +import type { TestContext } from "node:test"; +import assert from "node:assert/strict"; +import { + BURST_RUN, + DAILY_STORE_CAP, + count, + ensureTrackerSchema, + noteAlarm, + readCounts, + settleCounts, + trace, +} from "../server/tracker.ts"; +import { ensureDeveloperSchema } from "../server/developer.ts"; +import { fakeCtx, fakeSql } from "./fakes.ts"; +import type { FakeSql } from "./fakes.ts"; + +function room(sql: FakeSql = fakeSql()) { + const ctx = fakeCtx({ sql }); + ensureDeveloperSchema(ctx.storage.sql); + ensureTrackerSchema(ctx.storage.sql); + return { ctx }; +} +const rows = (r: ReturnType, source: string) => + r.ctx.storage.sql + .exec<{ message: string }>("SELECT message FROM error_log WHERE source = ? ORDER BY id", source) + .toArray() + .map((x) => x.message); +const quiet = (t: TestContext) => { + const lines: string[] = []; + for (const level of ["log", "warn", "error"] as const) + t.mock.method(console, level, (line: string) => lines.push(line)); + return lines; +}; + +test("a trace prints one JSON line and stores a row; store=false prints only", (t) => { + const lines = quiet(t), + r = room(); + trace(r, "duel", "duel_started", { channel: "nesszers", duelId: "d1" }); + trace(r, "chat", "heard", { channel: "nesszers", user: "alice" }, false); + assert.deepEqual( + lines.map((l) => JSON.parse(l)), + [ + { log: "duel", message: "duel_started", channel: "nesszers", duelId: "d1" }, + { log: "chat", message: "heard", channel: "nesszers", user: "alice" }, + ], + ); + assert.deepEqual(rows(r, "duel"), ["duel_started"]); + assert.deepEqual(rows(r, "chat"), []); + assert.deepEqual(readCounts(r)[0]?.counts.log_chat, 1); +}); + +test("busy sources store at most the daily cap, and count every line", (t) => { + quiet(t); + const r = room(); + for (let i = 0; i < DAILY_STORE_CAP + 5; i++) trace(r, "alarm", "set x " + i); + const kept = rows(r, "alarm"); + assert.ok(kept.length <= 225, "trimmed to its own tail of 200 (plus at most one trim batch)"); + assert.equal(kept.at(-1), "set x " + (DAILY_STORE_CAP - 1), "nothing past the cap is stored"); + assert.equal(readCounts(r)[0]?.counts.log_alarm, DAILY_STORE_CAP + 5); +}); + +test("each source trims its own tail, so traces never push errors out", (t) => { + quiet(t); + const r = room(); + trace(r, "room", "the one error"); + for (let i = 0; i < 260; i++) trace(r, "duel", "duel_action " + i); + assert.deepEqual(rows(r, "room"), ["the one error"]); + assert.ok(rows(r, "duel").length < 225); +}); + +test("counters survive a restart: a new instance keeps adding to today's row", (t) => { + quiet(t); + const sql = fakeSql(), + a = room(sql); + count(a, "requests", 3); + readCounts(a); // flushes + const b = room(sql); + count(b, "requests", 2); + const today = readCounts(b); + assert.equal(today.length, 1); + assert.equal(today[0]?.day, new Date().toISOString().slice(0, 10)); + assert.equal(today[0]?.counts.requests, 5); +}); + +test("a day's load past 25000 requests and alarms logs one warning", (t) => { + quiet(t); + const r = room(); + count(r, "requests", 24_999); + assert.deepEqual(rows(r, "warn"), []); + count(r, "alarms"); + count(r, "requests"); + assert.deepEqual(rows(r, "warn"), ["room load passed 25000 requests and alarms today"]); +}); + +test("an alarm burst logs one warning, and alarms trace why they ran", (t) => { + quiet(t); + const r = room(); + noteAlarm(r, ["rematch_lock"], 3, "nesszers"); + for (let i = 1; i < BURST_RUN * 2; i++) noteAlarm(r, [], null, "nesszers"); + assert.equal(rows(r, "alarm")[0], "ran rematch_lock"); + assert.equal(rows(r, "alarm")[1], "ran nothing due"); + assert.deepEqual(rows(r, "warn"), [`alarm burst: ${BURST_RUN} alarms under a second apart`]); + const c = readCounts(r)[0]?.counts; + assert.deepEqual([c?.alarms, c?.alarms_idle], [BURST_RUN * 2, BURST_RUN * 2 - 1]); +}); + +test("settleCounts writes what a woken room counted before it can hibernate", (t) => { + quiet(t); + const sql = fakeSql(), + stored = () => { + const row = sql.exec<{ data: string }>("SELECT data FROM daily_stats").toArray()[0]; + return row ? JSON.parse(row.data) : undefined; + }, + a = room(sql); + count(a, "requests"); + assert.equal(stored()?.requests, 1, "the first count after a wake writes"); + count(a, "requests"); + settleCounts(a); + assert.equal(stored()?.requests, 1, "a request right after the last write waits"); + noteAlarm(a, ["respawn"], 0, "nesszers"); + settleCounts(a, true); + assert.deepEqual([stored()?.requests, stored()?.alarms], [2, 1], "an alarm always writes"); +}); + +test("alarms in a burst save counters at most every SETTLE_MS, not on every run", (t) => { + quiet(t); + const sql = fakeSql(), + r = room(sql), + storedAlarms = () => + JSON.parse(sql.exec<{ data: string }>("SELECT data FROM daily_stats").toArray()[0]?.data ?? "{}").alarms; + t.mock.timers.enable({ apis: ["Date"], now: 1_800_000_000_000 }); + const alarm = () => { + noteAlarm(r, ["tick"], 0, "nesszers"); + settleCounts(r, true); + t.mock.timers.tick(100); + return storedAlarms(); + }; + const beforeBurst = Array.from({ length: BURST_RUN }, alarm); + assert.deepEqual(beforeBurst.slice(-2), [BURST_RUN - 1, BURST_RUN - 1], "alarms save each run until the burst"); + const inBurst = new Set(Array.from({ length: 100 }, alarm)); + assert.deepEqual([...inBurst], [BURST_RUN - 1, 119], "100 burst alarms over 10 s save once, after SETTLE_MS"); +}); diff --git a/tsconfig.node.json b/tsconfig.node.json index 94416bf..3d8c284 100644 --- a/tsconfig.node.json +++ b/tsconfig.node.json @@ -33,10 +33,12 @@ "tests/upload.test.ts", "tests/worker.test.ts", "tests/parse.test.ts", + "tests/tracker.test.ts", "vite.config.ts", "scripts/install-hooks.ts", "scripts/release.ts", "scripts/devtools.ts", + "scripts/logs.ts", "scripts/test-all.ts", "tests/chrome.ts", "tests/seed-local.ts",