Show live and retained run logs in the admin panel

This commit is contained in:
Matt Isenhower
2026-09-07 13:42:25 -07:00
parent ec797c4e13
commit f9154a1dfb
12 changed files with 142 additions and 14 deletions

38
src/app/log.js Normal file
View File

@@ -0,0 +1,38 @@
import { AsyncLocalStorage } from 'node:async_hooks';
// Capture application messages for one run without replacing the global console.
const currentRun = new AsyncLocalStorage();
const MAX_LINES = 200;
const MAX_LINE_LENGTH = 500;
const MAX_BYTES = 32_000;
const encoder = new TextEncoder();
export function createRunLog(secrets = []) {
let snapshot = { lines: [], omitted: 0 };
return {
snapshot,
run: callback => currentRun.run({ snapshot, bytes: 0, secrets: secrets.filter(value => typeof value === 'string' && value.length >= 6) }, callback),
};
}
export function logMessage(level, message, fields) {
if (fields === undefined) console[level](message);
else if (fields.updater) console[level]({ message, ...fields });
else console[level](message, fields);
let context = currentRun.getStore();
if (!context) return;
let text = message instanceof Error ? message.message : String(message);
// Keep readable progress messages; the full structured result has its own JSON view.
if (fields?.updater) text = `[${fields.updater}] ${text}`;
if (fields?.error) text += `: ${fields.error}`;
if (fields?.attempt) text += ` (retry ${fields.attempt})`;
for (let secret of context.secrets) text = text.replaceAll(secret, '[redacted]');
text = text.replace(/Bearer\s+[^\s,;]+/gi, 'Bearer [redacted]');
const { snapshot } = context;
snapshot.lines.push({ at: Date.now(), level, text: text.length > MAX_LINE_LENGTH ? text.slice(0, MAX_LINE_LENGTH) + '…' : text });
context.bytes += encoder.encode(JSON.stringify(snapshot.lines.at(-1))).length;
while (snapshot.lines.length > MAX_LINES || context.bytes > MAX_BYTES) {
context.bytes -= encoder.encode(JSON.stringify(snapshot.lines.shift())).length;
snapshot.omitted++;
}
}

View File

@@ -1,3 +1,4 @@
import { logMessage } from '../log.js';
import { fetchWithTimeout } from '../../common/fetch.js';
import { screenshotReadySelector } from '../../common/screenshot.js';
@@ -95,7 +96,7 @@ export async function captureScreenshot({ hash, viewport: viewportOverrides, for
if (!retryable || attempt === 3)
throw error;
let delayMs = 500 * 2 ** attempt;
console.warn('Retrying Browser Run screenshot', { attempt: attempt + 1, delayMs, error: error.message });
logMessage('warn', 'Retrying Browser Run screenshot', { attempt: attempt + 1, delayMs, error: error.message });
await new Promise(resolve => setTimeout(resolve, delayMs));
}
}

View File

