fix wrangler dev logs being logged on the incorrect level in some cases

.changeset/deep-lizards-move.md

@@ -0,0 +1,35 @@
+---
+"wrangler": patch
+---
+
+fix `wrangler dev` logs being logged on the incorrect level in some cases
+
+currently the way `wrangler dev` prints logs is faulty, for example the following code
+
+```js
+console.error("this is an error");
+console.warn("this is a warning");
+console.debug("this is a debug");
+```
+
+inside a worker would cause the following logs:
+
+```text
+✘ [ERROR] this is an error
+
+✘ [ERROR] this is a warning
+
+this is a debug
+```
+
+(note that the warning is printed as an error and the debug log is printed even if by default it should not)
+
+the changes here make sure that the logs are instead logged to their correct level, so for the code about the following will be logged instead:
+
+```text
+✘ [ERROR] this is an error
+
+▲ [WARNING] this is a warning
+```
+
+(running `wrangler dev` with the `--log-level=debug` flag will also cause the debug log to be included as well)

.changeset/full-areas-lick.md

@@ -0,0 +1,7 @@
+---
+"miniflare": minor
+---
+
+add `structuredWorkerdLogs` option
+
+add a new top-level option named `structuredWorkerdLogs` that makes workerd print to stdout structured logs (stringified jsons of the following shape: `{ timestamp: number, level: string, message: string }`) instead of printing logs to stdout and stderr

fixtures/shared/src/run-wrangler-long-lived.ts

