[wrangler] Log `Error#cause` and `DOMException` reasons when running `wrangler dev` #2851

mrbbot · 2023-03-03T18:09:54Z

What this PR solves:

Previously, the cause property of errors was ignored when logging. This is used by D1 to include context on why an operation failed. Because we weren't logging this, D1 failures would always show up as D1_ERROR, with no additional context, making debugging difficult.

This change attempts to extract cause from the object preview sent back from the inspector with the rest of exception details. Unfortunately, the stack trace we get back is an unstructured string, so we need to parse it into an array of call sites before we can source-map. The stack trace may be truncated as this is only a preview. In this case, we just log the truncation. We could send a request to the inspector to get the full stack in this case if we
wanted. Additionally, the cause is sometimes not returned on the first request. This is the same bug that causes objects entries not to be displayed when console.logging on first request too.

DOMExceptions are special, the actually useful stack trace is hidden behind the stack getter, and not included in the preview. DOMExceptions are quite common (e.g. invalid base64 in atob(), invalid algorithm name when using WebCrypto, ...). Currently, these errors are just logged as DOMException, which isn't helpful for debugging. With this change, the actual reason is logged, along with the source-mapped location. Note this requires us sending requests to the inspector, and waiting for the response. To avoid ID collisions with DevTools frontend's own RPC requests, we use negative integer IDs, which are allowed by workerd.

How to test:

Run wrangler dev worker.js with the following:

export default {
  async fetch(request, env, ctx) {
    throw new Error("thing", {
      cause: new TypeError("cause"),
    });
  },
};

Visit the Worker in your browser and look at the console. You may need to refresh the page again, but you should see the cause. Replace the fetch handler body with some other examples that throw DOMExceptions, e.g. atob("🙃"); or await crypto.subtle.digest("🇲🇩5", new Uint8Array());.

Best reviewed commit-by-commit (see commit descriptions for more details). 🙂

Associated docs issues/PR:

N/A

Author has included the following, where applicable:

Tests
Changeset

Reviewer has performed the following, where applicable:

Checked for inclusion of relevant tests
Checked for inclusion of a relevant changeset
Checked for creation of associated docs updates
Manually pulled down the changes and spot-tested

changeset-bot · 2023-03-03T18:09:57Z

🦋 Changeset detected

Latest commit: fac6553

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 1 package

Name	Type
wrangler	Minor

Not sure what this means? Click here to learn what changesets are.

Click here if you're a maintainer who wants to add another changeset to this PR

github-actions · 2023-03-03T18:12:21Z

A wrangler prerelease is available for testing. You can install this latest build in your project with:

npm install --save-dev https://prerelease-registry.devprod.cloudflare.dev/workers-sdk/runs/4608360297/npm-package-wrangler-2851

You can reference the automatically updated head of this PR with:

npm install --save-dev https://prerelease-registry.devprod.cloudflare.dev/workers-sdk/prs/2851/npm-package-wrangler-2851

Or you can use npx with this latest build directly:

npx https://prerelease-registry.devprod.cloudflare.dev/workers-sdk/runs/4608360297/npm-package-wrangler-2851 dev path/to/script.js

Additional artifacts:

npm install https://prerelease-registry.devprod.cloudflare.dev/workers-sdk/runs/4608360297/npm-package-cloudflare-pages-shared-2851

Note that these links will no longer work once the GitHub Actions artifact expires.

packages/wrangler/src/callsite.ts

JacobMGEvans · 2023-03-03T18:15:23Z

Best reviewed commit-by-commit (see commit descriptions for more details). 🙂

This is appreciated for something like this 😄

codecov · 2023-03-03T18:19:18Z

Codecov Report

Merging #2851 (fac6553) into main (e311bbb) will decrease coverage by 0.61%.
The diff coverage is 4.65%.

@@            Coverage Diff             @@
##             main    #2851      +/-   ##
==========================================
- Coverage   73.57%   72.96%   -0.61%     
==========================================
  Files         167      167              
  Lines       10504    10597      +93     
  Branches     2807     2849      +42     
==========================================
+ Hits         7728     7732       +4     
- Misses       2776     2865      +89

Impacted Files	Coverage Δ
packages/wrangler/src/inspect.ts	`4.25% <0.81%> (-1.05%)`	⬇️
packages/wrangler/src/bundle.ts	`93.15% <83.33%> (ø)`

... and 2 files with indirect coverage changes

packages/wrangler/src/inspect.ts

JacobMGEvans · 2023-03-03T18:33:26Z

packages/wrangler/src/inspect.ts

