Intercept workerd logs + write all debug logs to a hidden file

.changeset/gentle-pans-push.md

@@ -0,0 +1,5 @@
+---
+"miniflare": minor
+---
+
+Added a `handleRuntimeStdio` which enables wrangler (or any other direct use of Miniflare) to handle the `stdout` and `stderr` streams from the workerd child process. By default, if this option is not provided, the previous behaviour is retained which splits the streams into lines and calls `console.log`/`console.error`.

.changeset/weak-peaches-marry.md

@@ -0,0 +1,7 @@
+---
+"wrangler": minor
+---
+
+Wrangler now writes all logs to a .log file in the `.wrangler` directory. Set a directory or specific .log filepath to write logs to with `WRANGLER_LOG_PATH=../Desktop/my-logs/` or `WRANGLER_LOG_PATH=../Desktop/my-logs/my-log-file.log`. When specifying a directory or using the default location, a filename with a timestamp is used.
+
+Wrangler now filters workerd stdout/stderr and marks unactionable messages as debug logs. These debug logs are still observable in the debug log file but will no longer show in the terminal by default without the user setting the env var `WRANGLER_LOG=debug`.

.github/workflows/e2e.yml

@@ -82,3 +82,11 @@ jobs:
           CLOUDFLARE_ACCOUNT_ID: ${{ secrets.TEST_CLOUDFLARE_ACCOUNT_ID }}
           WRANGLER: pnpm --silent --package ${{ steps.find-wrangler.outputs.dir}} dlx wrangler
           NODE_OPTIONS: "--max_old_space_size=8192"
+          WRANGLER_LOG_PATH: ${{ runner.temp }}/wrangler-debug-logs/
+
+      - name: Upload debug logs
+        if: always()
+        uses: actions/upload-artifact@v3
+        with:
+          name: e2e-test-debug-logs-${{ matrix.os }}-${{ matrix.node }}
+          path: ${{ runner.temp }}/wrangler-debug-logs/

.github/workflows/pullrequests.yml

@@ -115,6 +115,14 @@ jobs:
           TMP_CLOUDFLARE_API_TOKEN: ${{ secrets.CLOUDFLARE_API_TOKEN }}
           TMP_CLOUDFLARE_ACCOUNT_ID: ${{ secrets.CLOUDFLARE_ACCOUNT_ID }}
           NODE_OPTIONS: "--max_old_space_size=8192"
+          WRANGLER_LOG_PATH: ${{ runner.temp }}/wrangler-debug-logs/
+
+      - name: Upload debug logs
+        if: always()
+        uses: actions/upload-artifact@v3
+        with:
+          name: e2e-test-debug-logs-${{ matrix.os }}-${{ matrix.node }}
+          path: ${{ runner.temp }}/wrangler-debug-logs/
 
       - name: Run changeset version tests
         run: node .github/changeset-version.test.js

packages/miniflare/src/index.ts

@@ -1129,6 +1129,7 @@ export class Miniflare {
 			requiredSockets,
 			inspectorAddress,
 			verbose: this.#sharedOpts.core.verbose,
+			handleRuntimeStdio: this.#sharedOpts.core.handleRuntimeStdio,
 		};
 		const maybeSocketPorts = await this.#runtime.updateConfig(
 			configBuffer,

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

@@ -2,6 +2,7 @@ import assert from "assert";
 import { readFileSync } from "fs";
 import fs from "fs/promises";
 import path from "path";
+import { Readable } from "stream";
 import tls from "tls";
 import { TextEncoder } from "util";
 import { bold } from "kleur/colors";