@@ -87,7 +87,9 @@ async function runLongLivedWrangler(
 		chunks.push(chunk);
 	});
 	wranglerProcess.stderr?.on("data", (chunk) => {
-		console.log(`[${command}]`, chunk.toString());
+		if (process.env.WRANGLER_LOG === "debug") {
+			console.log(`[${command}]`, chunk.toString());
+		}
 		chunks.push(chunk);
 	});
 	wranglerProcess.once("exit", (exitCode) => {

fixtures/worker-logs/package.json

@@ -0,0 +1,22 @@
+{
+	"name": "@fixture/worker-logs",
+	"private": true,
+	"scripts": {
+		"check:type": "tsc",
+		"dev": "pnpm dev.module",
+		"dev.module": "wrangler dev -c wrangler.module.jsonc",
+		"dev.service": "wrangler dev -c wrangler.service.jsonc",
+		"start": "pnpm dev.module",
+		"test:ci": "vitest run",
+		"test:watch": "vitest"
+	},
+	"devDependencies": {
+		"@cloudflare/workers-tsconfig": "workspace:^",
+		"typescript": "catalog:default",
+		"vitest": "catalog:default",
+		"wrangler": "workspace:*"
+	},
+	"volta": {
+		"extends": "../../package.json"
+	}
+}

fixtures/worker-logs/src/module.js

@@ -0,0 +1,25 @@
+export default {
+	async fetch(request, env) {
+		const response = new Response("Hello");
+
+		const customMessage = request.headers.get("x-custom-message");
+		if (customMessage) {
+			if (customMessage === "%__VERY_VERY_LONG_MESSAGE_%") {
+				// We can't simply pass a huge long message as a header thus
+				// why a placeholder is used here
+				console.log("z".repeat(2 ** 20));
+			} else {
+				console.log(customMessage);
+			}
+			return response;
+		}
+
+		console.log("<<<<<this is a log>>>>>");
+		console.warn("<<<<<this is a warning>>>>>");
+		console.error("<<<<<this is an error>>>>>");
+		console.debug("<<<<<this is a debug message>>>>>");
+		console.info("<<<<<this is an info message>>>>>");
+
+		return response;
+	},
+};

fixtures/worker-logs/src/service.js

@@ -0,0 +1,12 @@
+async function handler(request) {
+	console.log("<<<<<this is a log>>>>>");
+	console.warn("<<<<<this is a warning>>>>>");
+	console.error("<<<<<this is an error>>>>>");
+	console.debug("<<<<<this is a debug message>>>>>");
+	console.info("<<<<<this is an info message>>>>>");
+	return new Response("Hello");
+}
+
+addEventListener("fetch", (event) => {
+	event.respondWith(handler(event.request));
+});

fixtures/worker-logs/tests/index.test.ts

@@ -0,0 +1,273 @@
+import { setTimeout } from "node:timers/promises";
+import { resolve } from "path";
+import { describe, test } from "vitest";
+import { runWranglerDev } from "../../shared/src/run-wrangler-long-lived";
+
+async function getWranglerDevOutput(
+	type: "module" | "service",
+	extraArgs: string[] = [],
+	customMessage?: string,
+	requests = 1,
+	env = {}
+) {
+	const { ip, port, stop, getOutput } = await runWranglerDev(
+		resolve(__dirname, ".."),
+		[
+			`-c=wrangler.${type}.jsonc`,
+			"--port=0",
+			"--inspector-port=0",
+			...extraArgs,
+		],
+		env
+	);
+
+	const request = new Request(`http://${ip}:${port}`);
+	if (customMessage) {
+		request.headers.set("x-custom-message", customMessage);
+	}
+
+	for (let i = 0; i < requests; i++) {
+		const response = await fetch(request);
+		await response.text();
+
+		// We wait for a bit for the output stream to be completely ready
+		// (this is a bit slow but it's generic to be used by all tests
+		// in this file, it also seems to make the tests very stable)
+		await setTimeout(500);
+	}
+
+	await stop();
+
+	let output = getOutput();
+
+	output = output
+		// Windows gets a different marker for ✘, so let's normalize it here
+		// so that these tests can be platform independent
+		.replaceAll("✘", "X")
+		// Let's also normalize Windows newlines
+		.replaceAll("\r\n", "\n");
+
+	// Let's filter out lines we're not interested in
+	output = output
+		.split("\n")
+		.filter((line) =>
+			logLineToIgnoreRegexps.every((regex) => !regex.test(line))
+		)
+		// let's also sort the logs for more stability of the tests, ideally
+		// we would want to test the log's ordering as well but that seems
+		// to cause flakes in the CI runs
+		.sort()
+		.join("\n");
+
+	return output;
+}
+
+describe("'wrangler dev' correctly displays logs", () => {
+	describe("module workers", () => {
+		test("default behavior", async ({ expect }) => {
+			const output = await getWranglerDevOutput("module");
+			expect(output).toMatchInlineSnapshot(`
+				"X [ERROR] <<<<<this is an error>>>>>
+				▲ [WARNING] <<<<<this is a warning>>>>>
+				<<<<<this is a log>>>>>
+				<<<<<this is an info message>>>>>"
+			`);
+		});
+
+		test("with --log-level=log", async ({ expect }) => {
+			const output = await getWranglerDevOutput("module", ["--log-level=log"]);
+			expect(output).toMatchInlineSnapshot(`
+				"X [ERROR] <<<<<this is an error>>>>>
+				▲ [WARNING] <<<<<this is a warning>>>>>
+				<<<<<this is a log>>>>>
+				<<<<<this is an info message>>>>>"
+			`);
+		});
+
+		test("with --log-level=info", async ({ expect }) => {
+			const output = await getWranglerDevOutput("module", ["--log-level=info"]);
+			expect(output).toMatchInlineSnapshot(`
+				"X [ERROR] <<<<<this is an error>>>>>
+				▲ [WARNING] <<<<<this is a warning>>>>>
+				<<<<<this is an info message>>>>>"
+			`);
+		});
+
+		test("with --log-level=warn", async ({ expect }) => {
+			const output = await getWranglerDevOutput("module", ["--log-level=warn"]);
+			expect(output).toMatchInlineSnapshot(`
+				"X [ERROR] <<<<<this is an error>>>>>
+				▲ [WARNING] <<<<<this is a warning>>>>>"
+			`);
+		});
+
+		test("with --log-level=error", async ({ expect }) => {
+			const output = await getWranglerDevOutput("module", [
+				"--log-level=error",
+			]);
+			expect(output).toMatchInlineSnapshot(
+				`"X [ERROR] <<<<<this is an error>>>>>"`
+			);
+		});
+
+		test("with --log-level=debug", async ({ expect }) => {
+			const output = await getWranglerDevOutput(
+				"module",
+				["--log-level=debug"],
+				undefined,
+				// For some reason in debug mode two requests are
+				// needed to trigger the log here...
+				2
+			);
+			expect(output).toContain("<<<<<this is a debug message>>>>>");
+		});
+
+		test('with WRANGLER_LOG="debug"', async ({ expect }) => {
+			const output = await getWranglerDevOutput(
+				"module",
+				[],
+				undefined,
+				// For some reason in debug mode two requests are
+				// needed to trigger the log here...
+				2,
+				{ WRANGLER_LOG: "debug" }
+			);
+			expect(output).toContain("<<<<<this is a debug message>>>>>");
+		});
+
+		test("with --log-level=none", async ({ expect }) => {
+			const output = await getWranglerDevOutput("module", ["--log-level=none"]);
+			expect(output).toMatchInlineSnapshot(`""`);
+		});
+
+		// the workerd structured logs follow this structure:
+		//   {"timestamp":<number>,"level":"<string>","message":"<string>"}
+		// the following tests check for edge case scenario where the following
+		// structure could not get detected correctly
+		describe("edge case scenarios", () => {
+			test("base case", async ({ expect }) => {
+				const output = await getWranglerDevOutput("module", [], "hello");
+				expect(output).toMatchInlineSnapshot(`"hello"`);
+			});
+			test("quotes in message", async ({ expect }) => {
+				const output = await getWranglerDevOutput("module", [], 'hel"lo');
+				expect(output).toMatchInlineSnapshot(`"hel"lo"`);
+			});
+
+			test("braces in message", async ({ expect }) => {
+				const output = await getWranglerDevOutput("module", [], "hel{}lo");
+				expect(output).toMatchInlineSnapshot(`"hel{}lo"`);
+			});
+
+			test("a workerd structured message in the message", async ({
+				expect,
+			}) => {
+				const output = await getWranglerDevOutput(
+					"module",
+					[],
+					'This is an example of a Workerd structured log: {"timestamp":1234567890,"level":"log","message":"Hello World!"}'
+				);
+				expect(output).toMatchInlineSnapshot(
+					`"This is an example of a Workerd structured log: {"timestamp":1234567890,"level":"log","message":"Hello World!"}"`
+				);
+			});
+
+			test("a very very very long message (that gets split in multiple chunks)", async ({
+				expect,
+			}) => {
+				const output = await getWranglerDevOutput(
+					"module",
+					[],
+					"%__VERY_VERY_LONG_MESSAGE_%"
+				);
+				expect(output).toMatch(new RegExp(`^z{${2 ** 20}}$`));
+			});
+		});
+	});
+
+	// Note: service workers logs are handled differently from standard logs (and are built on top of
+	//       inspector Runtime.consoleAPICalled events), they don't work as well as logs for module
+	//       workers. Service workers are also deprecated so it's not a huge deal, the following
+	//       tests are only here in place to make sure that the basic logging functionality of
+	//       service workers does work
+	describe("service workers", () => {
+		test("default behavior", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service");
+			expect(output).toMatchInlineSnapshot(`
+				"<<<<<this is a log>>>>>
+				<<<<<this is a warning>>>>>
+				<<<<<this is an error>>>>>
+				<<<<<this is an info message>>>>>"
+			`);
+		});
+
+		test("with --log-level=log", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service", ["--log-level=log"]);
+			expect(output).toMatchInlineSnapshot(`
+				"<<<<<this is a log>>>>>
+				<<<<<this is a warning>>>>>
+				<<<<<this is an error>>>>>
+				<<<<<this is an info message>>>>>"
+			`);
+		});
+
+		test("with --log-level=info", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service", [
+				"--log-level=info",
+			]);
+			expect(output).toMatchInlineSnapshot(`
+				"<<<<<this is a warning>>>>>
+				<<<<<this is an error>>>>>
+				<<<<<this is an info message>>>>>"
+			`);
+		});
+
+		test("with --log-level=warn", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service", [
+				"--log-level=warn",
+			]);
+			expect(output).toMatchInlineSnapshot(`
+				"<<<<<this is a warning>>>>>
+				<<<<<this is an error>>>>>"
+			`);
+		});
+
+		test("with --log-level=error", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service", [
+				"--log-level=error",
+			]);
+			expect(output).toMatchInlineSnapshot(`"<<<<<this is an error>>>>>"`);
+		});
+
+		test("with --log-level=debug", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service", [
+				"--log-level=debug",
+			]);
+			expect(output).toContain("<<<<<this is a debug message>>>>>");
+		});
+
+		test("with --log-level=none", async ({ expect }) => {
+			const output = await getWranglerDevOutput("service", [
+				"--log-level=none",
+			]);
+			expect(output).toMatchInlineSnapshot(`""`);
+		});
+	});
+});
+
+const logLineToIgnoreRegexps = [
+	// let's skip empty lines
+	/^\s*$/,
+	// part of the wrangler banner
+	/⛅️ wrangler/,
+	// divisor after the wrangler banner
+	/^─+$/,
+	// wrangler logs such as ` ⎔ Starting local server...`
+	/^\s*⎔/,
+	// wrangler's ready on log
+	/^\[wrangler:info\] Ready on http:\/\/[^:]+:\d+$/,
+	// positive response to get request
+	/^\[wrangler:info\] GET \/ 200 OK \(\d+ms\)$/,
+	// let's skip the telemetry messages
+	/^Cloudflare collects anonymous telemetry about your usage of Wrangler\. Learn more at https:\/\/.*$/,
+];