From edc9754bd82565174012761c44ec523289d92817 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 3 Nov 2023 14:35:34 +0000 Subject: [PATCH 01/29] don't rethrow errors in miniflare Log class when the log level means it won't be logged --- packages/miniflare/src/shared/log.ts | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/packages/miniflare/src/shared/log.ts b/packages/miniflare/src/shared/log.ts index d4fddcbcbe09..26861108ab81 100644 --- a/packages/miniflare/src/shared/log.ts +++ b/packages/miniflare/src/shared/log.ts @@ -76,10 +76,9 @@ export class Log { } } - error(message: Error): void { - if (this.level < LogLevel.ERROR) { - // Rethrow message if it won't get logged - throw message; + error(message: Error): void { + if (this.level < LogLevel.ERROR) { + // 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); From f0576d7ce7aad5f34da5fba119b871a246d984cc Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 3 Nov 2023 17:19:30 +0000 Subject: [PATCH 02/29] expose miniflare option: handleRuntimeStdio allowing wrangler to decide whether workerd logs should reach the terminal --- packages/miniflare/src/index.ts | 1 + packages/miniflare/src/plugins/core/index.ts | 7 +++++++ packages/miniflare/src/runtime/index.ts | 17 +++++++++-------- 3 files changed, 17 insertions(+), 8 deletions(-) diff --git a/packages/miniflare/src/index.ts b/packages/miniflare/src/index.ts index b160110853fc..d5ae7128ed31 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..146d9b33803a 100644 --- a/packages/miniflare/src/plugins/core/index.ts +++ b/packages/miniflare/src/plugins/core/index.ts @@ -51,6 +51,7 @@ import { withSourceURL, } from "./modules"; import { ServiceDesignatorSchema } from "./services"; +import { Readable } from "stream"; // `workerd`'s `trustBrowserCas` should probably be named `trustSystemCas`. // Rather than using a bundled CA store like Node, it uses @@ -137,6 +138,12 @@ 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..fa4d4345c95f 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); From ce37b6f627f4aea6d7a916177cec3f987e23134b Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 3 Nov 2023 19:09:58 +0000 Subject: [PATCH 03/29] intercept workerd logs in wrangler --- packages/wrangler/src/dev/miniflare.ts | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index ea3426227bf9..3363f3d91dbd 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -425,6 +425,17 @@ async function buildMiniflareOptions( log, verbose: logger.loggerLevel === "debug", + handleRuntimeStdio: (stdout, stderr) => { + stdout.on("data", (chunk) => { + // TODO: with some conditional heuristic, call log.debug instead of log.info + log.info(chunk.toString()); + }); + + stderr.on("data", (chunk) => { + // TODO: with some conditional heuristic, call log.debug instead of log.error + log.error(chunk.toString()); + }); + }, ...httpsOptions, ...persistOptions, From 601987ef47371b60e2174da14e2b7691f7f73540 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 3 Nov 2023 20:40:30 +0000 Subject: [PATCH 04/29] write all debug logs to a .wrangler/*.log file --- .../src/environment-variables/factory.ts | 1 + packages/wrangler/src/logger.ts | 6 +++ packages/wrangler/src/utils/debug-log-file.ts | 50 +++++++++++++++++++ 3 files changed, 57 insertions(+) create mode 100644 packages/wrangler/src/utils/debug-log-file.ts diff --git a/packages/wrangler/src/environment-variables/factory.ts b/packages/wrangler/src/environment-variables/factory.ts index 1975e7764449..0e5be3a9a41f 100644 --- a/packages/wrangler/src/environment-variables/factory.ts +++ b/packages/wrangler/src/environment-variables/factory.ts @@ -14,6 +14,7 @@ type VariableNames = | "WRANGLER_C3_COMMAND" | "WRANGLER_CF_AUTHORIZATION_TOKEN" | "WRANGLER_CLIENT_ID" + | "WRANGLER_DEBUG_LOG" | "WRANGLER_LOG" | "WRANGLER_REVOKE_URL" | "WRANGLER_SEND_METRICS" diff --git a/packages/wrangler/src/logger.ts b/packages/wrangler/src/logger.ts index 92e9092ed584..583db8a241f4 100644 --- a/packages/wrangler/src/logger.ts +++ b/packages/wrangler/src/logger.ts @@ -4,6 +4,7 @@ import CLITable from "cli-table3"; import { formatMessagesSync } from "esbuild"; import { getEnvironmentVariableFactory } from "./environment-variables/factory"; import type { Message } from "esbuild"; +import { appendToDebugLogFile } from "./utils/debug-log-file"; export const LOGGER_LEVELS = { none: -1, error: 0, @@ -73,6 +74,11 @@ export class Logger { private doLog(messageLevel: Exclude, args: unknown[]) { if (LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS[messageLevel]) { + if (messageLevel === "debug") { + appendToDebugLogFile(...args); + return; + } + console[messageLevel](this.formatMessage(messageLevel, format(...args))); } } 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..7fe5a0fc8207 --- /dev/null +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -0,0 +1,50 @@ +import path from "node:path"; +import { format } from "node:util"; +import { appendFile } from "node:fs/promises"; +import { getEnvironmentVariableFactory } from "../environment-variables/factory"; +import { getBasePath } from "../paths"; +import { logger } from "../logger"; + +const getDebugFilepath = getEnvironmentVariableFactory({ + variableName: "WRANGLER_DEBUG_LOG", + defaultValue: () => { + const date = new Date() + .toISOString() + .replaceAll(":", "-") + .replace(".", "_") + .replace("T", "_") + .replace("Z", ""); + const absoluteFilepath = path.join( + getBasePath(), + ".wrangler", + `wrangler-debug-${date}.log` + ); + const relativeFilepath = path.relative(process.cwd(), absoluteFilepath); + + return relativeFilepath; + }, +}); + +const debugLogFilepath = getDebugFilepath(); + +let hasLoggedLocation = false; +let hasLoggedError = false; + +export function appendToDebugLogFile(...args: unknown[]) { + const entry = ` +--- ${new Date().toISOString()} +${format(...args)} +--- +`; + + appendFile(debugLogFilepath, entry).catch((err) => { + if (hasLoggedError) return; + hasLoggedError = true; + logger.error(`Failed to write to debug log file`, err); + }); + + if (hasLoggedLocation) return; + hasLoggedLocation = true; + logger.info(`🐛 Writing debug logs to "${debugLogFilepath}"`); + // TODO: move this into an exit hook so it isn't the first thing logged +} From 4e5fbbc8b527716f709d45d94682a175533afa9b Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 6 Nov 2023 14:25:58 +0000 Subject: [PATCH 05/29] initial heuristic to cleanup workerd logs --- packages/wrangler/src/dev/miniflare.ts | 86 ++++++++++++++++++++++---- 1 file changed, 75 insertions(+), 11 deletions(-) diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 3363f3d91dbd..316d9fccfdea 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 { 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,79 @@ 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) { + return chunk.includes( + "Not symbolizing stack traces because $LLVM_SYMBOLIZER is not set" + ); + }, + // 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(); + + 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(); + + 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 (${address}) already in use. Please check that you are not already running a server on this address or specify a different port with --port.` + ); + } + + // 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,17 +499,7 @@ async function buildMiniflareOptions( log, verbose: logger.loggerLevel === "debug", - handleRuntimeStdio: (stdout, stderr) => { - stdout.on("data", (chunk) => { - // TODO: with some conditional heuristic, call log.debug instead of log.info - log.info(chunk.toString()); - }); - - stderr.on("data", (chunk) => { - // TODO: with some conditional heuristic, call log.debug instead of log.error - log.error(chunk.toString()); - }); - }, + handleRuntimeStdio, ...httpsOptions, ...persistOptions, From 232936855457d5b051aa056cf16405427076036d Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 6 Nov 2023 14:47:11 +0000 Subject: [PATCH 06/29] chore: remove wrangler deps from wrangler's build importing parsePackageJSON relies on esbuild `define` replacements --- packages/wrangler/scripts/deps.ts | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) 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 From b4e09b1a3fefbc1f9c83180faa54e040bacff6d0 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 6 Nov 2023 17:12:35 +0000 Subject: [PATCH 07/29] update heuristic to check for hex stack output --- packages/wrangler/src/dev/miniflare.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 316d9fccfdea..227f3bdde537 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -397,9 +397,12 @@ function handleRuntimeStdio(stdout: Readable, stderr: Readable) { const classifiers = { // Is this chunk a big chonky barf from workerd that we want to hijack to cleanup/ignore? isBarf(chunk: string) { - return chunk.includes( + 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) { From 5f4705b26132e9bc9a41f68c5fc7cab0705b94cc Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Thu, 9 Nov 2023 17:38:44 +0000 Subject: [PATCH 08/29] add tests --- packages/wrangler/e2e/dev.test.ts | 252 +++++++++++++++++++-- packages/wrangler/e2e/helpers/normalize.ts | 11 + packages/wrangler/src/dev/miniflare.ts | 2 + 3 files changed, 244 insertions(+), 21 deletions(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index aa8fd136145c..ee83347c5a69 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"; @@ -9,26 +11,75 @@ import { afterEach, beforeEach, describe, expect, it } from "vitest"; import { retry } from "./helpers/retry"; import { dedent, makeRoot, seed } from "./helpers/setup"; import { WRANGLER } from "./helpers/wrangler-command"; +import { normalizeOutput } from "./helpers/normalize"; + +type MaybePromise = T | Promise; + +const waitForPortToBeBound = async (port: number) => { + await retry( + (s) => false, // only retry if promise below rejects (network error) + () => fetch(`http://127.0.0.1:${port}`) + ); +}; + +const waitUntil = async ( + predicate: () => MaybePromise, + intervalMs = 100 +) => { + await retry( + (result) => !result, + async () => { + await setTimeout(intervalMs); + return predicate(); + } + ); +}; + +interface Session { + port: number; + stdout: string; + stderr: string; +} async function runDevSession( workerPath: string, flags: string, - session: (port: number) => Promise + session: (session: Session) => MaybePromise ) { let pid; try { - const port = await getPort(); + let port: number; + if (!flags.includes("--port")) { + port = await getPort(); + flags += ` --port ${port}`; + } else { + port = parseInt(flags.match(/--port (\d+)/)![1]); + + if (port === 0) port = await getPort(); + } + // 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: Session = { + 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 +91,7 @@ type DevWorker = { workerPath: string; runDevSession: ( flags: string, - session: (port: number) => Promise + session: (session: Session) => MaybePromise ) => ReturnType; seed: ( seeder: ((name: string) => Record) | Record @@ -56,8 +107,10 @@ async function makeWorker(): Promise { return { workerName, workerPath, - runDevSession: (flags: string, session: (port: number) => Promise) => - runDevSession(workerPath, flags, session), + runDevSession: ( + flags: string, + session: (session: Session) => MaybePromise + ) => runDevSession(workerPath, flags, session), seed: (seeder) => seed( workerPath, @@ -97,11 +150,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 +172,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 +191,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 +200,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 +226,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 +291,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 +305,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 +317,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 +350,7 @@ describe("hyperdrive dev tests", () => { name = "${workerName}" main = "src/index.ts" compatibility_date = "2023-10-25" - + [[hyperdrive]] binding = "HYPERDRIVE" id = "hyperdrive_id" @@ -364,9 +418,165 @@ describe("hyperdrive dev tests", () => { }); 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 () => { + await a.runDevSession("--log-level debug", async (session) => { + const normalize = (text: string) => + normalizeOutput(text, { [session.port]: "" }); + + await waitForPortToBeBound(session.port); + + await waitUntil(() => session.stdout.includes("🐛")); + + const filepath = session.stdout.match( + /🐛 Writing debug logs to "(.+\.log)"/ + )?.[1]; + assert(filepath); + + expect(existsSync(filepath)).toBe(true); + + expect(normalize(session.stdout)).toMatchInlineSnapshot(` + "🐛 Writing debug logs to \\"../../../../../../../../Users/sethi/code/workers-sdk/packages/wrangler/.wrangler/wrangler-debug-.log\\" + ⎔ Starting local server... + [mf:inf] Ready on http://0.0.0.0: + [mf:inf] - http://127.0.0.1: + [mf:inf] - http://127.0.2.2: + [mf:inf] - http://127.0.2.3: + [mf:inf] - http://172.16.29.60: + [mf:inf] GET / 200 OK (TIMINGS) + " + `); + expect(normalize(session.stderr)).toMatchInlineSnapshot(` + "X [ERROR] workerd/server/server.c++:2984: info: Inspector is listening + X [ERROR] workerd/server/server.c++:1174: info: Inspector client attaching [core:user:a] + " + `); + }); + }); + + it("does NOT write to file when --log-level != debug", async () => { + await a.runDevSession("", async (session) => { + const normalize = (text: string) => + normalizeOutput(text, { [session.port]: "" }); + + await waitForPortToBeBound(session.port); + + const filepath = session.stdout.match( + /🐛 Writing debug logs to "(.+\.log)"/ + )?.[1]; + + expect(filepath).toBeUndefined(); + + expect(normalize(session.stdout)).toMatchInlineSnapshot(` + "⎔ Starting local server... + [mf:inf] Ready on http://0.0.0.0: + [mf:inf] - http://127.0.0.1: + [mf:inf] - http://127.0.2.2: + [mf:inf] - http://127.0.2.3: + [mf:inf] - http://172.16.29.60: + " + `); + expect(normalize(session.stderr)).toMatchInlineSnapshot('""'); + }); + }); + + 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 session B emits an "Address in use" error log + await waitUntil(() => + normalize(sessionB.stderr).includes( + "[ERROR] Address (0.0.0.0:) already in use." + ) + ); + + // ensure the workerd error message IS NOT present + expect(normalize(sessionB.stderr)).not.toContain( + "Address already in use; toString() = " + ); + // ensure th wrangler (nicer) error message IS present + expect(normalize(sessionB.stderr)).toContain( + "[ERROR] Address (0.0.0.0:) already in use." + ); + + // snapshot stdout/stderr so we can see what the user sees + expect(normalize(sessionB.stdout)).toMatchInlineSnapshot(` + "⎔ Starting local server... + " + `); + expect(normalize(sessionB.stderr)).toMatchInlineSnapshot(` + "X [ERROR] Address (0.0.0.0:) already in use. Please check that you are not already running a server on this address or specify a different port with --port. + X [ERROR] MiniflareCoreError [ERR_RUNTIME_FAILURE]: The Workers runtime failed to start. There is likely additional logging output above. + " + `); + }); + }); + }); +}); diff --git a/packages/wrangler/e2e/helpers/normalize.ts b/packages/wrangler/e2e/helpers/normalize.ts index 6ca994f17441..90f56defa9e9 100644 --- a/packages/wrangler/e2e/helpers/normalize.ts +++ b/packages/wrangler/e2e/helpers/normalize.ts @@ -18,6 +18,7 @@ export function normalizeOutput( removeTimestamp, stripDevTimings, stripEmptyNewlines, + normalizeDebugLogFilepath, ]; for (const f of functions) { stdout = f(stdout); @@ -131,3 +132,13 @@ 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" + ); +} diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 227f3bdde537..f639a1e4a93d 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -449,6 +449,8 @@ function handleRuntimeStdio(stdout: Readable, stderr: Readable) { logger.error( `Address (${address}) already in use. Please check that you are not already running a server on this address or specify a different port with --port.` ); + + return; } // IGNORABLE: From c2b2ebe1b17720fc2d6e856cd89f6046c0ce9a93 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Thu, 9 Nov 2023 17:50:23 +0000 Subject: [PATCH 09/29] protect appendFile calls with mutex --- packages/wrangler/src/utils/debug-log-file.ts | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index 7fe5a0fc8207..cef849ebdd8f 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -4,6 +4,7 @@ import { appendFile } from "node:fs/promises"; import { getEnvironmentVariableFactory } from "../environment-variables/factory"; import { getBasePath } from "../paths"; import { logger } from "../logger"; +import { Mutex } from "miniflare"; const getDebugFilepath = getEnvironmentVariableFactory({ variableName: "WRANGLER_DEBUG_LOG", @@ -26,22 +27,25 @@ const getDebugFilepath = getEnvironmentVariableFactory({ }); const debugLogFilepath = getDebugFilepath(); +const mutex = new Mutex(); let hasLoggedLocation = false; let hasLoggedError = false; -export function appendToDebugLogFile(...args: unknown[]) { +export async function appendToDebugLogFile(...args: unknown[]) { const entry = ` --- ${new Date().toISOString()} ${format(...args)} --- `; - appendFile(debugLogFilepath, entry).catch((err) => { - if (hasLoggedError) return; - hasLoggedError = true; - logger.error(`Failed to write to debug log file`, err); - }); + await mutex.runWith(() => + appendFile(debugLogFilepath, entry).catch((err) => { + if (hasLoggedError) return; + hasLoggedError = true; + logger.error(`Failed to write to debug log file`, err); + }) + ); if (hasLoggedLocation) return; hasLoggedLocation = true; From c06b828d8c6072ce8214e3e399ca9e0c11c979a2 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 10 Nov 2023 15:54:51 +0000 Subject: [PATCH 10/29] normalise stdout bound local network addresses --- packages/wrangler/e2e/dev.test.ts | 143 ++++++++++----------- packages/wrangler/e2e/helpers/normalize.ts | 11 ++ 2 files changed, 81 insertions(+), 73 deletions(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index ee83347c5a69..f80e9313998e 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -479,64 +479,58 @@ describe("writes debug logs to hidden file", () => { }); it("writes to file when --log-level = debug", async () => { - await a.runDevSession("--log-level debug", async (session) => { - const normalize = (text: string) => - normalizeOutput(text, { [session.port]: "" }); - - await waitForPortToBeBound(session.port); + const finalA = await a.runDevSession( + "--log-level debug", + async (session) => { + await waitForPortToBeBound(session.port); - await waitUntil(() => session.stdout.includes("🐛")); - - const filepath = session.stdout.match( - /🐛 Writing debug logs to "(.+\.log)"/ - )?.[1]; - assert(filepath); - - expect(existsSync(filepath)).toBe(true); - - expect(normalize(session.stdout)).toMatchInlineSnapshot(` - "🐛 Writing debug logs to \\"../../../../../../../../Users/sethi/code/workers-sdk/packages/wrangler/.wrangler/wrangler-debug-.log\\" - ⎔ Starting local server... - [mf:inf] Ready on http://0.0.0.0: - [mf:inf] - http://127.0.0.1: - [mf:inf] - http://127.0.2.2: - [mf:inf] - http://127.0.2.3: - [mf:inf] - http://172.16.29.60: - [mf:inf] GET / 200 OK (TIMINGS) - " - `); - expect(normalize(session.stderr)).toMatchInlineSnapshot(` - "X [ERROR] workerd/server/server.c++:2984: info: Inspector is listening - X [ERROR] workerd/server/server.c++:1174: info: Inspector client attaching [core:user:a] - " - `); - }); + await waitUntil(() => session.stdout.includes("🐛")); + } + ); + + const filepath = finalA.stdout.match( + /🐛 Writing debug logs to "(.+\.log)"/ + )?.[1]; + assert(filepath); + + expect(existsSync(filepath)).toBe(true); + + expect(normalizeOutput(finalA.stdout)).toMatchInlineSnapshot(` + "🐛 Writing debug logs to \\"../../../../../../../../Users/sethi/code/workers-sdk/packages/wrangler/.wrangler/wrangler-debug-.log\\" + ⎔ Starting local server... + [mf:inf] Ready on http://: + [mf:inf] - http://: + [mf:inf] GET / 200 OK (TIMINGS) + " + `); + expect(normalizeOutput(finalA.stderr)).toMatchInlineSnapshot(` + "X [ERROR] workerd/server/server.c++:2984: info: Inspector is listening + X [ERROR] workerd/server/server.c++:1174: info: Inspector client attaching [core:user:a] + " + `); }); it("does NOT write to file when --log-level != debug", async () => { - await a.runDevSession("", async (session) => { + const finalA = await a.runDevSession("", async (session) => { const normalize = (text: string) => normalizeOutput(text, { [session.port]: "" }); await waitForPortToBeBound(session.port); + }); - const filepath = session.stdout.match( - /🐛 Writing debug logs to "(.+\.log)"/ - )?.[1]; + const filepath = finalA.stdout.match( + /🐛 Writing debug logs to "(.+\.log)"/ + )?.[1]; - expect(filepath).toBeUndefined(); + expect(filepath).toBeUndefined(); - expect(normalize(session.stdout)).toMatchInlineSnapshot(` - "⎔ Starting local server... - [mf:inf] Ready on http://0.0.0.0: - [mf:inf] - http://127.0.0.1: - [mf:inf] - http://127.0.2.2: - [mf:inf] - http://127.0.2.3: - [mf:inf] - http://172.16.29.60: - " - `); - expect(normalize(session.stderr)).toMatchInlineSnapshot('""'); - }); + expect(normalizeOutput(finalA.stdout)).toMatchInlineSnapshot(` + "⎔ Starting local server... + [mf:inf] Ready on http://: + [mf:inf] - http://: + " + `); + expect(normalizeOutput(finalA.stderr)).toMatchInlineSnapshot('""'); }); it("rewrites address-in-use error logs", async () => { @@ -549,34 +543,37 @@ describe("writes debug logs to hidden file", () => { 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 session B emits an "Address in use" error log - await waitUntil(() => - normalize(sessionB.stderr).includes( - "[ERROR] Address (0.0.0.0:) already in use." - ) - ); + const finalB = await b.runDevSession( + `--port ${sessionA.port}`, + async (sessionB) => { + // 4. wait until session B emits an "Address in use" error log + await waitUntil(() => + normalize(sessionB.stderr).includes( + "[ERROR] Address (0.0.0.0:) already in use." + ) + ); + } + ); - // ensure the workerd error message IS NOT present - expect(normalize(sessionB.stderr)).not.toContain( - "Address already in use; toString() = " - ); - // ensure th wrangler (nicer) error message IS present - expect(normalize(sessionB.stderr)).toContain( - "[ERROR] Address (0.0.0.0:) already in use." - ); + // ensure the workerd error message IS NOT present + expect(normalize(finalB.stderr)).not.toContain( + "Address already in use; toString() = " + ); + // ensure th wrangler (nicer) error message IS present + expect(normalize(finalB.stderr)).toContain( + "[ERROR] Address (0.0.0.0:) already in use." + ); - // snapshot stdout/stderr so we can see what the user sees - expect(normalize(sessionB.stdout)).toMatchInlineSnapshot(` - "⎔ Starting local server... - " - `); - expect(normalize(sessionB.stderr)).toMatchInlineSnapshot(` - "X [ERROR] Address (0.0.0.0:) already in use. Please check that you are not already running a server on this address or specify a different port with --port. - X [ERROR] MiniflareCoreError [ERR_RUNTIME_FAILURE]: The Workers runtime failed to start. There is likely additional logging output above. - " - `); - }); + // snapshot stdout/stderr so we can see what the user sees + expect(normalize(finalB.stdout)).toMatchInlineSnapshot(` + "⎔ Starting local server... + " + `); + expect(normalize(finalB.stderr)).toMatchInlineSnapshot(` + "X [ERROR] Address (0.0.0.0:) already in use. Please check that you are not already running a server on this address or specify a different port with --port. + X [ERROR] MiniflareCoreError [ERR_RUNTIME_FAILURE]: The Workers runtime failed to start. There is likely additional logging output above. + " + `); }); }); }); diff --git a/packages/wrangler/e2e/helpers/normalize.ts b/packages/wrangler/e2e/helpers/normalize.ts index 90f56defa9e9..715a98213153 100644 --- a/packages/wrangler/e2e/helpers/normalize.ts +++ b/packages/wrangler/e2e/helpers/normalize.ts @@ -19,6 +19,7 @@ export function normalizeOutput( stripDevTimings, stripEmptyNewlines, normalizeDebugLogFilepath, + squashLocalNetworkBindings, ]; for (const f of functions) { stdout = f(stdout); @@ -142,3 +143,13 @@ export function normalizeDebugLogFilepath(stdout: string): string { "$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://:" + ); +} From 8767864993f147732134eff4875f023365edae14 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 10 Nov 2023 15:55:34 +0000 Subject: [PATCH 11/29] =?UTF-8?q?trim=20workerd=20stdout/stderr=20chunks?= =?UTF-8?q?=20before=20logging=20doesn't=20actually=20change=20anything=20?= =?UTF-8?q?but=20=F0=9F=A4=B7=E2=80=8D=E2=99=82=EF=B8=8F?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- packages/wrangler/src/dev/miniflare.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index f639a1e4a93d..08935e5648f1 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -411,7 +411,7 @@ function handleRuntimeStdio(stdout: Readable, stderr: Readable) { }; stdout.on("data", (chunk: Buffer | string) => { - chunk = chunk.toString(); + chunk = chunk.toString().trim(); if (classifiers.isBarf(chunk)) { // this is a big chonky barf from workerd that we want to hijack to cleanup/ignore @@ -434,7 +434,7 @@ function handleRuntimeStdio(stdout: Readable, stderr: Readable) { }); stderr.on("data", (chunk: Buffer | string) => { - chunk = chunk.toString(); + chunk = chunk.toString().trim(); if (classifiers.isBarf(chunk)) { // this is a big chonky barf from workerd that we want to hijack to cleanup/ignore From 189020be9356759cb545df2014d5afae5e1fdd9e Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 10 Nov 2023 16:15:02 +0000 Subject: [PATCH 12/29] fix linting --- packages/miniflare/src/index.ts | 2 +- packages/miniflare/src/plugins/core/index.ts | 11 ++++------ packages/miniflare/src/runtime/index.ts | 8 ++++---- packages/miniflare/src/shared/log.ts | 4 ++-- packages/wrangler/e2e/dev.test.ts | 20 +++++++++---------- packages/wrangler/src/dev/miniflare.ts | 2 +- packages/wrangler/src/logger.ts | 4 ++-- packages/wrangler/src/utils/debug-log-file.ts | 6 +++--- 8 files changed, 26 insertions(+), 31 deletions(-) diff --git a/packages/miniflare/src/index.ts b/packages/miniflare/src/index.ts index d5ae7128ed31..fc02e5429e84 100644 --- a/packages/miniflare/src/index.ts +++ b/packages/miniflare/src/index.ts @@ -1129,7 +1129,7 @@ export class Miniflare { requiredSockets, inspectorAddress, verbose: this.#sharedOpts.core.verbose, - handleRuntimeStdio: this.#sharedOpts.core.handleRuntimeStdio, + 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 146d9b33803a..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"; @@ -51,7 +52,6 @@ import { withSourceURL, } from "./modules"; import { ServiceDesignatorSchema } from "./services"; -import { Readable } from "stream"; // `workerd`'s `trustBrowserCas` should probably be named `trustSystemCas`. // Rather than using a bundled CA store like Node, it uses @@ -138,12 +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(), + 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 fa4d4345c95f..621ac87e950a 100644 --- a/packages/miniflare/src/runtime/index.ts +++ b/packages/miniflare/src/runtime/index.ts @@ -33,7 +33,7 @@ export interface RuntimeOptions { requiredSockets: SocketIdentifier[]; inspectorAddress?: string; verbose?: boolean; - handleRuntimeStdio?: (stdout: Readable, stderr: Readable) => void; + handleRuntimeStdio?: (stdout: Readable, stderr: Readable) => void; } async function waitForPorts( @@ -83,8 +83,8 @@ function pipeOutput(stdout: Readable, stderr: Readable) { // https://github.com/vadimdemedes/ink/blob/5d24ed8ada593a6c36ea5416f452158461e33ba5/readme.md#patchconsole // Writing directly to `process.stdout/stderr` would result in graphical // glitches. - rl.createInterface(stdout).on("line", ((data) => console.log(data))); - rl.createInterface(stderr).on("line", ((data) => console.error(red(data)))); + 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); } @@ -144,7 +144,7 @@ export class Runtime { this.#process = runtimeProcess; this.#processExitPromise = waitForExit(runtimeProcess); - const handleRuntimeStdio = options.handleRuntimeStdio ?? pipeOutput; + const handleRuntimeStdio = options.handleRuntimeStdio ?? pipeOutput; handleRuntimeStdio(runtimeProcess.stdout, runtimeProcess.stderr); const controlPipe = runtimeProcess.stdio[3]; diff --git a/packages/miniflare/src/shared/log.ts b/packages/miniflare/src/shared/log.ts index 26861108ab81..cc49efb862b8 100644 --- a/packages/miniflare/src/shared/log.ts +++ b/packages/miniflare/src/shared/log.ts @@ -76,8 +76,8 @@ export class Log { } } - error(message: Error): void { - if (this.level < LogLevel.ERROR) { + error(message: Error): void { + if (this.level < LogLevel.ERROR) { // Ignore message if it won't get logged } else if (message.stack) { // Dim internal stack trace lines to highlight user code diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index f80e9313998e..0af6269f25dd 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -8,16 +8,16 @@ 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"; -import { normalizeOutput } from "./helpers/normalize"; type MaybePromise = T | Promise; const waitForPortToBeBound = async (port: number) => { await retry( - (s) => false, // only retry if promise below rejects (network error) + () => false, // only retry if promise below rejects (network error) () => fetch(`http://127.0.0.1:${port}`) ); }; @@ -35,7 +35,7 @@ const waitUntil = async ( ); }; -interface Session { +interface SessionData { port: number; stdout: string; stderr: string; @@ -44,16 +44,17 @@ interface Session { async function runDevSession( workerPath: string, flags: string, - session: (session: Session) => MaybePromise + session: (sessionData: SessionData) => MaybePromise ) { let pid; try { + const match = flags.match(/--port (\d+)/); let port: number; - if (!flags.includes("--port")) { + if (!match) { port = await getPort(); flags += ` --port ${port}`; } else { - port = parseInt(flags.match(/--port (\d+)/)![1]); + port = parseInt(match[1]); if (port === 0) port = await getPort(); } @@ -91,7 +92,7 @@ type DevWorker = { workerPath: string; runDevSession: ( flags: string, - session: (session: Session) => MaybePromise + session: (sessionData: SessionData) => MaybePromise ) => ReturnType; seed: ( seeder: ((name: string) => Record) | Record @@ -109,7 +110,7 @@ async function makeWorker(): Promise { workerPath, runDevSession: ( flags: string, - session: (session: Session) => MaybePromise + session: (sessionData: SessionData) => MaybePromise ) => runDevSession(workerPath, flags, session), seed: (seeder) => seed( @@ -512,9 +513,6 @@ describe("writes debug logs to hidden file", () => { it("does NOT write to file when --log-level != debug", async () => { const finalA = await a.runDevSession("", async (session) => { - const normalize = (text: string) => - normalizeOutput(text, { [session.port]: "" }); - await waitForPortToBeBound(session.port); }); diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 08935e5648f1..1fd672b053fd 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -37,7 +37,7 @@ import type { Response, } from "miniflare"; import type { Abortable } from "node:events"; -import { Readable } from "node:stream"; +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 diff --git a/packages/wrangler/src/logger.ts b/packages/wrangler/src/logger.ts index 583db8a241f4..541241c367af 100644 --- a/packages/wrangler/src/logger.ts +++ b/packages/wrangler/src/logger.ts @@ -3,8 +3,8 @@ import chalk from "chalk"; import CLITable from "cli-table3"; import { formatMessagesSync } from "esbuild"; import { getEnvironmentVariableFactory } from "./environment-variables/factory"; -import type { Message } from "esbuild"; import { appendToDebugLogFile } from "./utils/debug-log-file"; +import type { Message } from "esbuild"; export const LOGGER_LEVELS = { none: -1, error: 0, @@ -75,7 +75,7 @@ export class Logger { private doLog(messageLevel: Exclude, args: unknown[]) { if (LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS[messageLevel]) { if (messageLevel === "debug") { - appendToDebugLogFile(...args); + void appendToDebugLogFile(...args); return; } diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index cef849ebdd8f..ba6be3053161 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -1,10 +1,10 @@ +import { appendFile } from "node:fs/promises"; import path from "node:path"; import { format } from "node:util"; -import { appendFile } from "node:fs/promises"; +import { Mutex } from "miniflare"; import { getEnvironmentVariableFactory } from "../environment-variables/factory"; -import { getBasePath } from "../paths"; import { logger } from "../logger"; -import { Mutex } from "miniflare"; +import { getBasePath } from "../paths"; const getDebugFilepath = getEnvironmentVariableFactory({ variableName: "WRANGLER_DEBUG_LOG", From 0a429dae59b3258cb930cc7af15173e72b7d5788 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 10 Nov 2023 17:14:38 +0000 Subject: [PATCH 13/29] fix tests --- packages/wrangler/e2e/dev.test.ts | 79 ++++++++++++++++---------- packages/wrangler/e2e/helpers/retry.ts | 4 +- packages/wrangler/src/dev/miniflare.ts | 2 +- 3 files changed, 53 insertions(+), 32 deletions(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index 0af6269f25dd..72e33be07d65 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -35,6 +35,24 @@ const waitUntil = async ( ); }; +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; @@ -71,7 +89,7 @@ async function runDevSession( pid = bg.pid; // sessionData is a mutable object where stdout/stderr update - const sessionData: Session = { + const sessionData: SessionData = { port, stdout: "", stderr: "", @@ -486,6 +504,8 @@ describe("writes debug logs to hidden file", () => { await waitForPortToBeBound(session.port); await waitUntil(() => session.stdout.includes("🐛")); + + await setTimeout(1000); // wait a bit to ensure the file is written to disk } ); @@ -514,6 +534,8 @@ describe("writes debug logs to hidden file", () => { 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( @@ -526,6 +548,7 @@ describe("writes debug logs to hidden file", () => { "⎔ Starting local server... [mf:inf] Ready on http://: [mf:inf] - http://: + [mf:inf] GET / 200 OK (TIMINGS) " `); expect(normalizeOutput(finalA.stderr)).toMatchInlineSnapshot('""'); @@ -541,37 +564,33 @@ describe("writes debug logs to hidden file", () => { await waitForPortToBeBound(sessionA.port); // 3. try to start worker B on the same port - const finalB = await b.runDevSession( - `--port ${sessionA.port}`, - async (sessionB) => { - // 4. wait until session B emits an "Address in use" error log - await waitUntil(() => - normalize(sessionB.stderr).includes( - "[ERROR] Address (0.0.0.0:) already in use." - ) - ); - } - ); + await b.runDevSession(`--port ${sessionA.port}`, async (sessionB) => { + // 4. wait until session B emits an "Address in use" error log + await waitUntilOutputContains( + sessionB, + "[ERROR] Address already in use" + ); - // ensure the workerd error message IS NOT present - expect(normalize(finalB.stderr)).not.toContain( - "Address already in use; toString() = " - ); - // ensure th wrangler (nicer) error message IS present - expect(normalize(finalB.stderr)).toContain( - "[ERROR] Address (0.0.0.0:) already in use." - ); + // 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" + ); - // snapshot stdout/stderr so we can see what the user sees - expect(normalize(finalB.stdout)).toMatchInlineSnapshot(` - "⎔ Starting local server... - " - `); - expect(normalize(finalB.stderr)).toMatchInlineSnapshot(` - "X [ERROR] Address (0.0.0.0:) already in use. Please check that you are not already running a server on this address or specify a different port with --port. - X [ERROR] MiniflareCoreError [ERR_RUNTIME_FAILURE]: The Workers runtime failed to start. There is likely additional logging output above. - " - `); + // snapshot stdout/stderr so we can see what the user sees + expect(normalize(sessionB.stdout)).toMatchInlineSnapshot(` + "⎔ Starting local server... + " + `); + expect(normalize(sessionB.stderr)).toMatchInlineSnapshot(` + "X [ERROR] Address already in use (*:). Please check that you are not already running a server on this address or specify a different port with --port. + X [ERROR] MiniflareCoreError [ERR_RUNTIME_FAILURE]: The Workers runtime failed to start. There is likely additional logging output above. + " + `); + }); }); }); }); 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/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 1fd672b053fd..4e911161f7b1 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -447,7 +447,7 @@ function handleRuntimeStdio(stdout: Readable, stderr: Readable) { )?.[1]; logger.error( - `Address (${address}) already in use. Please check that you are not already running a server on this address or specify a different port with --port.` + `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.` ); return; From 4ab3508cfcaa453c564b7ad7e39b948e5050e678 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 10 Nov 2023 17:21:32 +0000 Subject: [PATCH 14/29] improve observability when waitUntil fails --- packages/wrangler/e2e/dev.test.ts | 15 +-------------- 1 file changed, 1 insertion(+), 14 deletions(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index 72e33be07d65..9b3f54951967 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -22,19 +22,6 @@ const waitForPortToBeBound = async (port: number) => { ); }; -const waitUntil = async ( - predicate: () => MaybePromise, - intervalMs = 100 -) => { - await retry( - (result) => !result, - async () => { - await setTimeout(intervalMs); - return predicate(); - } - ); -}; - const waitUntilOutputContains = async ( session: SessionData, substring: string, @@ -503,7 +490,7 @@ describe("writes debug logs to hidden file", () => { async (session) => { await waitForPortToBeBound(session.port); - await waitUntil(() => session.stdout.includes("🐛")); + await waitUntilOutputContains(session, "🐛 Writing debug logs to"); await setTimeout(1000); // wait a bit to ensure the file is written to disk } From b60bef376ca6f28b801a42731670168ae6246281 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 13 Nov 2023 15:29:19 +0000 Subject: [PATCH 15/29] change debug log default directory --- packages/wrangler/src/utils/debug-log-file.ts | 53 +++++++++++++------ 1 file changed, 38 insertions(+), 15 deletions(-) diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index ba6be3053161..a5a428886875 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -1,10 +1,9 @@ -import { appendFile } from "node:fs/promises"; +import { appendFile, mkdir, readFile } from "node:fs/promises"; import path from "node:path"; -import { format } from "node:util"; import { Mutex } from "miniflare"; import { getEnvironmentVariableFactory } from "../environment-variables/factory"; -import { logger } from "../logger"; import { getBasePath } from "../paths"; +import type { LoggerLevel } from "../logger"; const getDebugFilepath = getEnvironmentVariableFactory({ variableName: "WRANGLER_DEBUG_LOG", @@ -18,37 +17,61 @@ const getDebugFilepath = getEnvironmentVariableFactory({ const absoluteFilepath = path.join( getBasePath(), ".wrangler", + "debug-logs", `wrangler-debug-${date}.log` ); - const relativeFilepath = path.relative(process.cwd(), absoluteFilepath); - return relativeFilepath; + return absoluteFilepath; }, }); -const debugLogFilepath = getDebugFilepath(); +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; -export async function appendToDebugLogFile(...args: unknown[]) { +/** + * 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()} -${format(...args)} +--- ${new Date().toISOString()} ${messageLevel} +${message} --- `; - await mutex.runWith(() => - appendFile(debugLogFilepath, entry).catch((err) => { + await mutex.runWith(async () => { + try { + await ensureDirectoryExists(debugLogFilepath); + await appendFile(debugLogFilepath, entry); + } catch (err) { if (hasLoggedError) return; hasLoggedError = true; - logger.error(`Failed to write to debug log file`, err); - }) - ); + console.error(`Failed to write to debug log file`, err); + console.error(`Would have written:`, entry); + } + }); if (hasLoggedLocation) return; hasLoggedLocation = true; - logger.info(`🐛 Writing debug logs to "${debugLogFilepath}"`); + const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); + console.info(`🐛 Writing debug logs to "${relativeFilepath}"`); // TODO: move this into an exit hook so it isn't the first thing logged } + +/** + * Reads the current log file after waiting for all pending writes + */ +export function readDebugLogFile(): Promise { + return mutex.runWith(() => readFile(debugLogFilepath, "utf-8")); +} From d83214be6f4a89ba89a0994ad8457ef68133b56e Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 13 Nov 2023 15:29:21 +0000 Subject: [PATCH 16/29] disable debug log file during jest unit-tests --- packages/wrangler/src/__tests__/dev.test.tsx | 6 ------ packages/wrangler/src/logger.ts | 16 +++++++++++++--- 2 files changed, 13 insertions(+), 9 deletions(-) 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/logger.ts b/packages/wrangler/src/logger.ts index 541241c367af..5d2cc40ebc24 100644 --- a/packages/wrangler/src/logger.ts +++ b/packages/wrangler/src/logger.ts @@ -74,12 +74,22 @@ export class Logger { private doLog(messageLevel: Exclude, args: unknown[]) { if (LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS[messageLevel]) { - if (messageLevel === "debug") { - void appendToDebugLogFile(...args); + const message = this.formatMessage(messageLevel, format(...args)); + + const inUnitTests = typeof jest !== "undefined"; + // unless in unit-tests, if logLevel >= debug, send ALL logs to the debug log file (even non-debug logs for context & order) + if ( + !inUnitTests && + LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS.debug + ) { + void appendToDebugLogFile(messageLevel, message); + } + // unless in unit-tests, if the current message is a debug log, do not pollute the terminal with it (it's now in the debug log file) + if (!inUnitTests && LOGGER_LEVELS[messageLevel] === LOGGER_LEVELS.debug) { return; } - console[messageLevel](this.formatMessage(messageLevel, format(...args))); + console[messageLevel](message); } } From 1fe136f4853ce36da2e5af9da182212b7071d3cb Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 13 Nov 2023 17:19:42 +0000 Subject: [PATCH 17/29] update snapshots --- packages/wrangler/e2e/dev.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index 9b3f54951967..9d310295bb9e 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -504,7 +504,7 @@ describe("writes debug logs to hidden file", () => { expect(existsSync(filepath)).toBe(true); expect(normalizeOutput(finalA.stdout)).toMatchInlineSnapshot(` - "🐛 Writing debug logs to \\"../../../../../../../../Users/sethi/code/workers-sdk/packages/wrangler/.wrangler/wrangler-debug-.log\\" + "🐛 Writing debug logs to \\"../../../../../../../../Users/sethi/code/workers-sdk/packages/wrangler/.wrangler/debug-logs/wrangler-debug-.log\\" ⎔ Starting local server... [mf:inf] Ready on http://: [mf:inf] - http://: From 88fbf14447436b085d8d56f642717c2a97ff3f5c Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 13 Nov 2023 19:04:53 +0000 Subject: [PATCH 18/29] try make test fail on assertion, not waitUntil --- packages/wrangler/e2e/dev.test.ts | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index 9d310295bb9e..2a8a70fad8cb 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -552,11 +552,10 @@ describe("writes debug logs to hidden file", () => { // 3. try to start worker B on the same port await b.runDevSession(`--port ${sessionA.port}`, async (sessionB) => { - // 4. wait until session B emits an "Address in use" error log - await waitUntilOutputContains( - sessionB, - "[ERROR] Address already in use" - ); + // 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(200); // ensure the workerd error message IS NOT present expect(normalize(sessionB.stderr)).not.toContain( From 75693537ca995f7b97d16958293ff0a03b3d5f1c Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 13 Nov 2023 19:18:00 +0000 Subject: [PATCH 19/29] fix hyperdrive e2e tests --- packages/wrangler/e2e/dev.test.ts | 57 ++++++------------------------- 1 file changed, 11 insertions(+), 46 deletions(-) diff --git a/packages/wrangler/e2e/dev.test.ts b/packages/wrangler/e2e/dev.test.ts index 2a8a70fad8cb..ee2782d5fbc9 100644 --- a/packages/wrangler/e2e/dev.test.ts +++ b/packages/wrangler/e2e/dev.test.ts @@ -53,15 +53,14 @@ async function runDevSession( ) { let pid; try { - const match = flags.match(/--port (\d+)/); - let port: number; - if (!match) { + const portFlagMatch = flags.match(/--port (\d+)/); + let port = 0; + if (portFlagMatch) { + port = parseInt(portFlagMatch[1]); + } + if (port === 0) { port = await getPort(); flags += ` --port ${port}`; - } else { - port = parseInt(match[1]); - - if (port === 0) port = await getPort(); } // Must use the `in` statement in the shellac script rather than `.in()` modifier on the `shellac` object @@ -383,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 }; } ); @@ -411,13 +410,13 @@ 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 }; } ); @@ -502,20 +501,6 @@ describe("writes debug logs to hidden file", () => { assert(filepath); expect(existsSync(filepath)).toBe(true); - - expect(normalizeOutput(finalA.stdout)).toMatchInlineSnapshot(` - "🐛 Writing debug logs to \\"../../../../../../../../Users/sethi/code/workers-sdk/packages/wrangler/.wrangler/debug-logs/wrangler-debug-.log\\" - ⎔ Starting local server... - [mf:inf] Ready on http://: - [mf:inf] - http://: - [mf:inf] GET / 200 OK (TIMINGS) - " - `); - expect(normalizeOutput(finalA.stderr)).toMatchInlineSnapshot(` - "X [ERROR] workerd/server/server.c++:2984: info: Inspector is listening - X [ERROR] workerd/server/server.c++:1174: info: Inspector client attaching [core:user:a] - " - `); }); it("does NOT write to file when --log-level != debug", async () => { @@ -530,15 +515,6 @@ describe("writes debug logs to hidden file", () => { )?.[1]; expect(filepath).toBeUndefined(); - - expect(normalizeOutput(finalA.stdout)).toMatchInlineSnapshot(` - "⎔ Starting local server... - [mf:inf] Ready on http://: - [mf:inf] - http://: - [mf:inf] GET / 200 OK (TIMINGS) - " - `); - expect(normalizeOutput(finalA.stderr)).toMatchInlineSnapshot('""'); }); it("rewrites address-in-use error logs", async () => { @@ -555,7 +531,7 @@ describe("writes debug logs to hidden file", () => { // 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(200); + await setTimeout(1000); // ensure the workerd error message IS NOT present expect(normalize(sessionB.stderr)).not.toContain( @@ -565,17 +541,6 @@ describe("writes debug logs to hidden file", () => { expect(normalize(sessionB.stderr)).toContain( "[ERROR] Address already in use" ); - - // snapshot stdout/stderr so we can see what the user sees - expect(normalize(sessionB.stdout)).toMatchInlineSnapshot(` - "⎔ Starting local server... - " - `); - expect(normalize(sessionB.stderr)).toMatchInlineSnapshot(` - "X [ERROR] Address already in use (*:). Please check that you are not already running a server on this address or specify a different port with --port. - X [ERROR] MiniflareCoreError [ERR_RUNTIME_FAILURE]: The Workers runtime failed to start. There is likely additional logging output above. - " - `); }); }); }); From fd128245294767814a6d08e1aa19ae6c25896afc Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Tue, 14 Nov 2023 14:30:00 +0000 Subject: [PATCH 20/29] upload debug logs as artifact --- .github/workflows/e2e.yml | 8 ++++++++ .github/workflows/pullrequests.yml | 8 ++++++++ packages/wrangler/src/utils/debug-log-file.ts | 2 +- 3 files changed, 17 insertions(+), 1 deletion(-) diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 7aac41bfa2ef..fb9522de734a 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_DEBUG_LOG: ${{ 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..5ca23991678e 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_DEBUG_LOG: ${{ 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/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index a5a428886875..b37a49defffd 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -31,7 +31,7 @@ async function ensureDirectoryExists(filepath: string) { await mkdir(dirpath, { recursive: true }); } -export const debugLogFilepath = getDebugFilepath(); +export const debugLogFilepath = path.resolve(getDebugFilepath()); const mutex = new Mutex(); let hasLoggedLocation = false; From 2dfea77a0ec39012daa074784358c2843709cb2d Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 17 Nov 2023 14:40:21 +0000 Subject: [PATCH 21/29] allow user to provide filepath *or* directory for WRANGLER_LOG_DIR --- .github/workflows/e2e.yml | 2 +- .github/workflows/pullrequests.yml | 2 +- .../src/environment-variables/factory.ts | 2 +- packages/wrangler/src/utils/debug-log-file.ts | 39 ++++++++++--------- 4 files changed, 24 insertions(+), 21 deletions(-) diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index fb9522de734a..18be576841a5 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -82,7 +82,7 @@ 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_DEBUG_LOG: ${{ runner.temp }}/wrangler-debug-logs/ + WRANGLER_LOG_DIR: ${{ runner.temp }}/wrangler-debug-logs/ - name: Upload debug logs if: always() diff --git a/.github/workflows/pullrequests.yml b/.github/workflows/pullrequests.yml index 5ca23991678e..e2d3a6878599 100644 --- a/.github/workflows/pullrequests.yml +++ b/.github/workflows/pullrequests.yml @@ -115,7 +115,7 @@ 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_DEBUG_LOG: ${{ runner.temp }}/wrangler-debug-logs/ + WRANGLER_LOG_DIR: ${{ runner.temp }}/wrangler-debug-logs/ - name: Upload debug logs if: always() diff --git a/packages/wrangler/src/environment-variables/factory.ts b/packages/wrangler/src/environment-variables/factory.ts index 0e5be3a9a41f..0f9d68074aa3 100644 --- a/packages/wrangler/src/environment-variables/factory.ts +++ b/packages/wrangler/src/environment-variables/factory.ts @@ -14,8 +14,8 @@ type VariableNames = | "WRANGLER_C3_COMMAND" | "WRANGLER_CF_AUTHORIZATION_TOKEN" | "WRANGLER_CLIENT_ID" - | "WRANGLER_DEBUG_LOG" | "WRANGLER_LOG" + | "WRANGLER_LOG_DIR" | "WRANGLER_REVOKE_URL" | "WRANGLER_SEND_METRICS" | "WRANGLER_TOKEN_URL"; diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index b37a49defffd..9c1cffb91d24 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -5,26 +5,29 @@ import { getEnvironmentVariableFactory } from "../environment-variables/factory" import { getBasePath } from "../paths"; import type { LoggerLevel } from "../logger"; -const getDebugFilepath = getEnvironmentVariableFactory({ - variableName: "WRANGLER_DEBUG_LOG", - defaultValue: () => { - const date = new Date() - .toISOString() - .replaceAll(":", "-") - .replace(".", "_") - .replace("T", "_") - .replace("Z", ""); - const absoluteFilepath = path.join( - getBasePath(), - ".wrangler", - "debug-logs", - `wrangler-debug-${date}.log` - ); - - return absoluteFilepath; - }, +const getDebugFileDir = getEnvironmentVariableFactory({ + variableName: "WRANGLER_LOG_DIR", }); +function getDebugFilepath() { + const dir = + getDebugFileDir() ?? path.join(getBasePath(), ".wrangler", "debug-logs"); + + 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-debug-${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); From e5d4c02f452bc3779aca4d860470a0d5ada2e408 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 17 Nov 2023 15:21:54 +0000 Subject: [PATCH 22/29] log debug-log-file location to terminal on exit as well as on startup --- packages/wrangler/src/utils/debug-log-file.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index 9c1cffb91d24..ea95833974e9 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -1,6 +1,7 @@ import { appendFile, mkdir, readFile } from "node:fs/promises"; import path from "node:path"; import { Mutex } from "miniflare"; +import onExit from "signal-exit"; import { getEnvironmentVariableFactory } from "../environment-variables/factory"; import { getBasePath } from "../paths"; import type { LoggerLevel } from "../logger"; @@ -69,7 +70,9 @@ ${message} hasLoggedLocation = true; const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); console.info(`🐛 Writing debug logs to "${relativeFilepath}"`); - // TODO: move this into an exit hook so it isn't the first thing logged + onExit(() => { + console.info(`🐛 Debug logs were written to "${relativeFilepath}"`); + }); } /** From 6b6ecdd530deac08150ed46116aec7853caf6c7d Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Fri, 17 Nov 2023 15:22:42 +0000 Subject: [PATCH 23/29] even if intecepted, log chunks from workerd to debug file --- packages/wrangler/src/dev/miniflare.ts | 3 +- packages/wrangler/src/utils/debug-log-file.ts | 28 ++++++++++--------- 2 files changed, 17 insertions(+), 14 deletions(-) diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare.ts index 4e911161f7b1..3e8412c23942 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare.ts @@ -450,7 +450,8 @@ function handleRuntimeStdio(stdout: Readable, stderr: Readable) { `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.` ); - return; + // 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: diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index ea95833974e9..ba309c4f5ea0 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -35,7 +35,7 @@ async function ensureDirectoryExists(filepath: string) { await mkdir(dirpath, { recursive: true }); } -export const debugLogFilepath = path.resolve(getDebugFilepath()); +export const debugLogFilepath = getDebugFilepath(); const mutex = new Mutex(); let hasLoggedLocation = false; @@ -54,25 +54,27 @@ ${message} --- `; + if (!hasLoggedLocation) { + hasLoggedLocation = true; + const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); + console.info(`🐛 Writing debug logs to "${relativeFilepath}"`); + onExit(() => { + console.info(`🐛 Debug logs were written to "${relativeFilepath}"`); + }); + } + await mutex.runWith(async () => { try { await ensureDirectoryExists(debugLogFilepath); await appendFile(debugLogFilepath, entry); } catch (err) { - if (hasLoggedError) return; - hasLoggedError = true; - console.error(`Failed to write to debug log file`, err); - console.error(`Would have written:`, entry); + if (!hasLoggedError) { + hasLoggedError = true; + console.error(`Failed to write to debug log file`, err); + console.error(`Would have written:`, entry); + } } }); - - if (hasLoggedLocation) return; - hasLoggedLocation = true; - const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); - console.info(`🐛 Writing debug logs to "${relativeFilepath}"`); - onExit(() => { - console.info(`🐛 Debug logs were written to "${relativeFilepath}"`); - }); } /** From 54815c065076b9a11f1eea0c32884043ce6ce5f1 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 14:10:38 +0000 Subject: [PATCH 24/29] fix Miniflare NoOpLog to now throw when logging errors --- packages/miniflare/src/shared/log.ts | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/packages/miniflare/src/shared/log.ts b/packages/miniflare/src/shared/log.ts index cc49efb862b8..20a4d164c9ac 100644 --- a/packages/miniflare/src/shared/log.ts +++ b/packages/miniflare/src/shared/log.ts @@ -115,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 From cd024dd0e35908f1c9321a7d823247bcc482ab67 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 14:14:17 +0000 Subject: [PATCH 25/29] try use .wrangler dir in project root before package base path --- packages/wrangler/src/utils/debug-log-file.ts | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index ba309c4f5ea0..6974fd2bd404 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -2,17 +2,23 @@ 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 { getBasePath } from "../paths"; import type { LoggerLevel } from "../logger"; const getDebugFileDir = getEnvironmentVariableFactory({ variableName: "WRANGLER_LOG_DIR", + defaultValue() { + const configPath = findWranglerToml(); + const configDir = configPath ? path.dirname(configPath) : getBasePath(); + + return path.join(configDir, ".wrangler", "debug-logs"); + }, }); function getDebugFilepath() { - const dir = - getDebugFileDir() ?? path.join(getBasePath(), ".wrangler", "debug-logs"); + const dir = getDebugFileDir(); const date = new Date() .toISOString() From a5c8bb591a1b21912d19af3921240a6fd8dce3af Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 14:26:50 +0000 Subject: [PATCH 26/29] rename WRANGLER_LOG_DIR to WRANGLER_LOG_PATH --- .github/workflows/e2e.yml | 2 +- .github/workflows/pullrequests.yml | 2 +- packages/wrangler/src/environment-variables/factory.ts | 2 +- packages/wrangler/src/utils/debug-log-file.ts | 2 +- 4 files changed, 4 insertions(+), 4 deletions(-) diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 18be576841a5..34b38959b915 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -82,7 +82,7 @@ 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_DIR: ${{ runner.temp }}/wrangler-debug-logs/ + WRANGLER_LOG_PATH: ${{ runner.temp }}/wrangler-debug-logs/ - name: Upload debug logs if: always() diff --git a/.github/workflows/pullrequests.yml b/.github/workflows/pullrequests.yml index e2d3a6878599..4f313d8e23c2 100644 --- a/.github/workflows/pullrequests.yml +++ b/.github/workflows/pullrequests.yml @@ -115,7 +115,7 @@ 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_DIR: ${{ runner.temp }}/wrangler-debug-logs/ + WRANGLER_LOG_PATH: ${{ runner.temp }}/wrangler-debug-logs/ - name: Upload debug logs if: always() diff --git a/packages/wrangler/src/environment-variables/factory.ts b/packages/wrangler/src/environment-variables/factory.ts index 0f9d68074aa3..658ccff593c6 100644 --- a/packages/wrangler/src/environment-variables/factory.ts +++ b/packages/wrangler/src/environment-variables/factory.ts @@ -15,7 +15,7 @@ type VariableNames = | "WRANGLER_CF_AUTHORIZATION_TOKEN" | "WRANGLER_CLIENT_ID" | "WRANGLER_LOG" - | "WRANGLER_LOG_DIR" + | "WRANGLER_LOG_PATH" | "WRANGLER_REVOKE_URL" | "WRANGLER_SEND_METRICS" | "WRANGLER_TOKEN_URL"; diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index 6974fd2bd404..efaf9a939fcb 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -8,7 +8,7 @@ import { getBasePath } from "../paths"; import type { LoggerLevel } from "../logger"; const getDebugFileDir = getEnvironmentVariableFactory({ - variableName: "WRANGLER_LOG_DIR", + variableName: "WRANGLER_LOG_PATH", defaultValue() { const configPath = findWranglerToml(); const configDir = configPath ? path.dirname(configPath) : getBasePath(); From 8200491b4547b2710250b94a2820a94fd51ee9d1 Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 14:36:22 +0000 Subject: [PATCH 27/29] add changeset --- .changeset/gentle-pans-push.md | 5 +++++ .changeset/weak-peaches-marry.md | 5 +++++ packages/miniflare/test/http/fetch.spec.ts | 4 ++-- 3 files changed, 12 insertions(+), 2 deletions(-) create mode 100644 .changeset/gentle-pans-push.md create mode 100644 .changeset/weak-peaches-marry.md 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..8af3599774a4 --- /dev/null +++ b/.changeset/weak-peaches-marry.md @@ -0,0 +1,5 @@ +--- +"wrangler": minor +--- + +Wrangler now writes all debug logs to a .log file in the `.wrangler` directory. Enable debug log-mode as usual with `WRANGLER_LOG=debug npx wrangler ...`. Debug logs are no longer printed to the terminal. Set a directory or specific .log filepath to write debug 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. 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: { From ea03a4aeeb0b1f4e9bed72cef26dc9d620cd2b8f Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 15:03:48 +0000 Subject: [PATCH 28/29] write logs to file unconditionally WRANGLER_LOG=debug will continue to log to the terminal --- .changeset/weak-peaches-marry.md | 4 +++- packages/wrangler/src/logger.ts | 22 +++++++------------ packages/wrangler/src/utils/debug-log-file.ts | 4 ++-- 3 files changed, 13 insertions(+), 17 deletions(-) diff --git a/.changeset/weak-peaches-marry.md b/.changeset/weak-peaches-marry.md index 8af3599774a4..2c4167cd0cd9 100644 --- a/.changeset/weak-peaches-marry.md +++ b/.changeset/weak-peaches-marry.md @@ -2,4 +2,6 @@ "wrangler": minor --- -Wrangler now writes all debug logs to a .log file in the `.wrangler` directory. Enable debug log-mode as usual with `WRANGLER_LOG=debug npx wrangler ...`. Debug logs are no longer printed to the terminal. Set a directory or specific .log filepath to write debug 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 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/packages/wrangler/src/logger.ts b/packages/wrangler/src/logger.ts index 5d2cc40ebc24..1932a8a9ff84 100644 --- a/packages/wrangler/src/logger.ts +++ b/packages/wrangler/src/logger.ts @@ -73,22 +73,16 @@ export class Logger { } private doLog(messageLevel: Exclude, args: unknown[]) { - if (LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS[messageLevel]) { - const message = this.formatMessage(messageLevel, format(...args)); + const message = this.formatMessage(messageLevel, format(...args)); - const inUnitTests = typeof jest !== "undefined"; - // unless in unit-tests, if logLevel >= debug, send ALL logs to the debug log file (even non-debug logs for context & order) - if ( - !inUnitTests && - LOGGER_LEVELS[this.loggerLevel] >= LOGGER_LEVELS.debug - ) { - void appendToDebugLogFile(messageLevel, message); - } - // unless in unit-tests, if the current message is a debug log, do not pollute the terminal with it (it's now in the debug log file) - if (!inUnitTests && LOGGER_LEVELS[messageLevel] === LOGGER_LEVELS.debug) { - return; - } + // 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](message); } } diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index efaf9a939fcb..fb5b14ec4e09 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -4,8 +4,8 @@ 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"; import { getBasePath } from "../paths"; -import type { LoggerLevel } from "../logger"; const getDebugFileDir = getEnvironmentVariableFactory({ variableName: "WRANGLER_LOG_PATH", @@ -63,7 +63,7 @@ ${message} if (!hasLoggedLocation) { hasLoggedLocation = true; const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); - console.info(`🐛 Writing debug logs to "${relativeFilepath}"`); + logger.debug(`🐛 Writing debug 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(`🐛 Debug logs were written to "${relativeFilepath}"`); }); From 664e4a4c3a408d9e8355c2a355238fbb41f7bc0b Mon Sep 17 00:00:00 2001 From: Rahul Sethi <5822355+RamIdeas@users.noreply.github.com> Date: Mon, 20 Nov 2023 15:13:54 +0000 Subject: [PATCH 29/29] fallback to cwd not package base path --- packages/wrangler/src/utils/debug-log-file.ts | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/packages/wrangler/src/utils/debug-log-file.ts b/packages/wrangler/src/utils/debug-log-file.ts index fb5b14ec4e09..980b40887590 100644 --- a/packages/wrangler/src/utils/debug-log-file.ts +++ b/packages/wrangler/src/utils/debug-log-file.ts @@ -5,15 +5,14 @@ import onExit from "signal-exit"; import { findWranglerToml } from "../config"; import { getEnvironmentVariableFactory } from "../environment-variables/factory"; import { logger, type LoggerLevel } from "../logger"; -import { getBasePath } from "../paths"; const getDebugFileDir = getEnvironmentVariableFactory({ variableName: "WRANGLER_LOG_PATH", defaultValue() { const configPath = findWranglerToml(); - const configDir = configPath ? path.dirname(configPath) : getBasePath(); + const configDir = configPath ? path.dirname(configPath) : process.cwd(); - return path.join(configDir, ".wrangler", "debug-logs"); + return path.join(configDir, ".wrangler", "logs"); }, }); @@ -29,7 +28,7 @@ function getDebugFilepath() { const filepath = dir.endsWith(".log") ? dir // allow the user to provide an exact filepath - : path.join(dir, `wrangler-debug-${date}.log`); + : 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); @@ -63,9 +62,9 @@ ${message} if (!hasLoggedLocation) { hasLoggedLocation = true; const relativeFilepath = path.relative(process.cwd(), debugLogFilepath); - logger.debug(`🐛 Writing debug logs to "${relativeFilepath}"`); // use logger.debug here to not show this message by default -- since logging to a file is no longer opt-in + 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(`🐛 Debug logs were written to "${relativeFilepath}"`); + console.info(`🐛 Logs were written to "${relativeFilepath}"`); }); } @@ -76,7 +75,7 @@ ${message} } catch (err) { if (!hasLoggedError) { hasLoggedError = true; - console.error(`Failed to write to debug log file`, err); + console.error(`Failed to write to log file`, err); console.error(`Would have written:`, entry); } }