[cli][node][node-bridge] improve edge/serverless function error messages (#9410)

The error messages shown during `vc dev` when an Edge or Serverless functions returns a promise that ends up being rejected could be better.

Main changes:

- removed "socket hang up" error messages because they were not helpful to the user
- changed serverless function error handling to log explicitly and exit
- changed serverless function error message to include the request path
- changed edge function error message to include request path and a faked (but useful) stack trace

## Current

### In Production

**Serverless Function:** In production, for a serverless function rejected promise, you'll see this in the logs:

```
Unhandled Promise Rejection 	{
  "errorType": "Runtime.UnhandledPromiseRejection",
  "errorMessage": "Error: intentional break!",
  "reason": {
    "errorType": "Error",
    "errorMessage": "intentional break!",
    "stack": [
      "Error: intentional break!",
      "    at handler (/var/task/api/node.js:3:9)",
      "    at Server.<anonymous> (/var/task/___vc/__helpers.js:813:19)",
      "    at Server.emit (node:events:527:28)",
      "    at parserOnIncoming (node:_http_server:956:12)",
      "    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)"
    ]
  },
  "promise": {},
  "stack": [
    "Runtime.UnhandledPromiseRejection: Error: intentional break!",
    "    at process.<anonymous> (file:///var/runtime/index.mjs:1194:17)",
    "    at process.emit (node:events:539:35)",
    "    at process.emit (/var/task/___vc/__sourcemap_support.js:559:21)",
    "    at emit (node:internal/process/promises:140:20)",
    "    at processPromiseRejections (node:internal/process/promises:274:27)",
    "    at processTicksAndRejections (node:internal/process/task_queues:97:32)"
  ]
}
Unknown application error occurred
Runtime.Unknown
```

**Edge Function:** In production, for an edge function rejected promise, you'll see this in the logs:

```
Error: intentional break!
    at (api/edge.js:10:10)
```

In both cases, in the browser, you see the "This Serverless/Edge Function has crashed." template with no error message or stack trace.


### In `vc dev`


**Serverless Function:** In `vc dev`, for a serverless function rejected promise, you'll see this in the output:

```
Unhandled rejection: Error: intentional break!
    at handler (/Users/smassa/source/demo/edge-errors/api/node.js:3:9)
    at Server.<anonymous> (/Users/smassa/source/vercel/vercel/packages/node-bridge/helpers.js:813:19)
    at Server.emit (node:events:513:28)
    at Server.emit (node:domain:489:12)
    at parserOnIncoming (node:_http_server:998:12)
    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)
Error: Failed to complete request to /api/node: Error: socket hang up
```

**Edge Function:** In `vc dev`, for an edge function rejected promise, you'll see this in the output:

```
Unhandled rejection: intentional break!
Error: Failed to complete request to /api/edge: Error: socket hang up
```

## After Changes

### In `vc dev`


**Serverless Function:** In `vc dev`, for a serverless function rejected promise, you'll see this in the output:

```
Rejected Promise returned from /api/node: Error: intentional break!
    at handler (/Users/smassa/source/demo/edge-errors/api/node.js:3:9)
    at Server.<anonymous> (/Users/smassa/source/vercel/vercel/packages/node-bridge/helpers.js:824:19)
    at Server.emit (node:events:513:28)
    at Server.emit (node:domain:489:12)
    at parserOnIncoming (node:_http_server:998:12)
    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)
```

**Edge Function:** In `vc dev`, for an edge function rejected promise, you'll see this in the output:

```
Rejected Promise returned from api/edge: intentional break!
    at (api/edge.ts)
```

We can't show the real stack trace for Edge Functions because the bundling + VM execution mangles it. What's rendered here is a fake one, but it's still useful to the user.

If we currently showed the real stack trace for edge functions, it would look like:

```
Rejected Promise returned from api/edge: intentional break!
    at edge (evalmachine.<anonymous>:35:9)
    at FetchEvent.<anonymous> (evalmachine.<anonymous>:87:26)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async EdgeRuntime.dispatchFetch (evalmachine.<anonymous>:29:7)
    at async Server.handler (/Users/smassa/source/vercel/vercel/node_modules/.pnpm/edge-runtime@2.0.0/node_modules/edge-runtime/src/server/create-handler.ts:46:26)
```

## Follow Up

We'll look into improving the Edge Function error stack traces later.
This commit is contained in:
Sean Massa
2023-02-10 18:14:58 -06:00
committed by GitHub
parent 084125d90f
commit d628880942
4 changed files with 44 additions and 43 deletions

View File

@@ -2307,7 +2307,10 @@ function proxyPass(
res, res,
{ target: dest, ignorePath }, { target: dest, ignorePath },
(error: NodeJS.ErrnoException) => { (error: NodeJS.ErrnoException) => {
devServer.output.error( // only debug output this error because it's always something generic like
// "Error: socket hang up"
// and the original error should have already been logged
devServer.output.debug(
`Failed to complete request to ${req.url}: ${error}` `Failed to complete request to ${req.url}: ${error}`
); );
if (!res.headersSent) { if (!res.headersSent) {

View File

@@ -100,15 +100,12 @@ test('[vercel dev] throws an error when an edge function has no response', async
let res = await fetch(`http://localhost:${port}/api/edge-no-response`); let res = await fetch(`http://localhost:${port}/api/edge-no-response`);
validateResponseHeaders(res); validateResponseHeaders(res);
const { stdout, stderr } = await dev.kill(); const { stdout } = await dev.kill();
expect(await res.status).toBe(500); expect(await res.status).toBe(500);
expect(await res.text()).toMatch('FUNCTION_INVOCATION_FAILED'); expect(await res.text()).toMatch('FUNCTION_INVOCATION_FAILED');
expect(stdout).toMatch( expect(stdout).toMatch(
/Unhandled rejection: Edge Function "api\/edge-no-response.js" did not return a response./g /Error from API Route api\/edge-no-response: Edge Function "api\/edge-no-response.js" did not return a response./g
);
expect(stderr).toMatch(
/Failed to complete request to \/api\/edge-no-response: Error: socket hang up/g
); );
} finally { } finally {
await dev.kill(); await dev.kill();
@@ -158,14 +155,13 @@ test('[vercel dev] should handle runtime errors thrown in edge functions', async
}); });
validateResponseHeaders(res); validateResponseHeaders(res);
const { stdout, stderr } = await dev.kill(); const { stdout } = await dev.kill();
expect(await res.text()).toMatch( expect(await res.text()).toMatch(
/<strong>500<\/strong>: INTERNAL_SERVER_ERROR/g /<strong>500<\/strong>: INTERNAL_SERVER_ERROR/g
); );
expect(stdout).toMatch(/Unhandled rejection: intentional runtime error/g); expect(stdout).toMatch(
expect(stderr).toMatch( /Error from API Route api\/edge-error-runtime: intentional runtime error/g
/Failed to complete request to \/api\/edge-error-runtime: Error: socket hang up/g
); );
} finally { } finally {
await dev.kill(); await dev.kill();
@@ -196,9 +192,6 @@ test('[vercel dev] should handle config errors thrown in edge functions', async
expect(stderr).toMatch( expect(stderr).toMatch(
/Invalid function runtime "invalid-runtime-value" for "api\/edge-error-config.js". Valid runtimes are: \["edge","experimental-edge"\]/g /Invalid function runtime "invalid-runtime-value" for "api\/edge-error-config.js". Valid runtimes are: \["edge","experimental-edge"\]/g
); );
expect(stderr).toMatch(
/Failed to complete request to \/api\/edge-error-config: Error: socket hang up/g
);
} finally { } finally {
await dev.kill(); await dev.kill();
} }
@@ -227,9 +220,6 @@ test('[vercel dev] should handle startup errors thrown in edge functions', async
); );
expect(stderr).toMatch(/Failed to instantiate edge runtime./g); expect(stderr).toMatch(/Failed to instantiate edge runtime./g);
expect(stderr).toMatch(/intentional startup error/g); expect(stderr).toMatch(/intentional startup error/g);
expect(stderr).toMatch(
/Failed to complete request to \/api\/edge-error-startup: Error: socket hang up/g
);
} finally { } finally {
await dev.kill(); await dev.kill();
} }
@@ -258,9 +248,6 @@ test('[vercel dev] should handle syntax errors thrown in edge functions', async
); );
expect(stderr).toMatch(/Failed to compile user code for edge runtime./g); expect(stderr).toMatch(/Failed to compile user code for edge runtime./g);
expect(stderr).toMatch(/Unexpected end of file/g); expect(stderr).toMatch(/Unexpected end of file/g);
expect(stderr).toMatch(
/Failed to complete request to \/api\/edge-error-syntax: Error: socket hang up/g
);
} finally { } finally {
await dev.kill(); await dev.kill();
} }
@@ -293,9 +280,6 @@ test('[vercel dev] should handle import errors thrown in edge functions', async
expect(stderr).toMatch( expect(stderr).toMatch(
/Could not resolve "unknown-module-893427589372458934795843"/g /Could not resolve "unknown-module-893427589372458934795843"/g
); );
expect(stderr).toMatch(
/Failed to complete request to \/api\/edge-error-unknown-import: Error: socket hang up/g
);
} finally { } finally {
await dev.kill(); await dev.kill();
} }
@@ -320,7 +304,7 @@ test('[vercel dev] should handle missing handler errors thrown in edge functions
); );
validateResponseHeaders(res); validateResponseHeaders(res);
const { stdout, stderr } = await dev.kill(); const { stdout } = await dev.kill();
expect(await res.text()).toMatch( expect(await res.text()).toMatch(
/<strong>500<\/strong>: INTERNAL_SERVER_ERROR/g /<strong>500<\/strong>: INTERNAL_SERVER_ERROR/g
@@ -328,9 +312,6 @@ test('[vercel dev] should handle missing handler errors thrown in edge functions
expect(stdout).toMatch( expect(stdout).toMatch(
/No default export was found. Add a default export to handle requests./g /No default export was found. Add a default export to handle requests./g
); );
expect(stderr).toMatch(
/Failed to complete request to \/api\/edge-error-no-handler: Error: socket hang up/g
);
} finally { } finally {
await dev.kill(); await dev.kill();
} }

View File

@@ -295,13 +295,15 @@ export function createServerWithHelpers(
res.send = body => send(req, res, body); res.send = body => send(req, res, body);
res.json = jsonBody => json(req, res, jsonBody); res.json = jsonBody => json(req, res, jsonBody);
try {
await handler(req, res); await handler(req, res);
} catch (err) { } catch (err) {
if (err instanceof ApiError) { console.log(`Error from API Route ${req.url}: ${err.stack}`);
sendError(res, err.statusCode, err.message); process.exit(1);
} else {
throw err;
} }
} catch (err) {
console.log(`Error while handling ${req.url}: ${err.message}`);
process.exit(1);
} }
}); });