@@ -289,9 +314,9 @@ export default function useInspector(props: InspectorProps) {
 		// each time. Consumers must be destroyed when no longer needed, so create
 		// an abort controller aborted to signal destruction.
 		const sourceMapAbortController = new AbortController();
-		let sourceMapConsumerPromise: Promise<SourceMapConsumer | undefined>;
+		let _sourceMapConsumerPromise: Promise<SourceMapConsumer | undefined>;


Are we commonly using the _privateVar pattern elsewhere? Just want to make sure we are not ad hoc introducing a convention.

We aren't. I wanted to make it clear that _sourceMapConsumerPromise shouldn't be used directly, but happy to change it back if you don't want to introduce this convention.

What is the reason for the concern of it being used directly? Is it exposed outside of inspect.ts or you are concerned someone will use it locally in the inspect.ts without the getter?

Could it be moved inside of the getSourceMapConsumer function before the return, making it part of a closure so its more encapsulated and perhaps the naming convention wont be necessary?

I'm concerned about accidental use within inspect.ts without the getter.

Could it be moved inside of the getSourceMapConsumer function before the return, making it part of a closure so its more encapsulated and perhaps the naming convention wont be necessary?

Not quite. Moving it inside getSourceMapConsumer would lead to something like...

function getConsumer() { let consumer; return consumer ??= (async () => { .. }); } const consumer = await getConsumer();

consumer would always be undefined when we called the function, so we'd lose laziness. We could do something like...

function getConsumerGetter() { let consumer; return () => { return consumer ??= (async () => { .. }); } } const getter = getConsumerGetter(); const consumer = getter();

...but that seems like too many functions. 😅

packages/wrangler/src/inspect.ts

mrbbot · 2023-03-06T10:25:24Z

Thanks @JacobMGEvans for the review! Had a bit more of a think about this, and I'm going to change this so we always log the full-cause if it's truncated. An error with a truncated stack trace would be really annoying, and wouldn't be source-mapped either. Will unmark as draft when ready.

mrbbot · 2023-03-06T12:15:31Z

Ok, this should be ready now. We now always fetch the un-truncated cause property. Rather than seeing [ERROR] Cause: Error: Error: ERROR 9009: SQL prepare error: near "SEL222ECT": ... you now see:

✘ [ERROR] Cause: Error: Error: ERROR 9009: SQL prepare error: near "SEL222ECT": syntax error in SEL222ECT * FROM kitchen_sink WHERE id = 1; SELECT * FROM kitchen_sink WHERE id = 1; at offset 0

  cause: new Error(e.cause || "Something went wrong"),
         ^
      at D1Database._send (/Users/.../packages/wrangler/templates/d1-beta-facade.js:101:12)
      at async D1PreparedStatement.all (/Users/.../packages/wrangler/templates/d1-beta-facade.js:174:4)
      at async Object.fetch (/Users/.../wrangler-miniflare3-test/d1.ts:78:18)

I've also fixed a bug with source-mapping in facades. 👍

Previously, we were reading and parsing source-maps every time we received an error from a Worker to log. Parsing source-maps can be quite expensive, so this change lifts this out into a memoised `Promise`, that gets reset whenever the script changes. Note, when a user sees an error in dev, it's quick likely they'll edit their script to fix it, so this isn't too much of a problem at the moment. We're going to add `cause` support now though, which may require source-mapping multiple errors in quick succession.

We'll need to apply source-mapping to causes too, and having this in a reusable function will make this easier.

Previously, the `cause` property of errors was ignored when logging. This is used by D1 to include context on why an operation failed. Because we weren't logging this, D1 failures would always show up as `D1_ERROR`, with no additional context, making debugging difficult. This change attempts to extract `cause` from the object preview sent back from the inspector with the rest of exception details. Unfortunately, the stack trace we get back is an unstructured string, so we need to parse it into an array of call sites before we can source-map. The stack trace may be truncated as this is only a preview. In this case, we just log the truncation. We could send a request to the inspector to get the full stack in this case if we wanted. Additionally, the cause is sometimes not returned on the first request. This is the same bug that causes objects entries not to be displayed when `console.log`ging on first request too.

`DOMException`s are special, the actually useful stack trace is hidden behind the `stack` getter, and not included in the preview. `DOMException`s are quite common (e.g. invalid base64 in `atob()`, invalid algorithm name when using WebCrypto, ...). Currently, these errors are just logged as `DOMException`, which isn't helpful for debugging. With this change, the actual reason is logged, along with the source-mapped location.

Always fetch un-truncated `cause` property

When applying facades, we write intermediate files to a temporary directory and then build them with `esbuild`. This outputs intermediate source maps, which get merged in the final bundle step to produce a final source map. On macOS, `os.tmpdir()` looks like `/var/folders/.../.../T`. `/var` is a symlink to `/private/var`. Unfortunately, source maps end up assuming files in `/var`, not `/private/var`, leading to invalid stack traces like `/private/Users/.../d1-beta-facade.js:101:12`. This change uses `realpathSync` to fully-resolve all symlinks before we pass paths containing the temporary directory to `esbuild` for source map generation. We actually implemented this same change in #2249 for the middleware loader facade, but not the rest.

rozenmd · 2023-04-25T11:24:46Z

packages/wrangler/src/inspect.ts

+							const causeDescriptor = getPropertiesResponse?.result.find(
+								(prop) => prop.name === "cause"
+							);
+							const cause = causeDescriptor?.value;


AFAICT the spec for Error.cause doesn't define a structure for the cause property - where'scause.description and cause.value etc coming from?

cause isn't actually the Error.cause, but rather a DevTools protocol Runtime.RemoteObject representing it. causeDescriptor is a Runtime.PropertyDescriptor.

elithrar · 2023-06-16T13:15:13Z

Relevant: cloudflare/cloudflare-docs#9298

RamIdeas · 2023-10-30T15:21:05Z

@mrbbot is this PR still relevant? Can you close it if not?

mrbbot · 2023-10-30T15:29:54Z

@RamIdeas This will have been fixed in local mode by cloudflare/workerd#1294. It will still be an issue in remote mode though, so will probably want to fix it there.

petebacondarwin · 2024-01-05T15:25:08Z

This PR is old and stale. The fix is no longer relevant for local dev, and we are tending to move people away from remote mode dev. So I am going to close this for now. We can reopen, rebase and retarget to remote mode dev if we have capacity in the future.

mrbbot requested a review from a team as a code owner March 3, 2023 18:09

mrbbot commented Mar 3, 2023

View reviewed changes

packages/wrangler/src/callsite.ts Outdated Show resolved Hide resolved

JacobMGEvans reviewed Mar 3, 2023

View reviewed changes

packages/wrangler/src/inspect.ts Outdated Show resolved Hide resolved

JacobMGEvans reviewed Mar 3, 2023

View reviewed changes

mrbbot marked this pull request as draft March 6, 2023 10:23

mrbbot marked this pull request as ready for review March 6, 2023 12:13

mrbbot added 9 commits April 4, 2023 14:27

Lift out source-mapping to function

f77d821

We'll need to apply source-mapping to causes too, and having this in a reusable function will make this easier.

Add changeset

a04c545

fixup! Log Error#cause in dev

7e43a21

Always fetch un-truncated `cause` property

Rename consumer back to sourceMapConsumer

3a6f17c

Remove vendored stack-trace package

fac6553

mrbbot force-pushed the bcoll/log-error-cause branch from 45c48c8 to fac6553 Compare April 4, 2023 13:31

rozenmd reviewed Apr 25, 2023

View reviewed changes

petebacondarwin closed this Jan 5, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[wrangler] Log `Error#cause` and `DOMException` reasons when running `wrangler dev` #2851

[wrangler] Log `Error#cause` and `DOMException` reasons when running `wrangler dev` #2851

mrbbot commented Mar 3, 2023 •

edited

Loading

changeset-bot bot commented Mar 3, 2023 •

edited

Loading

github-actions bot commented Mar 3, 2023 •

edited

Loading

JacobMGEvans commented Mar 3, 2023

codecov bot commented Mar 3, 2023 •

edited

Loading

JacobMGEvans Mar 3, 2023

mrbbot Mar 6, 2023

JacobMGEvans Mar 7, 2023 •

edited

Loading

mrbbot Mar 7, 2023 •

edited

Loading

mrbbot commented Mar 6, 2023 •

edited

Loading

mrbbot commented Mar 6, 2023

rozenmd Apr 25, 2023

mrbbot Apr 25, 2023

elithrar commented Jun 16, 2023

RamIdeas commented Oct 30, 2023

mrbbot commented Oct 30, 2023

petebacondarwin commented Jan 5, 2024

[wrangler] Log Error#cause and DOMException reasons when running wrangler dev #2851

[wrangler] Log Error#cause and DOMException reasons when running wrangler dev #2851

Conversation

mrbbot commented Mar 3, 2023 • edited Loading

What this PR solves:

How to test:

Associated docs issues/PR:

Author has included the following, where applicable:

Reviewer has performed the following, where applicable:

changeset-bot bot commented Mar 3, 2023 • edited Loading

🦋 Changeset detected

github-actions bot commented Mar 3, 2023 • edited Loading

JacobMGEvans commented Mar 3, 2023

codecov bot commented Mar 3, 2023 • edited Loading

Codecov Report

JacobMGEvans Mar 3, 2023

Choose a reason for hiding this comment

mrbbot Mar 6, 2023

Choose a reason for hiding this comment

JacobMGEvans Mar 7, 2023 • edited Loading

Choose a reason for hiding this comment

mrbbot Mar 7, 2023 • edited Loading

Choose a reason for hiding this comment

mrbbot commented Mar 6, 2023 • edited Loading

mrbbot commented Mar 6, 2023

rozenmd Apr 25, 2023

Choose a reason for hiding this comment

mrbbot Apr 25, 2023

Choose a reason for hiding this comment

elithrar commented Jun 16, 2023

RamIdeas commented Oct 30, 2023

mrbbot commented Oct 30, 2023

petebacondarwin commented Jan 5, 2024

[wrangler] Log `Error#cause` and `DOMException` reasons when running `wrangler dev` #2851

[wrangler] Log `Error#cause` and `DOMException` reasons when running `wrangler dev` #2851

mrbbot commented Mar 3, 2023 •

edited

Loading

changeset-bot bot commented Mar 3, 2023 •

edited

Loading

github-actions bot commented Mar 3, 2023 •

edited

Loading

codecov bot commented Mar 3, 2023 •

edited

Loading

JacobMGEvans Mar 7, 2023 •

edited

Loading

mrbbot Mar 7, 2023 •

edited

Loading

mrbbot commented Mar 6, 2023 •

edited

Loading