Skip to content

Commit 45461ba

Browse files
Brooooooklynclaude
andauthored
Show why hosted requests and cron jobs fail (#395)
## Problem A hosted app (napi-rs) returned about 100 worker 500s in one day. The 5xx alert email pointed to `void project requests` and `void project logs`. Neither command showed the cause: ``` $ void project requests --status 5xx 16:30:14 GET 500 static 1897ms <- the worker answered, but the label says "static" $ void project logs --level error 16:30:12 GET https://napi.rs/sponsors.svg 500 [error] TypeError: Cannot read properties of undefined (reading 'href') <- no stack, although the API returns it 13:00:25 POST https://internal/__void/scheduled 500 [error] AggregateError: Scheduled jobs failed <- which job failed, and why, is lost ``` Three causes: ``` request label dispatch: a path with a file extension (/sponsors.svg) stays "static", even when the app's own route answered it logs stack CLI: prints only `Name: message`; drops errorInfo[].stack and exception.stack cron error runtime: Workers log capture keeps an error's own message and stack, but not AggregateError.errors, so the inner errors vanish ``` ## What this PR changes ``` request label (dispatch metering) dotted path on an SSR deploy, no platform failure ├─ manifest says "not a file" and the worker answers the path ─> ssr ├─ worker owns the path and returns 5xx or times out ─────────> ssr └─ listed file, asset-layer answer, platform asset failure ───> static (unchanged) The ISR write-back checks the path directly, so these routes never enter the ISR cache. void project logs [error] TypeError: Cannot read properties of undefined (reading 'href') at assets/resvg-gkFxLqVH.js:14881:64 <- dimmed frames under the at assets/resvg-gkFxLqVH.js:15409:3 argument that logged them [exception] frames print the same way scheduled jobs job fails ─> console.error('[void] Scheduled job crons/x.ts failed for cron "0 5 * * *":', error) (logged at once, with the original error, so its stack is kept) all jobs done ─> throw AggregateError(errors, 'Scheduled jobs failed: crons/x.ts') (HTTP 500 and the shared onError are unchanged) ``` Real output from this branch's CLI against the live napi-rs data: ``` 15:23:32 GET https://napi.rs/sponsors.svg 500 [error] TypeError: Cannot read properties of undefined (reading 'href') at assets/resvg-gkFxLqVH.js:14881:64 at assets/resvg-gkFxLqVH.js:15409:3 at new Promise (<anonymous>) at assets/resvg-gkFxLqVH.js:15408:19 at assets/client-7iHZB5sW.js:16:49 ``` ## Decisions | Question | Decision | Why | |---|---|---| | How does dispatch know the worker answered? | Reuse the asset-manifest answer it already reads for the static cache | No new KV read on the hot path | | New request type such as `worker`? | No, use `ssr` | The CLI, docs and usage queries already know `ssr` | | Fix cron errors in the shared Hono `onError`? | No, in the scheduled runner | `onError` serves every route; the runner knows the job file and cron | | Change the platform API or tail worker for stacks? | No, CLI only | The API already returns `errorInfo[].stack` and `exception.stack` | | `void platform deployment logs` (operator command) | Not changed | Outside the reported problem | ## Rollout ``` merge ─> release void ──> users upgrade the CLI ──────> stacks print (no redeploy needed) └──> apps redeploy ──────────────> cron errors named deploy hosted dispatch ─────────────────────────> new rows labeled ssr (old Analytics rows keep "static") ``` ## Known limits - Some app routes on paths with a file extension can still be labeled `static` when they succeed or return 4xx. This applies to requests with a Cookie or Authorization header, to HEAD, Range and POST requests, and to SSR apps that uploaded no static files. On framework deploys, these requests also stay `static` when they fail with a 5xx. A correct label would need an asset-manifest read on every credentialed asset request. That is too much cost for a display label. On Void SSR apps, server errors are labeled `ssr` for every request shape. - A failed cron now shows two log lines on the hosted path: the per-job line and the `AggregateError` line. - Framework cron runners and queue runners have the same error-loss pattern. They are not changed here. ## Testing | Check | Result | |---|---| | New tests on old code | fail (dispatch 7+, logs rendering 1, scheduled dispatch 2) | | Changed test files | 5 files, 353 tests pass | | `vp run test --base origin/main` | 475 files, 10329 tests pass | | `vp lint`, `vp run check` | pass (31 typecheck tasks) | | `vp test run` | 689 files pass. 1 file failed on a port race in the Solid dev-server test: the test waited on a port that `vp dev` found busy. It passes on rerun. The race is fixed in #396. | | Branch CLI against live napi-rs logs | frames print under every error | | `vp dev` fixture with one failing cron job | per-job line with file, cron, message and stack; the other job runs; HTTP 500 | 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
1 parent c9c512e commit 45461ba

12 files changed

Lines changed: 963 additions & 69 deletions

File tree

‎docs/reference/cli/project.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -138,7 +138,7 @@ void project logs --level error --range 12h
138138
void project logs --level error --filter websocket
139139
```
140140

141-
Logs include top-level `console.*` calls and uncaught errors captured by Cloudflare Tail. If you catch an error and save it only to your database, it won't appear here. Also log it with `console.error()` or `logger.error()` from `void/log`.
141+
Logs include top-level `console.*` calls and uncaught errors captured by Cloudflare Tail. If you catch an error and save it only to your database, it won't appear here. Also log it with `console.error()` or `logger.error()` from `void/log`. On hosted Void targets, pass the `Error` object itself to `console.error()`, as in `console.error('Save failed:', error)`, to see its stack trace under the log line. Logging only `error.message` shows no stack.
142142

143143
For errors that never reach your Worker, such as edge routing errors or static site requests, use `void project requests --status 5xx`.
144144

‎packages/deploy-core/src/index.ts‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,10 @@ export type RedirectRule = {
3636
export type AssetConfig = {
3737
not_found_handling?: 'none' | 'single-page-application' | '404-page';
3838
html_handling?: 'auto-trailing-slash' | 'force-trailing-slash' | 'drop-trailing-slash' | 'none';
39-
/** Native Cloudflare Workers Assets routing; ignored by managed dispatch. */
39+
/**
40+
* Native Cloudflare Workers Assets routing. Managed dispatch does not route
41+
* by it; it reads it only to tell whether the app's worker answered a request.
42+
*/
4043
run_worker_first?: boolean | Array<string>;
4144
};
4245

‎packages/void/src/cli/client.ts‎

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -353,8 +353,13 @@ export type SecretResponse = {
353353
export type LogEntry = {
354354
timestamp: number;
355355
outcome: string;
356-
logs: Array<{ level: string; message: Array<unknown>; timestamp: number }>;
357-
exceptions: Array<{ name: string; message: string; timestamp: number }>;
356+
logs: Array<{
357+
level: string;
358+
message: Array<unknown>;
359+
timestamp: number;
360+
errorInfo?: Array<{ name: string; message: string; stack?: string } | null>;
361+
}>;
362+
exceptions: Array<{ name: string; message: string; timestamp: number; stack?: string }>;
358363
url: string;
359364
method: string;
360365
status: string;

‎packages/void/src/cli/logs.ts‎

Lines changed: 25 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
import { outro, log, wrapTextWithPrefix } from '@voidzero-dev/vite-plus-prompts';
22
import { getToken } from './auth.ts';
33
import { PlatformClient, type LogEntry } from './client.ts';
4-
import { dim, formatCount, pc } from './output.ts';
4+
import { dim, errorStackFrames, formatCount, pc } from './output.ts';
55
import { readDeploymentPlatform, readProjectConfig } from './project.ts';
66
import { sanitizeTerminalLogText } from './terminal-log-text.ts';
77

@@ -109,7 +109,7 @@ function printEntry(entry: LogEntry): void {
109109
);
110110

111111
for (const l of entry.logs) {
112-
const text = sanitizeTerminalLogText(l.message.map(String).join(' '));
112+
const text = formatLogMessage(l);
113113
const level = l.level ?? 'log';
114114
const marker =
115115
level === 'error'
@@ -126,14 +126,36 @@ function printEntry(entry: LogEntry): void {
126126
console.log(
127127
wrapTextWithPrefix(
128128
process.stdout,
129-
sanitizeTerminalLogText(`${ex.name}: ${ex.message}`),
129+
[
130+
sanitizeTerminalLogText(`${ex.name}: ${ex.message}`),
131+
...errorStackFrames(ex).map((frame) => dim(sanitizeTerminalLogText(frame))),
132+
].join('\n'),
130133
' '.repeat(14),
131134
` ${pc.red('[exception]')} `,
132135
),
133136
);
134137
}
135138
}
136139

140+
/**
141+
* Join a console call's arguments; an argument that was an `Error` is followed
142+
* by its dimmed stack frames. Arguments and frames are app data, so each is
143+
* sanitized before the dim style is added.
144+
*/
145+
function formatLogMessage(log: LogEntry['logs'][number]): string {
146+
let text = '';
147+
let separator = '';
148+
for (const [index, value] of log.message.entries()) {
149+
text += `${separator}${sanitizeTerminalLogText(String(value))}`;
150+
const frames = errorStackFrames(log.errorInfo?.[index]);
151+
if (frames.length > 0) {
152+
text += `\n${frames.map((frame) => dim(sanitizeTerminalLogText(frame))).join('\n')}`;
153+
}
154+
separator = frames.length > 0 ? '\n' : ' ';
155+
}
156+
return text;
157+
}
158+
137159
function formatTime(ts: number): string {
138160
const d = new Date(ts);
139161
return d.toLocaleTimeString('en-GB', { hour12: false });

‎packages/void/src/cli/output.ts‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -152,3 +152,26 @@ export function ensureUtc(s: string): string {
152152
}
153153
return s + 'Z';
154154
}
155+
156+
/**
157+
* Stack frames of an error a Worker reported, one line per frame. The log or
158+
* exception line already shows `Name: message`, so a leading copy of that
159+
* header is dropped; Workers send stacks both with and without it.
160+
*/
161+
export function errorStackFrames(error: unknown): Array<string> {
162+
if (!error || typeof error !== 'object') {
163+
return [];
164+
}
165+
const { name, message, stack } = error as { name?: unknown; message?: unknown; stack?: unknown };
166+
if (typeof stack !== 'string') {
167+
return [];
168+
}
169+
const header = message ? `${String(name)}: ${String(message)}` : String(name);
170+
const frames =
171+
stack === header
172+
? ''
173+
: stack.startsWith(`${header}\n`)
174+
? stack.slice(header.length + 1)
175+
: stack;
176+
return frames.trimEnd() ? frames.trimEnd().split('\n') : [];
177+
}

‎packages/void/src/router/compile.ts‎

Lines changed: 23 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
import { fileURLToPath } from 'node:url';
2+
import { relative } from 'pathslash';
23
import type { VoidAuthProvider } from '../auth/providers.ts';
34
import type { DevRedirectRule, HeaderRule } from '../cli/types.ts';
45
import type { NotFoundHandling } from '../config.ts';
@@ -478,25 +479,38 @@ export function compileRouteTable(
478479
lines.push(`const job${i}Crons = ${JSON.stringify(job.crons)};`);
479480
}
480481
lines.push('');
482+
// Workers log capture keeps only an error's own name, message and stack (not
483+
// AggregateError.errors or cause), so each job logs its own error, with the job file
484+
// and cron, as soon as it fails.
481485
lines.push('export async function scheduled(controller, env, ctx) {');
486+
lines.push(' const run = async (job, loadJob) => {');
487+
lines.push(' try {');
488+
lines.push(' const mod = await loadJob();');
489+
lines.push(
490+
" if (typeof mod.default === 'function') await mod.default(controller, env, ctx);",
491+
);
492+
lines.push(' } catch (error) {');
493+
lines.push(
494+
' console.error(`[void] Scheduled job ${job} failed for cron "${controller.cron}":`, error);',
495+
);
496+
lines.push(' return { job, error };');
497+
lines.push(' }');
498+
lines.push(' };');
482499
lines.push(' const tasks = [];');
483500
for (let i = 0; i < scan.jobs.length; i++) {
484501
const job = scan.jobs[i];
485502
const filePath = JSON.stringify(`${jobsDir}/${job.filePath}`);
486-
lines.push(` if (job${i}Crons.includes(controller.cron)) {`);
487-
lines.push(' tasks.push((async () => {');
488-
lines.push(` const mod = await import(${filePath});`);
503+
const label = JSON.stringify(relative(options.projectRoot, `${jobsDir}/${job.filePath}`));
489504
lines.push(
490-
" if (typeof mod.default === 'function') await mod.default(controller, env, ctx);",
505+
` if (job${i}Crons.includes(controller.cron)) tasks.push(run(${label}, () => import(${filePath})));`,
491506
);
492-
lines.push(' })());');
493-
lines.push(' }');
494507
}
495-
lines.push(' const results = await Promise.allSettled(tasks);');
508+
lines.push(' const failures = (await Promise.all(tasks)).filter(Boolean);');
509+
lines.push(' if (failures.length) {');
496510
lines.push(
497-
' const errors = results.filter(result => result.status === "rejected").map(result => result.reason);',
511+
' throw new AggregateError(failures.map((failure) => failure.error), `Scheduled jobs failed: ${failures.map((failure) => failure.job).join(", ")}`);',
498512
);
499-
lines.push(' if (errors.length) throw new AggregateError(errors, "Scheduled jobs failed");');
513+
lines.push(' }');
500514
lines.push('}');
501515
lines.push('');
502516
} else {

‎packages/void/test/unit/logs-rendering.test.ts‎

Lines changed: 142 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -197,3 +197,145 @@ it('keeps color codes, newlines and tabs, and removes other escape sequences who
197197
expect(sanitizeTerminalLogText('\u009b2J\u0085\u007f\u0000\u0008end')).toBe('2Jend');
198198
expect(sanitizeTerminalLogText('plain text, ünïcode ✓')).toBe('plain text, ünïcode ✓');
199199
});
200+
201+
it('prints stack frames under the error that logged them', async () => {
202+
logsFixture.entries = [
203+
{
204+
timestamp: 0,
205+
method: 'GET',
206+
url: '/sponsors.svg',
207+
status: '500',
208+
outcome: 'ok',
209+
logs: [
210+
{
211+
level: 'error',
212+
message: ["TypeError: Cannot read properties of undefined (reading 'href')"],
213+
errorInfo: [
214+
{
215+
name: 'TypeError',
216+
message: "Cannot read properties of undefined (reading 'href')",
217+
stack: ' at assets/resvg.js:14881:64\n at assets/resvg.js:15409:3',
218+
},
219+
],
220+
},
221+
{
222+
level: 'error',
223+
message: ['Render failed:', 'Error: font missing', 'retrying'],
224+
errorInfo: [
225+
null,
226+
{
227+
name: 'Error',
228+
message: 'font missing',
229+
stack: 'Error: font missing\n at render (index.js:10:5)',
230+
},
231+
null,
232+
],
233+
},
234+
{
235+
level: 'error',
236+
message: ['Error'],
237+
errorInfo: [{ name: 'Error', message: '', stack: 'Error\n at g (y.js:2:2)' }],
238+
},
239+
{
240+
level: 'warn',
241+
message: ['Error: retry later'],
242+
errorInfo: [{ name: 'Error', message: 'retry later' }],
243+
},
244+
],
245+
exceptions: [
246+
{
247+
name: 'Error',
248+
message: 'Worker threw',
249+
stack: 'Error: Worker threw\n at fetch (index.js:1:1)',
250+
},
251+
{ name: 'Error', message: 'boom', stack: 'Error: boom' },
252+
{ name: 'Error', message: 'Worker exceeded CPU time limit.' },
253+
],
254+
},
255+
];
256+
const output = Object.assign(
257+
new Writable({
258+
write(_chunk, _encoding, callback) {
259+
callback();
260+
},
261+
}),
262+
{ columns: 120 },
263+
);
264+
vi.spyOn(process, 'stdout', 'get').mockReturnValue(output as typeof process.stdout);
265+
const print = vi.spyOn(console, 'log').mockImplementation(() => {});
266+
await runLogsCommand('/fixture', '', '1h');
267+
const messages = print.mock.calls.map((args) => String(args[0] ?? ''));
268+
const header = messages.findIndex((line) => line.includes('/sponsors.svg'));
269+
expect(header).toBeGreaterThanOrEqual(0);
270+
expect(
271+
messages.slice(header + 1).flatMap((message) => stripVTControlCharacters(message).split('\n')),
272+
).toEqual([
273+
" [error] TypeError: Cannot read properties of undefined (reading 'href')",
274+
' at assets/resvg.js:14881:64',
275+
' at assets/resvg.js:15409:3',
276+
' [error] Render failed: Error: font missing',
277+
' at render (index.js:10:5)',
278+
' retrying',
279+
' [error] Error',
280+
' at g (y.js:2:2)',
281+
' [warn] Error: retry later',
282+
' [exception] Error: Worker threw',
283+
' at fetch (index.js:1:1)',
284+
' [exception] Error: boom',
285+
' [exception] Error: Worker exceeded CPU time limit.',
286+
]);
287+
expect(messages.join('\n')).toContain('\x1b[2m at assets/resvg.js:14881:64');
288+
});
289+
290+
it('drops terminal control sequences from stack frames', async () => {
291+
logsFixture.entries = [
292+
{
293+
timestamp: 0,
294+
method: 'GET',
295+
url: '/sponsors.svg',
296+
status: '500',
297+
outcome: 'exception',
298+
logs: [
299+
{
300+
level: 'error',
301+
message: ['Error: boom'],
302+
errorInfo: [
303+
{
304+
name: 'Error',
305+
message: 'boom',
306+
stack: 'Error: boom\n at \x1b]52;c;ZXZpbA==\x07f (a.js:1:1)\x1b[2J\r',
307+
},
308+
],
309+
},
310+
],
311+
exceptions: [
312+
{
313+
name: 'Error',
314+
message: 'x',
315+
stack:
316+
'Error: x\n at \x1b]8;;https://evil.example\x07g\x1b]8;;\x07 (b.js:2:2)\u009b2J',
317+
},
318+
],
319+
},
320+
];
321+
const output = Object.assign(
322+
new Writable({
323+
write(_chunk, _encoding, callback) {
324+
callback();
325+
},
326+
}),
327+
{ columns: 120 },
328+
);
329+
vi.spyOn(process, 'stdout', 'get').mockReturnValue(output as typeof process.stdout);
330+
const print = vi.spyOn(console, 'log').mockImplementation(() => {});
331+
await runLogsCommand('/fixture', '', '1h');
332+
333+
const printed = print.mock.calls.map((args) => String(args[0] ?? '')).join('\n');
334+
for (const unsafe of ['\x1b]', '\x1b[2J', '\r', '\x07', '\u009b']) {
335+
expect(printed).not.toContain(unsafe);
336+
}
337+
expect(printed).not.toContain('evil.example');
338+
const plain = stripVTControlCharacters(printed);
339+
expect(plain).toContain(' at f (a.js:1:1)');
340+
expect(plain).toContain(' at g (b.js:2:2)2J');
341+
});

0 commit comments

Comments
 (0)