[wrangler] feat: source map logged strings (#4423)

* feat: source map strings

Co-authored-by: Steve Lam <stevyo99@yahoo.ca>

* fix: ensure source mapped locations correct on Windows

Use `@cspotcode/source-map-support` instead of `source-map-support`.
This has some additional fixes for resolving paths on Windows, and is
used by `ts-node`.

---------

Co-authored-by: Steve Lam <stevyo99@yahoo.ca>

.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.

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" })

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 };
+}

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 }) => {

packages/miniflare/package.json

@@ -41,12 +41,12 @@
 		"miniflare": "bootstrap.js"
 	},
 	"dependencies": {
+		"@cspotcode/source-map-support": "0.8.1",
 		"acorn": "^8.8.0",
 		"acorn-walk": "^8.2.0",
 		"capnp-ts": "^0.7.0",
 		"exit-hook": "^2.2.1",
 		"glob-to-regexp": "^0.4.1",
-		"source-map-support": "0.5.21",
 		"stoppable": "^1.1.0",
 		"undici": "^5.22.1",
 		"workerd": "1.20231030.0",

packages/miniflare/src/plugins/core/errors/index.ts

@@ -1,7 +1,7 @@
 import fs from "fs";
 import path from "path";
 import { fileURLToPath } from "url";
-import type { UrlAndMap } from "source-map-support";
+import type { UrlAndMap } from "@cspotcode/source-map-support";
 import { z } from "zod";
 import { Request, Response } from "../../../http";
 import { Log } from "../../../shared";
@@ -49,7 +49,7 @@ interface SourceFile {
 }
 
 // Try to read a file from the file-system, returning undefined if not found
-function maybeGetDiskFile(filePath: string): SourceFile | undefined {
+function maybeGetDiskFile(filePath: string): Required<SourceFile> | undefined {
 	try {
 		const contents = fs.readFileSync(filePath, "utf8");
 		return { path: filePath, contents };

packages/miniflare/src/plugins/core/errors/sourcemap.ts

@@ -1,5 +1,5 @@
 import assert from "assert";
-import type { Options } from "source-map-support";
+import type { Options } from "@cspotcode/source-map-support";
 import { parseStack } from "./callsite";
 
 const sourceMapInstallBaseOptions: Options = {
@@ -8,6 +8,7 @@ const sourceMapInstallBaseOptions: Options = {
 	handleUncaughtExceptions: false,
 	// Don't hook Node `require` function
 	hookRequire: false,
+	redirectConflictingLibrary: false,
 
 	// Make sure we're using fresh copies of files (i.e. between `setOptions()`)
 	emptyCacheBetweenOperations: true,
@@ -36,10 +37,10 @@ export function getSourceMapper(): SourceMapper {
 	// 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"];
-	const support: typeof import("source-map-support") = require("source-map-support");
-	require.cache["source-map-support"] = originalSupport;
+	const originalSupport = require.cache["@cspotcode/source-map-support"];
+	delete require.cache["@cspotcode/source-map-support"];
+	const support: typeof import("@cspotcode/source-map-support") = require("@cspotcode/source-map-support");
+	require.cache["@cspotcode/source-map-support"] = originalSupport;
 
 	const originalPrepareStackTrace = Error.prepareStackTrace;
 	support.install(sourceMapInstallBaseOptions);
@@ -50,10 +51,13 @@ export function getSourceMapper(): SourceMapper {
 	sourceMapper = (retrieveSourceMap, error) => {
 		support.install({
 			...sourceMapInstallBaseOptions,
-			retrieveFile(file: string): string | null {
+			retrieveFile(_file: string): string {
 				// `retrieveFile` should only be called by the default implementation of
-				// `retrieveSourceMap`, so we shouldn't need to implement it
-				assert.fail(`Unexpected retrieveFile(${JSON.stringify(file)}) call`);
+				// `retrieveSourceMap`, which will only be called if `retrieveSourceMap`
+				// failed. In that case, return an empty string so the default
+				// implementation fails too (can't find `// sourceMappingURL` comment
+				// in empty string).
+				return "";
 			},
 			retrieveSourceMap,
 		});

packages/miniflare/test/plugins/core/errors/index.spec.ts

@@ -1,14 +1,14 @@
 import assert from "assert";
 import fs from "fs/promises";
 import path from "path";
-import { fileURLToPath } from "url";
+import { fileURLToPath, pathToFileURL } from "url";
 import test from "ava";
 import Protocol from "devtools-protocol";
 import esbuild from "esbuild";
 import { DeferredPromise, Log, LogLevel, Miniflare, fetch } from "miniflare";
 import type { RawSourceMap } from "source-map";
 import NodeWebSocket from "ws";
-import { escapeRegexp, useTmp } from "../../../test-shared";
+import { escapeRegexpComponent, useTmp } from "../../../test-shared";
 
 const FIXTURES_PATH = path.resolve(
 	__dirname,
@@ -26,6 +26,12 @@ const MODULES_ENTRY_PATH = path.join(FIXTURES_PATH, "modules.ts");
 const DEP_ENTRY_PATH = path.join(FIXTURES_PATH, "nested/dep.ts");
 const REDUCE_PATH = path.join(FIXTURES_PATH, "reduce.ts");
 
+function pathOrUrlRegexp(filePath: string): `(${string}|${string})` {
+	return `(${escapeRegexpComponent(filePath)}|${escapeRegexpComponent(
+		pathToFileURL(filePath).href
+	)})`;
+}
+
 test("source maps workers", async (t) => {
 	// Build fixtures
 	const tmp = await useTmp(t);
@@ -135,8 +141,8 @@ addEventListener("fetch", (event) => {
 	let error = await t.throwsAsync(mf.dispatchFetch("http://localhost"), {
 		message: "unnamed",
 	});
-	const serviceWorkerEntryRegexp = escapeRegexp(
-		`${SERVICE_WORKER_ENTRY_PATH}:6:16`
+	const serviceWorkerEntryRegexp = new RegExp(
+		`${pathOrUrlRegexp(SERVICE_WORKER_ENTRY_PATH)}:6:16`
 	);
 	t.regex(String(error?.stack), serviceWorkerEntryRegexp);
 	error = await t.throwsAsync(mf.dispatchFetch("http://localhost/a"), {
@@ -148,7 +154,9 @@ addEventListener("fetch", (event) => {
 	error = await t.throwsAsync(mf.dispatchFetch("http://localhost/b"), {
 		message: "b",
 	});
-	const modulesEntryRegexp = escapeRegexp(`${MODULES_ENTRY_PATH}:5:17`);
+	const modulesEntryRegexp = new RegExp(
+		`${pathOrUrlRegexp(MODULES_ENTRY_PATH)}:5:17`
+	);
 	t.regex(String(error?.stack), modulesEntryRegexp);
 	error = await t.throwsAsync(mf.dispatchFetch("http://localhost/c"), {
 		message: "c",
@@ -174,7 +182,7 @@ addEventListener("fetch", (event) => {
 		instanceOf: TypeError,
 		message: "Dependency error",
 	});
-	const nestedRegexp = escapeRegexp(`${DEP_ENTRY_PATH}:4:16`);
+	const nestedRegexp = new RegExp(`${pathOrUrlRegexp(DEP_ENTRY_PATH)}:4:16`);
 	t.regex(String(error?.stack), nestedRegexp);
 
 	// Check source mapping URLs rewritten

packages/miniflare/test/test-shared/asserts.ts

@@ -18,9 +18,9 @@ export function isWithin(
 	);
 }
 
-export function escapeRegexp(value: string): RegExp {
+export function escapeRegexpComponent(value: string): string {
 	// From https://developer.mozilla.org/en-US/docs/Web/JavaScript/Guide/Regular_expressions#escaping
-	return new RegExp(value.replace(/[.*+?^${}()|[\]\\]/g, "\\$&"));
+	return value.replace(/[.*+?^${}()|[\]\\]/g, "\\$&");
 }
 
 export function flaky(

packages/wrangler/package.json

@@ -102,6 +102,7 @@
 	},
 	"dependencies": {
 		"@cloudflare/kv-asset-handler": "^0.2.0",
+		"@cspotcode/source-map-support": "0.8.1",
 		"@esbuild-plugins/node-globals-polyfill": "^0.2.3",
 		"@esbuild-plugins/node-modules-polyfill": "^0.2.2",
 		"blake3-wasm": "^2.1.5",
@@ -113,7 +114,6 @@
 		"resolve.exports": "^2.0.2",
 		"selfsigned": "^2.0.1",
 		"source-map": "0.6.1",
-		"source-map-support": "0.5.21",
 		"xxhash-wasm": "^1.0.1"
 	},
 	"devDependencies": {

packages/wrangler/scripts/deps.ts

@@ -12,6 +12,8 @@ export const EXTERNAL_DEPENDENCIES = [
 	// todo - bundle miniflare too
 	"selfsigned",
 	"source-map",
+	// CommonJS module using `module.require()` which isn't provided by `esbuild`
+	"@cspotcode/source-map-support",
 	"@esbuild-plugins/node-globals-polyfill",
 	"@esbuild-plugins/node-modules-polyfill",
 	"chokidar",

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":

packages/wrangler/src/dev/miniflare.ts

@@ -7,6 +7,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 {
@@ -462,7 +463,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));
 		}
 	});
 
@@ -501,7 +502,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));
 		}
 	});
 }