View File

@@ -34,8 +34,8 @@ async function serializeRequest(message: IncomingMessage) {
} }
async function compileUserCode( async function compileUserCode(
entrypointPath: string, entrypointFullPath: string,
entrypointLabel: string, entrypointRelativePath: string,
isMiddleware: boolean isMiddleware: boolean
): Promise<undefined | { userCode: string; wasmAssets: WasmAssets }> { ): Promise<undefined | { userCode: string; wasmAssets: WasmAssets }> {
const { wasmAssets, plugin: edgeWasmPlugin } = createEdgeWasmPlugin(); const { wasmAssets, plugin: edgeWasmPlugin } = createEdgeWasmPlugin();
@@ -51,7 +51,7 @@ async function compileUserCode(
legalComments: 'none', legalComments: 'none',
bundle: true, bundle: true,
plugins: [edgeWasmPlugin], plugins: [edgeWasmPlugin],
entryPoints: [entrypointPath], entryPoints: [entrypointFullPath],
write: false, // operate in memory write: false, // operate in memory
format: 'cjs', format: 'cjs',
}); });
@@ -59,7 +59,7 @@ async function compileUserCode(
const compiledFile = result.outputFiles?.[0]; const compiledFile = result.outputFiles?.[0];
if (!compiledFile) { if (!compiledFile) {
throw new Error( throw new Error(
`Compilation of ${entrypointLabel} produced no output files.` `Compilation of ${entrypointRelativePath} produced no output files.`
); );
} }
@@ -72,7 +72,7 @@ async function compileUserCode(
// request metadata // request metadata
const IS_MIDDLEWARE = ${isMiddleware}; const IS_MIDDLEWARE = ${isMiddleware};
const ENTRYPOINT_LABEL = '${entrypointLabel}'; const ENTRYPOINT_LABEL = '${entrypointRelativePath}';
// edge handler // edge handler
${edgeHandlerTemplate} ${edgeHandlerTemplate}
@@ -134,13 +134,13 @@ async function createEdgeRuntime(params?: {
} }
export async function createEdgeEventHandler( export async function createEdgeEventHandler(
entrypointPath: string, entrypointFullPath: string,
entrypointLabel: string, entrypointRelativePath: string,
isMiddleware: boolean isMiddleware: boolean
): Promise<(request: IncomingMessage) => Promise<VercelProxyResponse>> { ): Promise<(request: IncomingMessage) => Promise<VercelProxyResponse>> {
const userCode = await compileUserCode( const userCode = await compileUserCode(
entrypointPath, entrypointFullPath,
entrypointLabel, entrypointRelativePath,
isMiddleware isMiddleware
); );
const server = await createEdgeRuntime(userCode); const server = await createEdgeRuntime(userCode);
@@ -164,8 +164,13 @@ export async function createEdgeEventHandler(
const isUserError = const isUserError =
response.headers.get('x-vercel-failed') === 'edge-wrapper'; response.headers.get('x-vercel-failed') === 'edge-wrapper';
if (isUserError && response.status >= 500) { if (isUserError && response.status >= 500) {
// this error was "unhandled" from the user code's perspective // We can't currently get a real stack trace from the Edge Function error,
console.log(`Unhandled rejection: ${body}`); // but we can fake a basic one that is still usefult to the user.
const fakeStackTrace = ` at (${entrypointRelativePath})`;
const urlPath = extractUrlPath(entrypointRelativePath);
console.log(
`Error from API Route ${urlPath}: ${body}\n${fakeStackTrace}`
);
// this matches the serverless function bridge launcher's behavior when // this matches the serverless function bridge launcher's behavior when
// an error is thrown in the function // an error is thrown in the function
@@ -180,3 +185,13 @@ export async function createEdgeEventHandler(
}; };
}; };
} }
// turns "api/some.func.js" into "api/some.func"
function extractUrlPath(entrypointRelativePath: string) {
const parts = entrypointRelativePath.split('.');
if (parts.length === 1) {
return entrypointRelativePath;
}
parts.pop();
return parts.join('.');
}