From d99087433814e4f1fb98cd61b03b6e2f606b1a15 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 16:42:57 +0000 Subject: [PATCH] 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 | 5 + .changeset/weak-peaches-marry.md | 7 + .github/workflows/e2e.yml | 8 + .github/workflows/pullrequests.yml | 8 + packages/miniflare/src/index.ts | 1 + packages/miniflare/src/plugins/core/index.ts | 4 + packages/miniflare/src/runtime/index.ts | 17 +- packages/miniflare/src/shared/log.ts | 7 +- packages/miniflare/test/http/fetch.spec.ts | 4 +- packages/wrangler/e2e/dev.test.ts | 225 ++++++++++++++++-- packages/wrangler/e2e/helpers/normalize.ts | 22 ++ packages/wrangler/e2e/helpers/retry.ts | 4 +- packages/wrangler/scripts/deps.ts | 6 +- packages/wrangler/src/__tests__/dev.test.tsx | 6 - packages/wrangler/src/dev/miniflare.ts | 81 +++++++ .../src/environment-variables/factory.ts | 1 + packages/wrangler/src/logger.ts | 12 +- packages/wrangler/src/utils/debug-log-file.ts | 90 +++++++ 18 files changed, 455 insertions(+), 53 deletions(-) create mode 100644 .changeset/gentle-pans-push.md create mode 100644 .changeset/weak-peaches-marry.md create mode 100644 packages/wrangler/src/utils/debug-log-file.ts diff --git a/.changeset/gentle-pans-push.md b/.changeset/gentle-pans-push.md new file mode 100644 index 000000000000..8b672edc7942 --- /dev/null +++ b/.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`. diff --git a/.changeset/weak-peaches-marry.md b/.changeset/weak-peaches-marry.md new file mode 100644 index 000000000000..2c4167cd0cd9 --- /dev/null +++ b/.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`. diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 7aac41bfa2ef..34b38959b915 100644 --- a/.github/workflows/e2e.yml +++ b/.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/ diff --git a/.github/workflows/pullrequests.yml b/.github/workflows/pullrequests.yml index 35b30a5cc7dc..4f313d8e23c2 100644 --- a/.github/workflows/pullrequests.yml +++ b/.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 diff --git a/packages/miniflare/src/index.ts b/packages/miniflare/src/index.ts index b160110853fc..fc02e5429e84 100644 --- a/packages/miniflare/src/index.ts +++ b/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, diff --git a/packages/miniflare/src/plugins/core/index.ts b/packages/miniflare/src/plugins/core/index.ts index 9b2e28abd300..108a3e0bd621 100644 --- a/packages/miniflare/src/plugins/core/index.ts +++ b/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 diff --git a/packages/miniflare/src/runtime/index.ts b/packages/miniflare/src/runtime/index.ts index 85c077b50639..621ac87e950a 100644 --- a/packages/miniflare/src/runtime/index.ts +++ b/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 { }); } -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); diff --git a/packages/miniflare/src/shared/log.ts b/packages/miniflare/src/shared/log.ts index d4fddcbcbe09..20a4d164c9ac 100644 --- a/packages/miniflare/src/shared/log.ts +++ b/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 diff --git a/packages/miniflare/test/http/fetch.spec.ts b/packages/miniflare/test/http/fetch.spec.ts index 0469dba4f22b..13a67c60e2b5 100644 --- a/packages/miniflare/test/http/fetch.spec.ts +++ b/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: { diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index aa8fd136145c..ee2782d5fbc9 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -1,4 +1,6 @@ +import assert from "node:assert"; import crypto from "node:crypto"; +import { existsSync } from "node:fs"; import * as nodeNet from "node:net"; import path from "node:path"; import { setTimeout } from "node:timers/promises"; @@ -6,29 +8,83 @@ import getPort from "get-port"; import shellac from "shellac"; import { fetch } from "undici"; import { afterEach, beforeEach, describe, expect, it } from "vitest"; +import { normalizeOutput } from "./helpers/normalize"; import { retry } from "./helpers/retry"; import { dedent, makeRoot, seed } from "./helpers/setup"; import { WRANGLER } from "./helpers/wrangler-command"; +type MaybePromise = T | Promise; + +const waitForPortToBeBound = async (port: number) => { + await retry( + () => false, // only retry if promise below rejects (network error) + () => fetch(`http://127.0.0.1:${port}`) + ); +}; + +const waitUntilOutputContains = async ( + session: SessionData, + substring: string, + intervalMs = 100 +) => { + await retry( + (stdout) => !stdout.includes(substring), + async () => { + await setTimeout(intervalMs); + return ( + normalizeOutput(session.stdout) + + "\n\n\n" + + normalizeOutput(session.stderr) + ); + } + ); +}; + +interface SessionData { + port: number; + stdout: string; + stderr: string; +} + async function runDevSession( workerPath: string, flags: string, - session: (port: number) => Promise + session: (sessionData: SessionData) => MaybePromise ) { let pid; try { - const port = await getPort(); + const portFlagMatch = flags.match(/--port (\d+)/); + let port = 0; + if (portFlagMatch) { + port = parseInt(portFlagMatch[1]); + } + if (port === 0) { + port = await getPort(); + flags += ` --port ${port}`; + } + // Must use the `in` statement in the shellac script rather than `.in()` modifier on the `shellac` object // otherwise the working directory does not get picked up. const bg = await shellac.env(process.env).bg` in ${workerPath} { exits { - $ ${WRANGLER} dev ${flags} --port ${port} + $ ${WRANGLER} dev ${flags} } } `; pid = bg.pid; - await session(port); + + // sessionData is a mutable object where stdout/stderr update + const sessionData: SessionData = { + port, + stdout: "", + stderr: "", + }; + bg.process.stdout.on("data", (chunk) => (sessionData.stdout += chunk)); + bg.process.stderr.on("data", (chunk) => (sessionData.stderr += chunk)); + + await session(sessionData); + return bg.promise; } finally { if (pid) process.kill(pid); @@ -40,7 +96,7 @@ type DevWorker = { workerPath: string; runDevSession: ( flags: string, - session: (port: number) => Promise + session: (sessionData: SessionData) => MaybePromise ) => ReturnType; seed: ( seeder: ((name: string) => Record) | Record @@ -56,8 +112,10 @@ async function makeWorker(): Promise { return { workerName, workerPath, - runDevSession: (flags: string, session: (port: number) => Promise) => - runDevSession(workerPath, flags, session), + runDevSession: ( + flags: string, + session: (sessionData: SessionData) => MaybePromise + ) => runDevSession(workerPath, flags, session), seed: (seeder) => seed( workerPath, @@ -97,11 +155,11 @@ describe("basic dev tests", () => { }); it("can modify worker during dev session (local)", async () => { - await worker.runDevSession("", async (port) => { + await worker.runDevSession("", async (session) => { const { text } = await retry( (s) => s.status !== 200, async () => { - const r = await fetch(`http://127.0.0.1:${port}`); + const r = await fetch(`http://127.0.0.1:${session.port}`); return { text: await r.text(), status: r.status }; } ); @@ -119,7 +177,7 @@ describe("basic dev tests", () => { const { text: text2 } = await retry( (s) => s.status !== 200 || s.text === "Hello World!", async () => { - const r = await fetch(`http://127.0.0.1:${port}`); + const r = await fetch(`http://127.0.0.1:${session.port}`); return { text: await r.text(), status: r.status }; } ); @@ -138,7 +196,7 @@ describe("basic dev tests", () => { const { text: text3 } = await retry( (s) => s.status !== 200 || s.text === "Updated Worker! value", async () => { - const r = await fetch(`http://127.0.0.1:${port}`); + const r = await fetch(`http://127.0.0.1:${session.port}`); return { text: await r.text(), status: r.status }; } ); @@ -147,11 +205,11 @@ describe("basic dev tests", () => { }); it("can modify worker during dev session (remote)", async () => { - await worker.runDevSession("--remote --ip 127.0.0.1", async (port) => { + await worker.runDevSession("--remote --ip 127.0.0.1", async (session) => { const { text } = await retry( (s) => s.status !== 200 || s.text === "", async () => { - const r = await fetch(`http://127.0.0.1:${port}`); + const r = await fetch(`http://127.0.0.1:${session.port}`); return { text: await r.text(), status: r.status }; } ); @@ -173,7 +231,7 @@ describe("basic dev tests", () => { const { text: text2 } = await retry( (s) => s.status !== 200 || s.text === "Hello World!", async () => { - const r = await fetch(`http://127.0.0.1:${port}`); + const r = await fetch(`http://127.0.0.1:${session.port}`); return { text: await r.text(), status: r.status }; } ); @@ -238,11 +296,11 @@ describe("dev registry", () => { }); it("can fetch b", async () => { - await b.runDevSession("", async (bPort) => { + await b.runDevSession("", async (sessionB) => { const { text } = await retry( (s) => s.status !== 200, async () => { - const r = await fetch(`http://127.0.0.1:${bPort}`); + const r = await fetch(`http://127.0.0.1:${sessionB.port}`); return { text: await r.text(), status: r.status }; } ); @@ -252,11 +310,11 @@ describe("dev registry", () => { it("can fetch b through a (start b, start a)", async () => { await b.runDevSession("", async () => { - await a.runDevSession("", async (aPort) => { + await a.runDevSession("", async (sessionA) => { const { text } = await retry( (s) => s.status !== 200, async () => { - const r = await fetch(`http://127.0.0.1:${aPort}`); + const r = await fetch(`http://127.0.0.1:${sessionA.port}`); return { text: await r.text(), status: r.status }; } ); @@ -264,13 +322,14 @@ describe("dev registry", () => { }); }); }); + it("can fetch b through a (start a, start b)", async () => { - await a.runDevSession("", async (aPort) => { + await a.runDevSession("", async (sessionA) => { await b.runDevSession("", async () => { const { text } = await retry( (s) => s.status !== 200, async () => { - const r = await fetch(`http://127.0.0.1:${aPort}`); + const r = await fetch(`http://127.0.0.1:${sessionA.port}`); return { text: await r.text(), status: r.status }; } ); @@ -296,7 +355,7 @@ describe("hyperdrive dev tests", () => { name = "${workerName}" main = "src/index.ts" compatibility_date = "2023-10-25" - + [[hyperdrive]] binding = "HYPERDRIVE" id = "hyperdrive_id" @@ -323,13 +382,13 @@ describe("hyperdrive dev tests", () => { }); it("matches expected configuration parameters", async () => { - await worker.runDevSession("", async (port) => { + await worker.runDevSession("", async (session) => { const { text } = await retry( (s) => { return s.status !== 200; }, async () => { - const resp = await fetch(`http://127.0.0.1:${port}`); + const resp = await fetch(`http://127.0.0.1:${session.port}`); return { text: await resp.text(), status: resp.status }; } ); @@ -351,22 +410,138 @@ describe("hyperdrive dev tests", () => { }); }); }); - await worker.runDevSession("", async (port) => { + await worker.runDevSession("", async (session) => { await retry( (s) => { return s.status !== 200; }, async () => { - const resp = await fetch(`http://127.0.0.1:${port}/connect`); + const resp = await fetch(`http://127.0.0.1:${session.port}/connect`); return { text: await resp.text(), status: resp.status }; } ); }); await socketMsgPromise; }); + afterEach(() => { if (server.listening) { server.close(); } }); }); + +describe("writes debug logs to hidden file", () => { + let a: DevWorker; + let b: DevWorker; + + beforeEach(async () => { + a = await makeWorker(); + await a.seed({ + "wrangler.toml": dedent` + name = "a" + main = "src/index.ts" + compatibility_date = "2023-01-01" + `, + "src/index.ts": dedent/* javascript */ ` + export default { + fetch(req, env) { + return new Response('A' + req.url); + }, + }; + `, + "package.json": dedent` + { + "name": "a", + "version": "0.0.0", + "private": true + } + `, + }); + + b = await makeWorker(); + await b.seed({ + "wrangler.toml": dedent` + name = "b" + main = "src/index.ts" + compatibility_date = "2023-01-01" + `, + "src/index.ts": dedent/* javascript */ ` + export default { + fetch(req, env) { + return new Response('B' + req.url); + }, + }; + `, + "package.json": dedent` + { + "name": "b", + "version": "0.0.0", + "private": true + } + `, + }); + }); + + it("writes to file when --log-level = debug", async () => { + const finalA = await a.runDevSession( + "--log-level debug", + async (session) => { + await waitForPortToBeBound(session.port); + + await waitUntilOutputContains(session, "🐛 Writing debug logs to"); + + await setTimeout(1000); // wait a bit to ensure the file is written to disk + } + ); + + const filepath = finalA.stdout.match( + /🐛 Writing debug logs to "(.+\.log)"/ + )?.[1]; + assert(filepath); + + expect(existsSync(filepath)).toBe(true); + }); + + it("does NOT write to file when --log-level != debug", async () => { + const finalA = await a.runDevSession("", async (session) => { + await waitForPortToBeBound(session.port); + + await setTimeout(1000); // wait a bit to ensure no debug logs are written + }); + + const filepath = finalA.stdout.match( + /🐛 Writing debug logs to "(.+\.log)"/ + )?.[1]; + + expect(filepath).toBeUndefined(); + }); + + it("rewrites address-in-use error logs", async () => { + // 1. start worker A on a (any) port + await a.runDevSession("", async (sessionA) => { + const normalize = (text: string) => + normalizeOutput(text, { [sessionA.port]: "" }); + + // 2. wait until worker A is bound to its port + await waitForPortToBeBound(sessionA.port); + + // 3. try to start worker B on the same port + await b.runDevSession(`--port ${sessionA.port}`, async (sessionB) => { + // 4. wait until wrangler tries to start workerd + await waitUntilOutputContains(sessionB, "Starting local server..."); + // 5. wait a period of time for workerd to complain about the port being in use + await setTimeout(1000); + + // ensure the workerd error message IS NOT present + expect(normalize(sessionB.stderr)).not.toContain( + "Address already in use; toString() = " + ); + // ensure the wrangler (nicer) error message IS present + expect(normalize(sessionB.stderr)).toContain( + "[ERROR] Address already in use" + ); + }); + }); + }); +}); diff --git a/packages/wrangler/e2e/helpers/normalize.ts b/packages/wrangler/e2e/helpers/normalize.ts index 6ca994f17441..715a98213153 100644 --- a/packages/wrangler/e2e/helpers/normalize.ts +++ b/packages/wrangler/e2e/helpers/normalize.ts @@ -18,6 +18,8 @@ export function normalizeOutput( removeTimestamp, stripDevTimings, stripEmptyNewlines, + normalizeDebugLogFilepath, + squashLocalNetworkBindings, ]; for (const f of functions) { stdout = f(stdout); @@ -131,3 +133,23 @@ function replaceByte(stdout: string): string { export function normalizeTempDirs(stdout: string): string { return stdout.replaceAll(/\/\/.+\/wrangler-smoke-.+/g, "//tmpdir"); } + +/** + * Debug log files are created with a timestamp, so we replace the debug log filepath timestamp with + */ +export function normalizeDebugLogFilepath(stdout: string): string { + return stdout.replace( + /(🐛 Writing debug logs to ".+wrangler-debug)-.+\.log/, + "$1-.log" + ); +} + +/** + * Squash the one or more local network bindings from `$ wrangler dev` + */ +export function squashLocalNetworkBindings(stdout: string): string { + return stdout.replace( + /(\[mf:inf\] Ready on http:\/\/.+:\d{4,5})(\n\[mf:inf\] - http:\/\/.+:\d{4,5})+/, + "[mf:inf] Ready on http://:\n[mf:inf] - http://:" + ); +} diff --git a/packages/wrangler/e2e/helpers/retry.ts b/packages/wrangler/e2e/helpers/retry.ts index d749998b6322..bc0e5025d001 100644 --- a/packages/wrangler/e2e/helpers/retry.ts +++ b/packages/wrangler/e2e/helpers/retry.ts @@ -1,8 +1,10 @@ import { setTimeout } from "node:timers/promises"; +type MaybePromise = T | Promise; + export async function retry( retryIf: (currentState: T) => boolean, - action: () => Promise, + action: () => MaybePromise, n = 30 ): Promise { const states: T[] = []; diff --git a/packages/wrangler/scripts/deps.ts b/packages/wrangler/scripts/deps.ts index bf86b0dd4e0a..493a7c313070 100644 --- a/packages/wrangler/scripts/deps.ts +++ b/packages/wrangler/scripts/deps.ts @@ -1,6 +1,5 @@ import fs from "node:fs"; import path from "node:path"; -import { parsePackageJSON } from "../src/parse"; /** * Dependencies that _are not_ bundled along with wrangler @@ -20,10 +19,7 @@ export const EXTERNAL_DEPENDENCIES = [ const pathToPackageJson = path.resolve(__dirname, "..", "package.json"); const packageJson = fs.readFileSync(pathToPackageJson, { encoding: "utf-8" }); -const { dependencies, devDependencies } = parsePackageJSON( - packageJson, - pathToPackageJson -); +const { dependencies, devDependencies } = JSON.parse(packageJson); /** * Dependencies that _are_ bundled along with wrangler diff --git a/packages/wrangler/src/__tests__/dev.test.tsx b/packages/wrangler/src/__tests__/dev.test.tsx index 557b7e94d505..d38b9f20777f 100644 --- a/packages/wrangler/src/__tests__/dev.test.tsx +++ b/packages/wrangler/src/__tests__/dev.test.tsx @@ -1453,12 +1453,6 @@ describe("wrangler dev", () => { } `); }); - - it("should not output Errors with log-level error", async () => { - fs.writeFileSync("index.js", `export default {};`); - await runWrangler("dev index.js --inspect --log-level debug"); - expect(std.debug.length > 1).toBe(true); - }); }); describe("service bindings", () => { diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index ea3426227bf9..3e8412c23942 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -37,6 +37,7 @@ import type { Response, } from "miniflare"; import type { Abortable } from "node:events"; +import type { Readable } from "node:stream"; // This worker proxies all external Durable Objects to the Wrangler session // where they're defined, and receives all requests from other Wrangler sessions @@ -388,6 +389,85 @@ function buildSitesOptions({ assetPaths }: ConfigBundle) { } } +function handleRuntimeStdio(stdout: Readable, stderr: Readable) { + // ASSUMPTION: each chunk is a whole message from workerd + // This may not hold across OSes/architectures, but it seems to work on macOS M-line + // I'm going with this simple approach to avoid complicating this too early + // We can iterate on this heuristic in the future if it causes issues + const classifiers = { + // Is this chunk a big chonky barf from workerd that we want to hijack to cleanup/ignore? + isBarf(chunk: string) { + const containsLlvmSymbolizerWarning = chunk.includes( + "Not symbolizing stack traces because $LLVM_SYMBOLIZER is not set" + ); + const containsHexStack = /stack:( [a-f\d]{9}){3,}/.test(chunk); + + return containsLlvmSymbolizerWarning || containsHexStack; + }, + // Is this chunk an Address In Use error? + isAddressInUse(chunk: string) { + return chunk.includes("Address already in use; toString() = "); + }, + }; + + stdout.on("data", (chunk: Buffer | string) => { + chunk = chunk.toString().trim(); + + if (classifiers.isBarf(chunk)) { + // this is a big chonky barf from workerd that we want to hijack to cleanup/ignore + + // CLEANABLE: + // there are no known cases to cleanup yet + // but, as they are identified, we will do that here + + // IGNORABLE: + // anything else not handled above is considered ignorable + // so send it to the debug logs which are discarded unless + // the user explicitly sets a logLevel indicating they care + logger.debug(chunk); + } + + // anything not exlicitly handled above should be logged as info (via stdout) + else { + logger.info(chunk); + } + }); + + stderr.on("data", (chunk: Buffer | string) => { + chunk = chunk.toString().trim(); + + if (classifiers.isBarf(chunk)) { + // this is a big chonky barf from workerd that we want to hijack to cleanup/ignore + + // CLEANABLE: + // known case to cleanup: Address in use errors + if (classifiers.isAddressInUse(chunk)) { + const address = chunk.match( + /Address already in use; toString\(\) = (.+)\n/ + )?.[1]; + + logger.error( + `Address already in use (${address}). Please check that you are not already running a server on this address or specify a different port with --port.` + ); + + // even though we've intercepted the chunk and logged a better error to stderr + // fallthrough to log the original chunk to the debug log file for observability + } + + // IGNORABLE: + // anything else not handled above is considered ignorable + // so send it to the debug logs which are discarded unless + // the user explicitly sets a logLevel indicating they care + logger.debug(chunk); + } + + // anything not exlicitly handled above should be logged as an error (via stderr) + else { + logger.error(chunk); + } + }); +} + async function buildMiniflareOptions( log: Log, config: ConfigBundle @@ -425,6 +505,7 @@ async function buildMiniflareOptions( log, verbose: logger.loggerLevel === "debug", + handleRuntimeStdio, ...httpsOptions, ...persistOptions, diff --git a/packages/wrangler/src/environment-variables/factory.ts b/packages/wrangler/src/environment-variables/factory.ts index 1975e7764449..658ccff593c6 100644 --- a/packages/wrangler/src/environment-variables/factory.ts +++ b/packages/wrangler/src/environment-variables/factory.ts @@ -15,6 +15,7 @@ type VariableNames = | "WRANGLER_CF_AUTHORIZATION_TOKEN" | "WRANGLER_CLIENT_ID" | "WRANGLER_LOG" + | "WRANGLER_LOG_PATH" | "WRANGLER_REVOKE_URL" | "WRANGLER_SEND_METRICS" | "WRANGLER_TOKEN_URL"; diff --git a/packages/wrangler/src/logger.ts b/packages/wrangler/src/logger.ts index 92e9092ed584..1932a8a9ff84 100644 --- a/packages/wrangler/src/logger.ts +++ b/packages/wrangler/src/logger.ts @@ -3,6 +3,7 @@ import chalk from "chalk"; import CLITable from "cli-table3"; import { formatMessagesSync } from "esbuild"; import { getEnvironmentVariableFactory } from "./environment-variables/factory"; +import { appendToDebugLogFile } from "./utils/debug-log-file"; import type { Message } from "esbuild"; export const LOGGER_LEVELS = { none: -1, @@ -72,8 +73,17 @@ export class Logger { } private doLog(messageLevel: Exclude, args: unknown[]) { + const message = this.formatMessage(messageLevel, format(...args)); + + // unless in unit-tests, send ALL logs to the debug log file (even non-debug logs for context & order) + const inUnitTests = typeof jest !== "undefined"; + if (!inUnitTests) { + void appendToDebugLogFile(messageLevel, message); + } + + // only send logs to the terminal if their level is at least the configured log-level if (LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS[messageLevel]) { - console[messageLevel](this.formatMessage(messageLevel, format(...args))); + console[messageLevel](message); } } diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts new file mode 100644 index 000000000000..980b40887590 --- /dev/null +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -0,0 +1,90 @@ +import { appendFile, mkdir, readFile } from "node:fs/promises"; +import path from "node:path"; +import { Mutex } from "miniflare"; +import onExit from "signal-exit"; +import { findWranglerToml } from "../config"; +import { getEnvironmentVariableFactory } from "../environment-variables/factory"; +import { logger, type LoggerLevel } from "../logger"; + +const getDebugFileDir = getEnvironmentVariableFactory({ + variableName: "WRANGLER_LOG_PATH", + defaultValue() { + const configPath = findWranglerToml(); + const configDir = configPath ? path.dirname(configPath) : process.cwd(); + + return path.join(configDir, ".wrangler", "logs"); + }, +}); + +function getDebugFilepath() { + const dir = getDebugFileDir(); + + const date = new Date() + .toISOString() + .replaceAll(":", "-") + .replace(".", "_") + .replace("T", "_") + .replace("Z", ""); + + const filepath = dir.endsWith(".log") + ? dir // allow the user to provide an exact filepath + : path.join(dir, `wrangler-${date}.log`); + + // use path.resolve to allow the user-provided env var to be a relative path + return path.resolve(filepath); +} + +async function ensureDirectoryExists(filepath: string) { + const dirpath = path.dirname(filepath); + + await mkdir(dirpath, { recursive: true }); +} + +export const debugLogFilepath = getDebugFilepath(); +const mutex = new Mutex(); + +let hasLoggedLocation = false; +let hasLoggedError = false; + +/** + * Appends a message to the log file after waiting for pending writes to complete + */ +export async function appendToDebugLogFile( + messageLevel: LoggerLevel, + message: string +) { + const entry = ` +--- ${new Date().toISOString()} ${messageLevel} +${message} +--- +`; + + if (!hasLoggedLocation) { + hasLoggedLocation = true; + const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); + logger.debug(`🐛 Writing logs to "${relativeFilepath}"`); // use logger.debug here to not show this message by default -- since logging to a file is no longer opt-in + onExit(() => { + console.info(`🐛 Logs were written to "${relativeFilepath}"`); + }); + } + + await mutex.runWith(async () => { + try { + await ensureDirectoryExists(debugLogFilepath); + await appendFile(debugLogFilepath, entry); + } catch (err) { + if (!hasLoggedError) { + hasLoggedError = true; + console.error(`Failed to write to log file`, err); + console.error(`Would have written:`, entry); + } + } + }); +} + +/** + * Reads the current log file after waiting for all pending writes + */ +export function readDebugLogFile(): Promise { + return mutex.runWith(() => readFile(debugLogFilepath, "utf-8")); +}