From af0185391087e3defbd22ae58d2ee5d54920a2bb Mon Sep 17 00:00:00 2001 From: bcoll Date: Fri, 10 Nov 2023 11:09:37 +0000 Subject: [PATCH] feat: source map strings Co-authored-by: Steve Lam --- .changeset/lazy-gifts-train.md | 9 ++ fixtures/worker-app/src/index.js | 5 +- fixtures/worker-app/src/log.ts | 12 ++ fixtures/worker-app/tests/index.test.ts | 11 ++ packages/wrangler/src/dev/inspect.ts | 4 + packages/wrangler/src/dev/miniflare.ts | 5 +- packages/wrangler/src/sourcemap.ts | 205 +++++++++++++++++++----- 7 files changed, 209 insertions(+), 42 deletions(-) create mode 100644 .changeset/lazy-gifts-train.md create mode 100644 fixtures/worker-app/src/log.ts diff --git a/.changeset/lazy-gifts-train.md b/.changeset/lazy-gifts-train.md new file mode 100644 index 000000000000..6278c5b90556 --- /dev/null +++ b/.changeset/lazy-gifts-train.md @@ -0,0 +1,9 @@ +--- +"wrangler": minor +--- + +feat: apply source mapping to logged strings + +Previously, Wrangler would only apply source mapping to uncaught exceptions. This meant if you caught an exception and logged its stack trace, the call sites would reference built JavaScript files as opposed to source files. This change looks for stack traces in logged messages, and tries to source map them. + +Note source mapping is only applied when outputting logs. `Error#stack` does not return a source mapped stack trace. This means the actual runtime value of `new Error().stack` and the output from `console.log(new Error().stack)` may be different. diff --git a/fixtures/worker-app/src/index.js b/fixtures/worker-app/src/index.js index f4a8ae017dc2..8c888b023f38 100644 --- a/fixtures/worker-app/src/index.js +++ b/fixtures/worker-app/src/index.js @@ -1,5 +1,6 @@ -import { now } from "./dep"; import { randomBytes } from "isomorphic-random-example"; +import { now } from "./dep"; +import { logErrors } from "./log"; console.log("startup log"); @@ -24,6 +25,8 @@ export default { request.cf ); + logErrors(); + await fetch(new URL("http://example.com")); await fetch( new Request("http://example.com", { method: "POST", body: "foo" }) diff --git a/fixtures/worker-app/src/log.ts b/fixtures/worker-app/src/log.ts new file mode 100644 index 000000000000..3a4b0bb202cf --- /dev/null +++ b/fixtures/worker-app/src/log.ts @@ -0,0 +1,12 @@ +// Make sure built JavaScript file doesn't use the same line numbers +interface Output { + thing: 42; +} + +export function logErrors(): Output { + console.log(new Error("logged error one")); + console.log(new Error("logged error two").stack); + console.log({ error: new Error("logged error three") }); + + return { thing: 42 }; +} diff --git a/fixtures/worker-app/tests/index.test.ts b/fixtures/worker-app/tests/index.test.ts index bd322378876a..9c9aae5f2c4d 100644 --- a/fixtures/worker-app/tests/index.test.ts +++ b/fixtures/worker-app/tests/index.test.ts @@ -29,6 +29,17 @@ describe("'wrangler dev' correctly renders pages", () => { const output = getOutput(); expect(output).toContain("startup log"); expect(output).toContain("request log"); + + // Check logged strings are source mapped + expect(output).toMatch( + /Error: logged error one.+fixtures\/worker-app\/src\/log.ts:7:14/s + ); + expect(output).toMatch( + /Error: logged error two.+fixtures\/worker-app\/src\/log.ts:8:14/s + ); + expect(output).toMatch( + /Error: logged error three.+fixtures\/worker-app\/src\/log.ts:9:23/s + ); }); it("uses `workerd` condition when bundling", async ({ expect }) => { diff --git a/packages/wrangler/src/dev/inspect.ts b/packages/wrangler/src/dev/inspect.ts index 605a12cf3042..412c29f2cc06 100644 --- a/packages/wrangler/src/dev/inspect.ts +++ b/packages/wrangler/src/dev/inspect.ts @@ -8,6 +8,7 @@ import { isAllowedSourcePath, } from "../api/startDevWorker/bundle-allowed-paths"; import { logger } from "../logger"; +import { getSourceMappedString } from "../sourcemap"; import type { EsbuildBundle } from "../dev/use-esbuild"; import type Protocol from "devtools-protocol"; import type { RawSourceMap } from "source-map"; @@ -57,6 +58,9 @@ export function logConsoleMessage( case "undefined": case "symbol": case "bigint": + if (typeof ro.value === "string") { + ro.value = getSourceMappedString(ro.value); + } args.push(ro.value); break; case "function": diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 8924ed51e6e6..4eca7d8a581f 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -6,6 +6,7 @@ import { ModuleTypeToRuleType } from "../deployment-bundle/module-collection"; import { withSourceURLs } from "../deployment-bundle/source-url"; import { getHttpsOptions } from "../https-options"; import { logger } from "../logger"; +import { getSourceMappedString } from "../sourcemap"; import { updateCheck } from "../update-check"; import type { Config } from "../config"; import type { @@ -450,7 +451,7 @@ export function handleRuntimeStdio(stdout: Readable, stderr: Readable) { // anything not exlicitly handled above should be logged as info (via stdout) else { - logger.info(chunk); + logger.info(getSourceMappedString(chunk)); } }); @@ -489,7 +490,7 @@ export function handleRuntimeStdio(stdout: Readable, stderr: Readable) { // anything not exlicitly handled above should be logged as an error (via stderr) else { - logger.error(chunk); + logger.error(getSourceMappedString(chunk)); } }); } diff --git a/packages/wrangler/src/sourcemap.ts b/packages/wrangler/src/sourcemap.ts index 5467e10f2e92..6dcfb06e966c 100644 --- a/packages/wrangler/src/sourcemap.ts +++ b/packages/wrangler/src/sourcemap.ts @@ -2,6 +2,41 @@ import assert from "node:assert"; import type Protocol from "devtools-protocol"; let sourceMappingPrepareStackTrace: typeof Error.prepareStackTrace; +function getSourceMappingPrepareStackTrace(): NonNullable< + typeof Error.prepareStackTrace +> { + if (sourceMappingPrepareStackTrace !== undefined) { + return sourceMappingPrepareStackTrace; + } + + // `source-map-support` will only modify `Error.prepareStackTrace` if this + // is the first time `install()` has been called. This is governed by a + // module level variable: `errorFormatterInstalled`. To ensure we're not + // affecting external user's use of this package, and so + // `Error.prepareStackTrace` is always updated, load a fresh copy, by + // resetting then restoring the `require` cache. + const originalSupport = require.cache["source-map-support"]; + delete require.cache["source-map-support"]; + // eslint-disable-next-line @typescript-eslint/consistent-type-imports,@typescript-eslint/no-var-requires + const support: typeof import("source-map-support") = require("source-map-support"); + require.cache["source-map-support"] = originalSupport; + + const originalPrepareStackTrace = Error.prepareStackTrace; + support.install({ + environment: "node", + // Don't add Node `uncaughtException` handler + handleUncaughtExceptions: false, + // Don't hook Node `require` function + hookRequire: false, + // Make sure we're using fresh copies of files each time we source map + emptyCacheBetweenOperations: true, + }); + sourceMappingPrepareStackTrace = Error.prepareStackTrace; + assert(sourceMappingPrepareStackTrace !== undefined); + Error.prepareStackTrace = originalPrepareStackTrace; + + return sourceMappingPrepareStackTrace; +} export function getSourceMappedStack( details: Protocol.Runtime.ExceptionDetails @@ -12,72 +47,164 @@ export function getSourceMappedStack( // mapping without parsing the stack, so just return the description as is if (callFrames === undefined) return description; - if (sourceMappingPrepareStackTrace === undefined) { - // `source-map-support` will only modify `Error.prepareStackTrace` if this - // is the first time `install()` has been called. This is governed by a - // module level variable: `errorFormatterInstalled`. To ensure we're not - // affecting external user's use of this package, and so - // `Error.prepareStackTrace` is always updated, load a fresh copy, by - // resetting then restoring the `require` cache. - const originalSupport = require.cache["source-map-support"]; - delete require.cache["source-map-support"]; - // eslint-disable-next-line @typescript-eslint/consistent-type-imports,@typescript-eslint/no-var-requires - const support: typeof import("source-map-support") = require("source-map-support"); - require.cache["source-map-support"] = originalSupport; - - const originalPrepareStackTrace = Error.prepareStackTrace; - support.install({ - environment: "node", - // Don't add Node `uncaughtException` handler - handleUncaughtExceptions: false, - // Don't hook Node `require` function - hookRequire: false, - // Make sure we're using fresh copies of files each time we source map - emptyCacheBetweenOperations: true, - }); - sourceMappingPrepareStackTrace = Error.prepareStackTrace; - assert(sourceMappingPrepareStackTrace !== undefined); - Error.prepareStackTrace = originalPrepareStackTrace; - } - const nameMessage = details.exception?.description?.split("\n")[0] ?? ""; const colonIndex = nameMessage.indexOf(":"); const error = new Error(nameMessage.substring(colonIndex + 2)); error.name = nameMessage.substring(0, colonIndex); - const callSites = callFrames.map((frame) => new CallSite(frame)); - return sourceMappingPrepareStackTrace(error, callSites); + const callSites = callFrames.map(callFrameToCallSite); + return getSourceMappingPrepareStackTrace()(error, callSites); +} + +function callFrameToCallSite(frame: Protocol.Runtime.CallFrame): CallSite { + return new CallSite({ + typeName: null, + functionName: frame.functionName, + methodName: null, + fileName: frame.url, + lineNumber: frame.lineNumber + 1, + columnNumber: frame.columnNumber + 1, + native: false, + }); +} + +const placeholderError = new Error(); +export function getSourceMappedString(value: string): string { + // We could use `.replace()` here with a function replacer, but + // `getSourceMappingPrepareStackTrace()` clears its source map caches between + // operations. It's likely call sites in this `value` will share source maps, + // so instead we find all call sites, source map them together, then replace. + // Note this still works if there are multiple instances of the same call site + // (e.g. stack overflow error), as the final `.replace()`s will only replace + // the first instance. If they replace the value with itself, all instances + // of the call site would've been replaced with the same thing. + const callSiteLines = Array.from(value.matchAll(CALL_SITE_REGEXP)); + const callSites = callSiteLines.map(lineMatchToCallSite); + const sourceMappedStackTrace: string = getSourceMappingPrepareStackTrace()( + placeholderError, + callSites + ); + const sourceMappedCallSiteLines = sourceMappedStackTrace.split("\n").slice(1); + for (let i = 0; i < callSiteLines.length; i++) { + value = value.replace( + callSiteLines[i][0], + sourceMappedCallSiteLines[i].substring(4) // Trim indent from stack + ); + } + return value; +} + +// Adapted from `node-stack-trace`: +/*! + * Copyright (c) 2011 Felix Geisendörfer (felix@debuggable.com) + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, + * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN + * THE SOFTWARE. + */ + +const CALL_SITE_REGEXP = + /at (?:(.+?)\s+\()?(?:(.+?):(\d+)(?::(\d+))?|([^)]+))\)?/g; +function lineMatchToCallSite(lineMatch: RegExpMatchArray): CallSite { + let object: string | null = null; + let method: string | null = null; + let functionName: string | null = null; + let typeName: string | null = null; + let methodName: string | null = null; + const isNative = lineMatch[5] === "native"; + + if (lineMatch[1]) { + functionName = lineMatch[1]; + let methodStart = functionName.lastIndexOf("."); + if (functionName[methodStart - 1] == ".") methodStart--; + if (methodStart > 0) { + object = functionName.substring(0, methodStart); + method = functionName.substring(methodStart + 1); + const objectEnd = object.indexOf(".Module"); + if (objectEnd > 0) { + functionName = functionName.substring(objectEnd + 1); + object = object.substring(0, objectEnd); + } + } + } + + if (method) { + typeName = object; + methodName = method; + } + + if (method === "") { + methodName = null; + functionName = null; + } + + return new CallSite({ + typeName, + functionName, + methodName, + fileName: lineMatch[2] || null, + lineNumber: parseInt(lineMatch[3]) || null, + columnNumber: parseInt(lineMatch[4]) || null, + native: isNative, + }); +} + +export interface CallSiteOptions { + typeName: string | null; + functionName: string | null; + methodName: string | null; + fileName: string | null; + lineNumber: number | null; + columnNumber: number | null; + native: boolean; } +// https://v8.dev/docs/stack-trace-api#customizing-stack-traces +// This class supports the subset of options implemented by `node-stack-trace`: +// https://github.com/felixge/node-stack-trace/blob/4c41a4526e74470179b3b6dd5d75191ca8c56c17/index.js export class CallSite implements NodeJS.CallSite { - constructor(private readonly frame: Protocol.Runtime.CallFrame) {} + constructor(private readonly opts: CallSiteOptions) {} getThis(): unknown { return null; } getTypeName(): string | null { - return null; + return this.opts.typeName; } // eslint-disable-next-line @typescript-eslint/ban-types getFunction(): Function | undefined { return undefined; } getFunctionName(): string | null { - return this.frame.functionName; + return this.opts.functionName; } getMethodName(): string | null { - return null; + return this.opts.methodName; } getFileName(): string | undefined { - return this.frame.url; + return this.opts.fileName ?? undefined; } getScriptNameOrSourceURL(): string | null { - return this.frame.url; + return this.opts.fileName; } getLineNumber(): number | null { - return this.frame.lineNumber + 1; + return this.opts.lineNumber; } getColumnNumber(): number | null { - return this.frame.columnNumber + 1; + return this.opts.columnNumber; } getEvalOrigin(): string | undefined { return undefined; @@ -89,7 +216,7 @@ export class CallSite implements NodeJS.CallSite { return false; } isNative(): boolean { - return false; + return this.opts.native; } isConstructor(): boolean { return false;