@@ -137,6 +138,9 @@ export const CoreSharedOptionsSchema = z.object({
 	verbose: z.boolean().optional(),
 
 	log: z.instanceof(Log).optional(),
+	handleRuntimeStdio: z
+		.function(z.tuple([z.instanceof(Readable), z.instanceof(Readable)]))
+		.optional(),
 
 	upstream: z.string().optional(),
 	// TODO: add back validation of cf object

packages/miniflare/src/runtime/index.ts

@@ -33,6 +33,7 @@ export interface RuntimeOptions {
 	requiredSockets: SocketIdentifier[];
 	inspectorAddress?: string;
 	verbose?: boolean;
+	handleRuntimeStdio?: (stdout: Readable, stderr: Readable) => void;
 }
 
 async function waitForPorts(
@@ -75,19 +76,17 @@ function waitForExit(process: childProcess.ChildProcess): Promise<void> {
 	});
 }
 
-function pipeOutput(runtime: childProcess.ChildProcessWithoutNullStreams) {
+function pipeOutput(stdout: Readable, stderr: Readable) {
 	// TODO: may want to proxy these and prettify ✨
 	// We can't just pipe() to `process.stdout/stderr` here, as Ink (used by
 	// wrangler), only patches the `console.*` methods:
 	// https://github.com/vadimdemedes/ink/blob/5d24ed8ada593a6c36ea5416f452158461e33ba5/readme.md#patchconsole
 	// Writing directly to `process.stdout/stderr` would result in graphical
 	// glitches.
-	const stdout = rl.createInterface(runtime.stdout);
-	const stderr = rl.createInterface(runtime.stderr);
-	stdout.on("line", (data) => console.log(data));
-	stderr.on("line", (data) => console.error(red(data)));
-	// runtime.stdout.pipe(process.stdout);
-	// runtime.stderr.pipe(process.stderr);
+	rl.createInterface(stdout).on("line", (data) => console.log(data));
+	rl.createInterface(stderr).on("line", (data) => console.error(red(data)));
+	// stdout.pipe(process.stdout);
+	// stderr.pipe(process.stderr);
 }
 
 function getRuntimeCommand() {
@@ -144,7 +143,9 @@ export class Runtime {
 		});
 		this.#process = runtimeProcess;
 		this.#processExitPromise = waitForExit(runtimeProcess);
-		pipeOutput(runtimeProcess);
+
+		const handleRuntimeStdio = options.handleRuntimeStdio ?? pipeOutput;
+		handleRuntimeStdio(runtimeProcess.stdout, runtimeProcess.stderr);
 
 		const controlPipe = runtimeProcess.stdio[3];
 		assert(controlPipe instanceof Readable);

packages/miniflare/src/shared/log.ts

@@ -78,8 +78,7 @@ export class Log {
 
 	error(message: Error): void {
 		if (this.level < LogLevel.ERROR) {
-			// Rethrow message if it won't get logged
-			throw message;
+			// Ignore message if it won't get logged
 		} else if (message.stack) {
 			// Dim internal stack trace lines to highlight user code
 			const lines = message.stack.split("\n").map(dimInternalStackLine);
@@ -116,9 +115,7 @@ export class NoOpLog extends Log {
 
 	protected log(): void {}
 
-	error(message: Error): void {
-		throw message;
-	}
+	error(_message: Error): void {}
 }
 
 // Adapted from https://github.com/chalk/ansi-regex/blob/02fa893d619d3da85411acc8fd4e2eea0e95a9d9/index.js

packages/miniflare/test/http/fetch.spec.ts

@@ -45,7 +45,7 @@ test("fetch: performs http request with form data", async (t) => {
 test("fetch: performs web socket upgrade", async (t) => {
 	const server = await useServer(t, noop, (ws, req) => {
 		ws.send("hello client");
-		ws.send(req.headers["user-agent"]);
+		ws.send(req.headers["user-agent"] ?? "");
 		ws.addEventListener("message", ({ data }) => ws.send(data));
 	});
 	const res = await fetch(server.http, {
@@ -69,7 +69,7 @@ test("fetch: performs web socket upgrade", async (t) => {
 });
 test("fetch: performs web socket upgrade with Sec-WebSocket-Protocol header", async (t) => {
 	const server = await useServer(t, noop, (ws, req) => {
-		ws.send(req.headers["sec-websocket-protocol"]);
+		ws.send(req.headers["sec-websocket-protocol"] ?? "");
 	});
 	const res = await fetch(server.http, {
 		headers: {