Intercept workerd logs + write all debug logs to a hidden file (#4341)

* don't rethrow errors in miniflare Log class
when the log level means it won't be logged

* expose miniflare option: handleRuntimeStdio
allowing wrangler to decide whether workerd logs should reach the terminal

* intercept workerd logs in wrangler

* write all debug logs to a .wrangler/*.log file
* allow user to provide filepath *or* directory
for WRANGLER_LOG_PATH

* log debug-log-file location to terminal on exit
as well as on startup

* even if intercepted, log chunks from workerd to debug file

* fix Miniflare NoOpLog to now throw when logging errors

* try use .wrangler dir in project root before package base path

* write logs to file unconditionally
WRANGLER_LOG=debug will continue to log to the terminal

* fallback to cwd not package base path

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