@@ -1,3 +1,4 @@
import { logMessage } from '../../log.js';
import { convertToJpeg } from '#image-converter';
import { getTopOfCurrentHour } from '../../../common/time.js';
import { pngSize } from '../../../common/png.js';
@@ -160,15 +161,15 @@ export default class SocialPostBase {
}
log(message) {
console.log(this.formatLogMessage(message));
logMessage('log', this.formatLogMessage(message));
}
info(message) {
console.info(this.formatLogMessage(message));
logMessage('info', this.formatLogMessage(message));
}
error(message) {
console.error(this.formatLogMessage(message));
logMessage('error', this.formatLogMessage(message));
}
/**

View File

@@ -1,3 +1,4 @@
import { logMessage } from '../log.js';
import SchedulesUpdater from './updaters/SchedulesUpdater.js';
import CoopSchedulesUpdater from './updaters/CoopSchedulesUpdater.js';
import TimelineUpdater from './updaters/TimelineUpdater.js';
@@ -47,7 +48,7 @@ export default async function updateAll(storage, { only } = {}) {
await updater.update();
results.push({ name, ok: true, ms: Date.now() - started });
} catch (e) {
console.error(e);
logMessage('error', e);
results.push({ name, ok: false, ms: Date.now() - started, error: e instanceof Error ? e.message : String(e) });
}
}

View File

@@ -1,3 +1,4 @@
import { logMessage } from '../../log.js';
import _ from 'lodash';
import jsonpath from '../../../common/jsonpath.js';
import SplatNet from '../../../common/splatnet.js';
@@ -252,14 +253,14 @@ export default class Updater {
}
log(message) {
console.log(this.formatLogMessage(message));
logMessage('log', this.formatLogMessage(message));
}
info(message) {
console.info(this.formatLogMessage(message));
logMessage('info', this.formatLogMessage(message));
}
error(message) {
console.error(this.formatLogMessage(message));
logMessage('error', this.formatLogMessage(message));
}
}

28
test/admin/log.test.mjs Normal file
View File

@@ -0,0 +1,28 @@
import { test, mock } from 'node:test';
import assert from 'node:assert/strict';
import { createRunLog, logMessage } from '../../src/app/log.js';
test('bounds retained logs, redacts secrets, and preserves normal console output', async () => {
const consoleLog = mock.method(console, 'info', () => {});
try {
const capture = createRunLog(['secret-value']);
await capture.run(async () => {
for (let i = 0; i < 205; i++) logMessage('info', `line ${i}`);
logMessage('info', 'secret-value Bearer sensitive-token');
});
assert.equal(capture.snapshot.lines.length, 200);
assert.equal(capture.snapshot.omitted, 6);
assert.equal(capture.snapshot.lines.at(-1).text, '[redacted] Bearer [redacted]');
assert.equal(consoleLog.mock.callCount(), 206);
} finally { mock.restoreAll(); }
});
test('concurrent run contexts do not capture each other or unrelated messages', async () => {
mock.method(console, 'info', () => {});
try {
const a = createRunLog(), b = createRunLog();
await Promise.all([a.run(async () => { await Promise.resolve(); logMessage('info', 'a'); }), b.run(async () => { logMessage('info', 'b'); })]);
logMessage('info', 'outside');
assert.deepEqual(a.snapshot.lines.map(l => l.text), ['a']);
assert.deepEqual(b.snapshot.lines.map(l => l.text), ['b']);
} finally { mock.restoreAll(); }
});

View File

@@ -127,6 +127,14 @@ normal checkpoints and the published-data check. An interrupted manual run is
reported as failed rather than automatically replaying an uncertain social send.
The hourly schedule is preserved. Paused scheduling also blocks manual runs.
The panel polls live application log lines every two seconds during a run and
stores up to the latest 200 lines (500 characters each, 32 KB total) with its
final summary.
Known secret values are redacted from captured lines. This includes updater,
social, and screenshot-retry messages, not platform or third-party library logs.
Live lines are held in memory until completion; an isolate interruption can lose
those lines. Full operational logs remain available through Workers logging.
Preview the actual panel with simulated results using `npm run admin:preview`,
then open `http://127.0.0.1:8788/admin/`. This standalone preview server listens
only on loopback and has no production credentials or bindings. The production

View File

@@ -161,6 +161,7 @@ describe('Scheduler', () => {
let first = scheduler.run({ only: ['Schedules'] });
try {
await vi.waitFor(() => expect(entered).toBe(true));
expect((await scheduler.status()).activeRun.logs.lines.some(line => line.text.includes('Updating data'))).toBe(true);
expect(await scheduler.run()).toMatchObject({ ok: false, busy: true });
expect(await scheduler.ensureArmed()).toMatchObject({ busy: true });
expect(await scheduler.pause()).toMatchObject({ ok: false, busy: true });
@@ -198,6 +199,8 @@ describe('Background manual runs', () => {
const status = await runAlarmUntil(scheduler, s => !!s.lastManualRun);
expect(status.lastManualRun).toMatchObject({ id: result.run.id, ok: true, status: 'succeeded', social: { skipped: true } });
expect(status.pendingManual).toBeNull();
expect(status.activeRun).toBeNull();
expect(status.lastManualRun.logs.lines.some(line => line.text.includes('Done.'))).toBe(true);
expect(status.hourlyAt).toBe(hourlyAt);
expect(renders).toHaveLength(0);
});

View File

@@ -8,7 +8,7 @@ const hour = Math.floor(Date.now() / 3600000) * 3600000;
const state = {
preview: true, user: { email: 'Local preview' }, paused: false, busy: false,
hourlyAt: hour + 3600000 + 10000, retryAt: null, pendingManual: null,
lastManualRun: { id: 'previous', mode: 'social', ok: false, status: 'failed', startedAt: hour - 1800000, runMs: 42300, error: 'Browser screenshot timed out. The post was not sent.' },
lastManualRun: { logs: { lines: [{ at: hour - 1800000, level: 'info', text: 'Starting social cycle' }, { at: hour - 1757700, level: 'error', text: 'Browser screenshot timed out. The post was not sent.' }], omitted: 0 }, id: 'previous', mode: 'social', ok: false, status: 'failed', startedAt: hour - 1800000, runMs: 42300, error: 'Browser screenshot timed out. The post was not sent.' },
lastRun: { mode: 'both', ok: true, startedAt: hour + 10000, runMs: 18200, updaters: { ok: true }, social: { ok: true } },
};
createServer(async (request, response) => {
@@ -30,13 +30,18 @@ createServer(async (request, response) => {
if (!['data', 'social', 'both'].includes(mode)) return json({ error: 'Unknown mode.' }, 400);
const run = { id: randomUUID(), mode, status: 'queued', requestedAt: Date.now() };
state.busy = true; state.pendingManual = run;
const logs = { lines: [{ at: Date.now(), level: 'info', text: `Starting ${mode} run` }], omitted: 0 };
state.activeRun = { mode, startedAt: Date.now(), logs };
setTimeout(() => logs.lines.push({ at: Date.now(), level: 'info', text: mode === 'social' ? '[Social] Checking post checkpoints…' : '[Updater] [Schedules] Updating data…' }), 1500);
setTimeout(() => logs.lines.push({ at: Date.now(), level: 'info', text: mode === 'social' ? '[Social] Preparing a due Bluesky post…' : '[Updater] [Schedules] Done.' }), 3200);
setTimeout(() => logs.lines.push({ at: Date.now(), level: 'info', text: '[Preview] Simulated work completed.' }), 5000);
setTimeout(() => { run.status = 'running'; run.startedAt = Date.now(); }, 700);
setTimeout(() => {
state.lastManualRun = { ...run, ok: true, status: 'succeeded', finishedAt: Date.now(), runMs: Date.now() - run.startedAt,
state.lastManualRun = { ...run, logs, ok: true, status: 'succeeded', finishedAt: Date.now(), runMs: Date.now() - run.startedAt,
updaters: mode === 'social' ? { ok: true, skipped: true } : { ok: true, updaters: ['Schedules', 'Timeline', 'CoopSchedules', 'Merchandises'].map(name => ({ name, ok: true })) },
social: mode === 'data' ? { ok: true, skipped: true } : { ok: true, posts: [{ name: 'Schedule', ok: true, simulated: true }] },
};
state.busy = false; state.pendingManual = null;
state.busy = false; state.pendingManual = null; state.activeRun = null;
}, 6000);
return json({ ok: true, run }, 202);
}

View File

@@ -1,3 +1,4 @@
import { createRunLog, logMessage } from '../../../src/app/log.js';
// One owner for the hourly update → social pipeline and authenticated manual runs.
// The alarm targets :00:10; the cron watchdog repairs a missing alarm. Alarms can be late.
import { DurableObject } from 'cloudflare:workers';
@@ -15,6 +16,7 @@ export class Scheduler extends DurableObject {
// I/O. This is a lock, not durable job state: interrupted RPC callers receive an error,
// and interrupted alarms are retried by Cloudflare using the persisted schedule.
#running = false;
#activeRun = null;
async #state() {
let saved = await this.ctx.storage.get('state') ?? {};
@@ -72,6 +74,7 @@ export class Scheduler extends DurableObject {
alarmAt: await this.ctx.storage.getAlarm(),
lastManualRun: await this.ctx.storage.get('lastManualRun') ?? null,
pendingManual: await this.#pendingManual(),
activeRun: this.#activeRun,
busy: this.#running || !!await this.#pendingManual(),
};
}
@@ -120,6 +123,23 @@ export class Scheduler extends DurableObject {
}
async #execute(only, mode = 'both') {
const secrets = Object.entries({ ...process.env, ...this.env })
.filter(([key]) => /TOKEN|PASSWORD|SESSION|ACCOUNT_ID|SECRET/.test(key))
.map(([, value]) => value);
const capture = createRunLog(secrets);
this.#activeRun = { mode, startedAt: Date.now(), logs: capture.snapshot };
try {
return await capture.run(async () => {
logMessage('info', `Starting ${mode === 'both' ? 'full cycle' : mode === 'data' ? 'data update' : 'social cycle'}`);
const result = await this.#executeWithLogs(only, mode);
return { ...result, logs: capture.snapshot };
});
} finally {
this.#activeRun = null;
}
}
async #executeWithLogs(only, mode) {
let startedAt = Date.now();
let result;
try {

View File

@@ -9,7 +9,7 @@
:root{font-family:Inter,ui-sans-serif,system-ui,-apple-system,BlinkMacSystemFont,"Segoe UI",sans-serif;color:#f3f2fa;background:#101116;font-synthesis:none;--muted:#aaaaba;--line:#30313d;--purple:#b1a0ff;--green:#91ddb6}
*{box-sizing:border-box}body{margin:0;background:radial-gradient(ellipse at 85% 0%,#242037 0,transparent 48%);min-height:100vh}button,a{-webkit-tap-highlight-color:transparent}button{font:inherit;cursor:pointer}button:disabled{cursor:default;opacity:.45}a{color:var(--purple)}button:focus-visible,a:focus-visible{outline:3px solid var(--purple);outline-offset:4px}.shell{width:min(920px,100% - 48px);margin:auto;padding:38px 0 30px}.top{display:flex;align-items:center;justify-content:space-between;gap:16px;padding-bottom:30px;border-bottom:1px solid var(--line)}.brand{font-weight:750;font-size:18px;letter-spacing:-.5px}.brand span{color:var(--purple)}.tag{font-size:11px;letter-spacing:1.4px;text-transform:uppercase;color:var(--muted);padding:6px 10px;border:1px solid var(--line);border-radius:5px}.intro{padding:38px 0 26px}.eyebrow{font-size:11px;font-weight:700;letter-spacing:2px;color:var(--purple);text-transform:uppercase}h1{font-size:38px;letter-spacing:-1.5px;line-height:1.15;margin:10px 0 12px}p{color:var(--muted);font-size:14px;line-height:1.65;margin:0}.preview{display:none;padding:12px 16px;border:1px solid #54476b;background:#251f32;border-radius:9px;color:#d0bee9;margin-bottom:20px;font-size:13px}.status{display:flex;align-items:center;justify-content:space-between;gap:20px;padding:20px 23px;border:1px solid var(--line);border-radius:12px;background:#1b1c25;margin-bottom:30px}.state-line{display:flex;align-items:center;gap:10px;font-size:15px;font-weight:650}.dot{height:8px;width:8px;border-radius:50%;background:var(--green);box-shadow:0 0 0 4px #91ddb612}.dot.busy{background:var(--purple)}.dot.warning{background:#edb685}.sub{font-size:12px;color:var(--muted);margin-top:7px}.next{text-align:right}.next strong{font-size:14px;font-weight:500}.next small{display:block;color:var(--muted);font-size:11px;margin-bottom:7px}.section-label{display:flex;justify-content:space-between;align-items:center;margin-bottom:14px}h2{font-size:15px;margin:0;font-weight:650}.hint{font-size:12px;color:var(--muted)}.actions{display:grid;grid-template-columns:repeat(3,1fr);gap:14px;margin-bottom:17px}.action{display:flex;flex-direction:column;background:#191a23;border:1px solid var(--line);border-radius:12px;padding:23px 21px}.icon{width:38px;height:38px;display:grid;place-items:center;border-radius:10px;background:#2c2640;color:var(--purple);margin-bottom:22px;font-size:19px}.action:nth-child(2) .icon{background:#20352e;color:#91ddb6}.action:nth-child(3) .icon{background:#333024;color:#e6d595}h3{font-size:16px;margin:0 0 9px;font-weight:650}.action p{font-size:13px;line-height:1.65;flex:1;margin-bottom:24px}.run{width:100%;border:1px solid #454050;border-radius:7px;background:#272431;color:#e6defc;padding:11px 8px;font-size:13px;font-weight:650;min-height:44px}.run:hover:not(:disabled){background:#373046;border-color:#8c75b7}.action:first-child .run{background:#b6a4fa;color:#191226;border-color:#b6a4fa}.action:first-child .run:hover:not(:disabled){background:#cbbbff}.note{font-size:12px;color:var(--muted);margin-bottom:32px;display:flex;gap:8px}.notice{border-radius:8px;background:#272333;border:1px solid #615277;padding:13px 16px;font-size:13px;margin:0 0 20px;line-height:1.6}.notice:empty{display:none}.history{border:1px solid var(--line);border-radius:12px;overflow:hidden}.record{padding:20px 23px;background:#191a23}.record+.record{border-top:1px solid var(--line)}.record-top{display:flex;justify-content:space-between;align-items:center;gap:16px}.record-name{font-weight:550;font-size:14px}.badge{font-size:11px;padding:4px 8px;border-radius:5px;color:var(--green);background:#20352b;white-space:nowrap}.badge.failed{color:#edbd9b;background:#392b27}.badge.neutral{color:var(--muted);background:#292a35}.detail{font-size:12px;color:var(--muted);line-height:1.6;margin-top:8px}.error{color:#edbd9b;margin-top:8px;font-size:12px;overflow-wrap:anywhere}details{margin-top:12px;font-size:12px;color:var(--muted)}summary{cursor:pointer;min-height:24px}pre{white-space:pre-wrap;overflow-wrap:anywhere;padding:12px;background:#111218;border-radius:7px;font-size:11px;line-height:1.6}.footer{display:flex;justify-content:space-between;gap:16px;color:#898a9d;font-size:11px;padding-top:26px;line-height:1.7}.refresh{background:transparent;border:0;color:var(--purple);font-size:12px;padding:8px;min-height:36px}#sign-in{display:none;margin-left:8px}.identity{overflow-wrap:anywhere}
@media(max-width:640px){.shell{width:calc(100% - 32px);padding-top:22px}.top{padding-bottom:22px}.intro{padding:28px 0 24px}h1{font-size:32px}.actions{grid-template-columns:1fr}.action{padding:20px;display:grid;grid-template-columns:40px 1fr;column-gap:16px}.icon{grid-row:1/3;margin:0}.action p{margin:0 0 16px}.run{grid-column:2}.status{padding:18px 17px;align-items:flex-start}.next strong{font-size:12px}.sub{max-width:180px;line-height:1.5}.record{padding:18px 17px}.footer{flex-direction:column;gap:5px}.hint{font-size:11px}.tag{font-size:10px}h3{margin-top:2px}.note{line-height:1.6}}
</style>
.log-view{max-height:300px;overflow:auto;background:#111218;border:1px solid var(--line);border-radius:8px;padding:12px;font:11px/1.8 ui-monospace,SFMono-Regular,Consolas,monospace;white-space:pre-wrap;overflow-wrap:anywhere}.log-line.error{color:#edbd9b;margin:0;font:inherit}.log-line.warn{color:#e6d595}.log-time{color:#898a9d}.log-note{color:var(--muted);font-size:11px;margin:8px 0}#live-run{margin-bottom:24px}#live-run[hidden]{display:none}</style>
</head>
<body>
<main class="shell">
@@ -25,6 +25,7 @@
</section>
<p class="note"><span aria-hidden="true">✓</span> Successful posts are remembered. Retrying a cycle skips posts already sent.</p>
<div id="notice" class="notice" role="status" aria-live="polite"></div><a id="sign-in" href="/admin/">Sign in again</a>
<section id="live-run" hidden><div class="section-label"><h2>Live run log</h2><span class="hint">Updates every 2 seconds</span></div><div id="live-log"></div></section>
<section><div class="section-label"><h2>Recent activity</h2><button class="refresh" id="refresh">Refresh status ↻</button></div><div class="history" id="history"><div class="record"><p>Loading recent runs…</p></div></div></section>
<footer class="footer"><div class="identity" id="identity">Protected by Cloudflare Access</div><div id="checked">Times shown in your local timezone.</div></footer>
</main>
@@ -35,6 +36,17 @@ const $ = id => document.getElementById(id);
let state, sending = false, polling = false, timer, lastRunId;
function date(value) { return value ? new Date(value).toLocaleString([], { month: 'short', day: 'numeric', hour: 'numeric', minute: '2-digit' }) : '—'; }
function controls() { for (const button of buttons) button.disabled = sending || !state || state.busy || state.paused; }
function logView(logs) {
const box = document.createElement('div'); box.className = 'log-view';
if (!logs?.lines?.length) { box.textContent = 'No log lines recorded for this run.'; return box; }
if (logs.omitted) { const note = document.createElement('div'); note.className = 'log-note'; note.textContent = `${logs.omitted} earlier lines omitted. Showing the most recent log lines.`; box.append(note); }
for (const line of logs.lines) {
const row = document.createElement('div'); row.className = 'log-line ' + line.level;
const time = document.createElement('span'); time.className = 'log-time'; time.textContent = new Date(line.at).toLocaleTimeString() + ' ';
row.append(time, document.createTextNode(line.text)); box.append(row);
}
return box;
}
function record(label, run) {
const row = document.createElement('div'); row.className = 'record';
const top = document.createElement('div'); top.className = 'record-top';
@@ -46,7 +58,8 @@ function record(label, run) {
if (run) {
const messages = [run.error, ...(run.updaters?.updaters || []).filter(item => !item.ok).map(item => item.error || `${item.name} failed`), ...(run.social?.posts || []).filter(item => item && !item.ok).map(item => item.error || 'A social post failed')].filter(Boolean);
if (messages.length) { const error = document.createElement('div'); error.className = 'error'; error.textContent = messages.join(' · '); row.append(error); }
const details = document.createElement('details'), summary = document.createElement('summary'), pre = document.createElement('pre'); summary.textContent = 'View run details'; pre.textContent = JSON.stringify(run, null, 2); details.append(summary, pre); row.append(details);
const logDetails = document.createElement('details'), logSummary = document.createElement('summary'); logSummary.textContent = 'View log lines'; logDetails.append(logSummary, logView(run.logs)); row.append(logDetails);
const details = document.createElement('details'), summary = document.createElement('summary'), pre = document.createElement('pre'); summary.textContent = 'View run details'; const { logs, ...summaryResult } = run; pre.textContent = JSON.stringify(summaryResult, null, 2); details.append(summary, pre); row.append(details);
}
return row;
}
@@ -56,6 +69,14 @@ function render() {
$('dot').className = 'dot' + (state.busy ? ' busy' : state.paused ? ' warning' : '');
$('state-detail').textContent = state.pendingManual ? `${names[state.pendingManual.mode]} · ${state.pendingManual.status === 'queued' ? 'waiting to start' : 'running'}` : state.busy ? 'A scheduled or API run is active.' : state.paused ? 'Manual runs are disabled while paused.' : 'The hourly schedule is running automatically.';
$('next').textContent = state.paused ? 'Paused' : date(state.retryAt || state.hourlyAt);
$('live-run').hidden = !state.activeRun;
if (state.activeRun) {
const old = $('live-log').firstElementChild;
const follow = !old || old.scrollHeight - old.scrollTop - old.clientHeight < 30;
const position = old?.scrollTop || 0;
const box = logView(state.activeRun.logs); $('live-log').replaceChildren(box);
box.scrollTop = follow ? box.scrollHeight : position;
}
// Keep expanded details open during polling when the records have not changed.
const signature = JSON.stringify([state.lastManualRun, state.lastRun]);
if ($('history').dataset.signature !== signature) {

View File

@@ -1,8 +1,9 @@
import { logMessage } from '../../../src/app/log.js';
// Structured logging for Workers Logs. Objects (not JSON strings) are logged so the
// dashboard extracts and indexes each field, e.g. filter on driftMs or updater.
export function createLogger(updater) {
function emit(level, message, fields) {
console[level]({ updater, message, ...fields });
logMessage(level, message, { updater, ...fields });
}
return {