Debug tracing: alarm, duel and chat logs, daily room counters, logs script

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

admin/dev/index.html

@@ -111,14 +111,24 @@ <h2>Error log, newest first</h2>
             <label class="inline" for="log-channel">Channel</label>
             <select id="log-channel" class="narrow"><option value="%SITE_CHANNEL%">%SITE_CHANNEL%</option></select>
             <label class="inline" for="log-source">Source</label>
-            <select id="log-source" class="narrow"><option value="">All</option><option value="room">Durable Object</option><option value="worker">Worker</option><option value="command">Chat commands</option><option value="warn">Warnings</option></select>
+            <select id="log-source" class="narrow"><option value="">All</option><option value="room">Durable Object</option><option value="worker">Worker</option><option value="command">Chat commands</option><option value="warn">Warnings</option><option value="alarm">Alarms</option><option value="duel">Duels</option><option value="chat">Chat delivery</option></select>
             <button class="btn" id="clear-logs" type="button">Clear log</button>
           </div>
           <div class="table-wrap"><table class="data">
             <thead><tr><th>Time</th><th>Source</th><th>Message</th><th>Context</th></tr></thead>
             <tbody id="logs"></tbody>
           </table></div>
-          <p class="caveat">The newest 100 of up to 200 stored rows per channel.</p>
+          <p class="caveat">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.</p>
+        </section>
+
+        <section class="section" id="sec-stats">
+          <h2>Room counters by day</h2>
+          <p class="muted">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.</p>
+          <div class="table-wrap"><table class="data">
+            <thead><tr id="stats-head"><th>Counter</th></tr></thead>
+            <tbody id="stats"></tbody>
+          </table></div>
+          <p class="caveat">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.</p>
         </section>
 
         <details class="history" id="dev-tools">

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:<login>` 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=<login>[&day=YYYY-MM-DD[&user=<login or id>]]` | 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-<login>-<day>-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=<login>&user=<login or id>[&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=<login>&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=<login>[&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[_<reason>]`, `eventsub_<kind>`, `event_<type>` and `log_<source>`. 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 <keys>`) |
 | 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

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

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<string, string> = {};
+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 <login>] [--source <log>] [--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 : ""}`,
+);