diff --git a/.changeset/deep-lizards-move.md b/.changeset/deep-lizards-move.md new file mode 100644 index 000000000000..e4ecbb02dbd2 --- /dev/null +++ b/.changeset/deep-lizards-move.md @@ -0,0 +1,35 @@ +--- +"wrangler": patch +--- + +fix `wrangler dev` logs being logged on the incorrect level in some cases + +currently the way `wrangler dev` prints logs is faulty, for example the following code + +```js +console.error("this is an error"); +console.warn("this is a warning"); +console.debug("this is a debug"); +``` + +inside a worker would cause the following logs: + +```text +✘ [ERROR] this is an error + +✘ [ERROR] this is a warning + +this is a debug +``` + +(note that the warning is printed as an error and the debug log is printed even if by default it should not) + +the changes here make sure that the logs are instead logged to their correct level, so for the code about the following will be logged instead: + +```text +✘ [ERROR] this is an error + +▲ [WARNING] this is a warning +``` + +(running `wrangler dev` with the `--log-level=debug` flag will also cause the debug log to be included as well) diff --git a/.changeset/full-areas-lick.md b/.changeset/full-areas-lick.md new file mode 100644 index 000000000000..66091e99e4e3 --- /dev/null +++ b/.changeset/full-areas-lick.md @@ -0,0 +1,7 @@ +--- +"miniflare": minor +--- + +add `structuredWorkerdLogs` option + +add a new top-level option named `structuredWorkerdLogs` that makes workerd print to stdout structured logs (stringified jsons of the following shape: `{ timestamp: number, level: string, message: string }`) instead of printing logs to stdout and stderr diff --git a/fixtures/shared/src/run-wrangler-long-lived.ts b/fixtures/shared/src/run-wrangler-long-lived.ts index b8d2aaa78f27..7ad701a39241 100644 --- a/fixtures/shared/src/run-wrangler-long-lived.ts +++ b/fixtures/shared/src/run-wrangler-long-lived.ts @@ -87,7 +87,9 @@ async function runLongLivedWrangler( chunks.push(chunk); }); wranglerProcess.stderr?.on("data", (chunk) => { - console.log(`[${command}]`, chunk.toString()); + if (process.env.WRANGLER_LOG === "debug") { + console.log(`[${command}]`, chunk.toString()); + } chunks.push(chunk); }); wranglerProcess.once("exit", (exitCode) => { diff --git a/fixtures/worker-logs/package.json b/fixtures/worker-logs/package.json new file mode 100644 index 000000000000..9e5d46ce66fb --- /dev/null +++ b/fixtures/worker-logs/package.json @@ -0,0 +1,22 @@ +{ + "name": "@fixture/worker-logs", + "private": true, + "scripts": { + "check:type": "tsc", + "dev": "pnpm dev.module", + "dev.module": "wrangler dev -c wrangler.module.jsonc", + "dev.service": "wrangler dev -c wrangler.service.jsonc", + "start": "pnpm dev.module", + "test:ci": "vitest run", + "test:watch": "vitest" + }, + "devDependencies": { + "@cloudflare/workers-tsconfig": "workspace:^", + "typescript": "catalog:default", + "vitest": "catalog:default", + "wrangler": "workspace:*" + }, + "volta": { + "extends": "../../package.json" + } +} diff --git a/fixtures/worker-logs/src/module.js b/fixtures/worker-logs/src/module.js new file mode 100644 index 000000000000..c825ace82cc2 --- /dev/null +++ b/fixtures/worker-logs/src/module.js @@ -0,0 +1,25 @@ +export default { + async fetch(request, env) { + const response = new Response("Hello"); + + const customMessage = request.headers.get("x-custom-message"); + if (customMessage) { + if (customMessage === "%__VERY_VERY_LONG_MESSAGE_%") { + // We can't simply pass a huge long message as a header thus + // why a placeholder is used here + console.log("z".repeat(2 ** 20)); + } else { + console.log(customMessage); + } + return response; + } + + console.log("<<<<>>>>"); + console.warn("<<<<>>>>"); + console.error("<<<<>>>>"); + console.debug("<<<<>>>>"); + console.info("<<<<>>>>"); + + return response; + }, +}; diff --git a/fixtures/worker-logs/src/service.js b/fixtures/worker-logs/src/service.js new file mode 100644 index 000000000000..cd66a074da2a --- /dev/null +++ b/fixtures/worker-logs/src/service.js @@ -0,0 +1,12 @@ +async function handler(request) { + console.log("<<<<>>>>"); + console.warn("<<<<>>>>"); + console.error("<<<<>>>>"); + console.debug("<<<<>>>>"); + console.info("<<<<>>>>"); + return new Response("Hello"); +} + +addEventListener("fetch", (event) => { + event.respondWith(handler(event.request)); +}); diff --git a/fixtures/worker-logs/tests/index.test.ts b/fixtures/worker-logs/tests/index.test.ts new file mode 100644 index 000000000000..17812629ecc2 --- /dev/null +++ b/fixtures/worker-logs/tests/index.test.ts @@ -0,0 +1,273 @@ +import { setTimeout } from "node:timers/promises"; +import { resolve } from "path"; +import { describe, test } from "vitest"; +import { runWranglerDev } from "../../shared/src/run-wrangler-long-lived"; + +async function getWranglerDevOutput( + type: "module" | "service", + extraArgs: string[] = [], + customMessage?: string, + requests = 1, + env = {} +) { + const { ip, port, stop, getOutput } = await runWranglerDev( + resolve(__dirname, ".."), + [ + `-c=wrangler.${type}.jsonc`, + "--port=0", + "--inspector-port=0", + ...extraArgs, + ], + env + ); + + const request = new Request(`http://${ip}:${port}`); + if (customMessage) { + request.headers.set("x-custom-message", customMessage); + } + + for (let i = 0; i < requests; i++) { + const response = await fetch(request); + await response.text(); + + // We wait for a bit for the output stream to be completely ready + // (this is a bit slow but it's generic to be used by all tests + // in this file, it also seems to make the tests very stable) + await setTimeout(500); + } + + await stop(); + + let output = getOutput(); + + output = output + // Windows gets a different marker for ✘, so let's normalize it here + // so that these tests can be platform independent + .replaceAll("✘", "X") + // Let's also normalize Windows newlines + .replaceAll("\r\n", "\n"); + + // Let's filter out lines we're not interested in + output = output + .split("\n") + .filter((line) => + logLineToIgnoreRegexps.every((regex) => !regex.test(line)) + ) + // let's also sort the logs for more stability of the tests, ideally + // we would want to test the log's ordering as well but that seems + // to cause flakes in the CI runs + .sort() + .join("\n"); + + return output; +} + +describe("'wrangler dev' correctly displays logs", () => { + describe("module workers", () => { + test("default behavior", async ({ expect }) => { + const output = await getWranglerDevOutput("module"); + expect(output).toMatchInlineSnapshot(` + "X [ERROR] <<<<>>>> + ▲ [WARNING] <<<<>>>> + <<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=log", async ({ expect }) => { + const output = await getWranglerDevOutput("module", ["--log-level=log"]); + expect(output).toMatchInlineSnapshot(` + "X [ERROR] <<<<>>>> + ▲ [WARNING] <<<<>>>> + <<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=info", async ({ expect }) => { + const output = await getWranglerDevOutput("module", ["--log-level=info"]); + expect(output).toMatchInlineSnapshot(` + "X [ERROR] <<<<>>>> + ▲ [WARNING] <<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=warn", async ({ expect }) => { + const output = await getWranglerDevOutput("module", ["--log-level=warn"]); + expect(output).toMatchInlineSnapshot(` + "X [ERROR] <<<<>>>> + ▲ [WARNING] <<<<>>>>" + `); + }); + + test("with --log-level=error", async ({ expect }) => { + const output = await getWranglerDevOutput("module", [ + "--log-level=error", + ]); + expect(output).toMatchInlineSnapshot( + `"X [ERROR] <<<<>>>>"` + ); + }); + + test("with --log-level=debug", async ({ expect }) => { + const output = await getWranglerDevOutput( + "module", + ["--log-level=debug"], + undefined, + // For some reason in debug mode two requests are + // needed to trigger the log here... + 2 + ); + expect(output).toContain("<<<<>>>>"); + }); + + test('with WRANGLER_LOG="debug"', async ({ expect }) => { + const output = await getWranglerDevOutput( + "module", + [], + undefined, + // For some reason in debug mode two requests are + // needed to trigger the log here... + 2, + { WRANGLER_LOG: "debug" } + ); + expect(output).toContain("<<<<>>>>"); + }); + + test("with --log-level=none", async ({ expect }) => { + const output = await getWranglerDevOutput("module", ["--log-level=none"]); + expect(output).toMatchInlineSnapshot(`""`); + }); + + // the workerd structured logs follow this structure: + // {"timestamp":,"level":"","message":""} + // the following tests check for edge case scenario where the following + // structure could not get detected correctly + describe("edge case scenarios", () => { + test("base case", async ({ expect }) => { + const output = await getWranglerDevOutput("module", [], "hello"); + expect(output).toMatchInlineSnapshot(`"hello"`); + }); + test("quotes in message", async ({ expect }) => { + const output = await getWranglerDevOutput("module", [], 'hel"lo'); + expect(output).toMatchInlineSnapshot(`"hel"lo"`); + }); + + test("braces in message", async ({ expect }) => { + const output = await getWranglerDevOutput("module", [], "hel{}lo"); + expect(output).toMatchInlineSnapshot(`"hel{}lo"`); + }); + + test("a workerd structured message in the message", async ({ + expect, + }) => { + const output = await getWranglerDevOutput( + "module", + [], + 'This is an example of a Workerd structured log: {"timestamp":1234567890,"level":"log","message":"Hello World!"}' + ); + expect(output).toMatchInlineSnapshot( + `"This is an example of a Workerd structured log: {"timestamp":1234567890,"level":"log","message":"Hello World!"}"` + ); + }); + + test("a very very very long message (that gets split in multiple chunks)", async ({ + expect, + }) => { + const output = await getWranglerDevOutput( + "module", + [], + "%__VERY_VERY_LONG_MESSAGE_%" + ); + expect(output).toMatch(new RegExp(`^z{${2 ** 20}}$`)); + }); + }); + }); + + // Note: service workers logs are handled differently from standard logs (and are built on top of + // inspector Runtime.consoleAPICalled events), they don't work as well as logs for module + // workers. Service workers are also deprecated so it's not a huge deal, the following + // tests are only here in place to make sure that the basic logging functionality of + // service workers does work + describe("service workers", () => { + test("default behavior", async ({ expect }) => { + const output = await getWranglerDevOutput("service"); + expect(output).toMatchInlineSnapshot(` + "<<<<>>>> + <<<<>>>> + <<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=log", async ({ expect }) => { + const output = await getWranglerDevOutput("service", ["--log-level=log"]); + expect(output).toMatchInlineSnapshot(` + "<<<<>>>> + <<<<>>>> + <<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=info", async ({ expect }) => { + const output = await getWranglerDevOutput("service", [ + "--log-level=info", + ]); + expect(output).toMatchInlineSnapshot(` + "<<<<>>>> + <<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=warn", async ({ expect }) => { + const output = await getWranglerDevOutput("service", [ + "--log-level=warn", + ]); + expect(output).toMatchInlineSnapshot(` + "<<<<>>>> + <<<<>>>>" + `); + }); + + test("with --log-level=error", async ({ expect }) => { + const output = await getWranglerDevOutput("service", [ + "--log-level=error", + ]); + expect(output).toMatchInlineSnapshot(`"<<<<>>>>"`); + }); + + test("with --log-level=debug", async ({ expect }) => { + const output = await getWranglerDevOutput("service", [ + "--log-level=debug", + ]); + expect(output).toContain("<<<<>>>>"); + }); + + test("with --log-level=none", async ({ expect }) => { + const output = await getWranglerDevOutput("service", [ + "--log-level=none", + ]); + expect(output).toMatchInlineSnapshot(`""`); + }); + }); +}); + +const logLineToIgnoreRegexps = [ + // let's skip empty lines + /^\s*$/, + // part of the wrangler banner + /⛅️ wrangler/, + // divisor after the wrangler banner + /^─+$/, + // wrangler logs such as ` ⎔ Starting local server...` + /^\s*⎔/, + // wrangler's ready on log + /^\[wrangler:info\] Ready on http:\/\/[^:]+:\d+$/, + // positive response to get request + /^\[wrangler:info\] GET \/ 200 OK \(\d+ms\)$/, + // let's skip the telemetry messages + /^Cloudflare collects anonymous telemetry about your usage of Wrangler\. Learn more at https:\/\/.*$/, +]; diff --git a/fixtures/worker-logs/tsconfig.json b/fixtures/worker-logs/tsconfig.json new file mode 100644 index 000000000000..df8f82d26782 --- /dev/null +++ b/fixtures/worker-logs/tsconfig.json @@ -0,0 +1,13 @@ +{ + "compilerOptions": { + "target": "ES2021", + "esModuleInterop": true, + "module": "CommonJS", + "lib": ["ES2021"], + "types": ["node"], + "skipLibCheck": true, + "moduleResolution": "node", + "noEmit": true + }, + "include": ["tests", "../../node-types.d.ts"] +} diff --git a/fixtures/worker-logs/wrangler.module.jsonc b/fixtures/worker-logs/wrangler.module.jsonc new file mode 100644 index 000000000000..4994cfa5d384 --- /dev/null +++ b/fixtures/worker-logs/wrangler.module.jsonc @@ -0,0 +1,5 @@ +{ + "name": "worker-logs", + "compatibility_date": "2022-03-31", + "main": "src/module.js", +} diff --git a/fixtures/worker-logs/wrangler.service.jsonc b/fixtures/worker-logs/wrangler.service.jsonc new file mode 100644 index 000000000000..950793198e49 --- /dev/null +++ b/fixtures/worker-logs/wrangler.service.jsonc @@ -0,0 +1,5 @@ +{ + "name": "worker-logs", + "compatibility_date": "2022-03-31", + "main": "src/service.js", +} diff --git a/packages/miniflare/src/index.ts b/packages/miniflare/src/index.ts index 3153bd4bbc76..bce443d74c65 100644 --- a/packages/miniflare/src/index.ts +++ b/packages/miniflare/src/index.ts @@ -860,6 +860,8 @@ export class Miniflare { #runtimeDispatcher?: Dispatcher; #proxyClient?: ProxyClient; + #structuredWorkerdLogs: boolean; + #cfObject?: Record = {}; // Path to temporary directory for use as scratch space/"in-memory" Durable @@ -915,6 +917,8 @@ export class Miniflare { } this.#log = this.#sharedOpts.core.log ?? new NoOpLog(); + this.#structuredWorkerdLogs = + this.#sharedOpts.core.structuredWorkerdLogs ?? false; // If we're in a JavaScript Debug terminal, Miniflare will send the inspector ports directly to VSCode for registration // As such, we don't need our inspector proxy and in fact including it causes issue with multiple clients connected to the @@ -1982,7 +1986,13 @@ export class Miniflare { "Ensure wrapped bindings don't have bindings to themselves." ); } - return { services: servicesArray, sockets, extensions }; + + return { + services: servicesArray, + sockets, + extensions, + structuredLogging: this.#structuredWorkerdLogs, + }; } async #assembleAndUpdateConfig() { @@ -2376,6 +2386,9 @@ export class Miniflare { this.#sharedOpts = sharedOpts; this.#workerOpts = workerOpts; this.#log = this.#sharedOpts.core.log ?? this.#log; + this.#structuredWorkerdLogs = + this.#sharedOpts.core.structuredWorkerdLogs ?? + this.#structuredWorkerdLogs; await this.#devRegistry.updateRegistryPath( sharedOpts.core.unsafeDevRegistryPath, diff --git a/packages/miniflare/src/plugins/core/index.ts b/packages/miniflare/src/plugins/core/index.ts index 97c9ea858e5f..538123fd6ac0 100644 --- a/packages/miniflare/src/plugins/core/index.ts +++ b/packages/miniflare/src/plugins/core/index.ts @@ -247,6 +247,10 @@ export const CoreSharedOptionsSchema = z.object({ defaultPersistRoot: z.string().optional(), // Strip the MF-DISABLE_PRETTY_ERROR header from user request stripDisablePrettyError: z.boolean().default(true), + + // Whether to get structured logs from workerd or not (default to `false`) + // This option is useful in combination with a custom handleRuntimeStdio. + structuredWorkerdLogs: z.boolean().default(false), }); export const CORE_PLUGIN_NAME = "core"; diff --git a/packages/miniflare/src/runtime/config/generated.ts b/packages/miniflare/src/runtime/config/generated.ts index 853de89437d5..db0578d12fb6 100644 --- a/packages/miniflare/src/runtime/config/generated.ts +++ b/packages/miniflare/src/runtime/config/generated.ts @@ -10,7 +10,8 @@ export class Config extends $.Struct { static readonly _capnp = { displayName: "Config", id: "8794486c76aaa7d6", - size: new $.ObjectSize(0, 5), + size: new $.ObjectSize(8, 5), + defaultStructuredLogging: $.getBitMask(false, 0), }; static _Services: $.ListCtor; static _Sockets: $.ListCtor; @@ -151,6 +152,19 @@ export class Config extends $.Struct { set autogates(value: $.List) { $.utils.copyFrom(value, $.utils.getPointer(4, this)); } + /** + * If true, logs will be emitted as JSON for structured logging. + * When false, logs use the traditional human-readable format. + * This affects the format of logs from KJ_LOG and exception reporting as well as js logs. + * This won't work for logs coming from service worker syntax workers with the old module registry. + * + */ + get structuredLogging(): boolean { + return $.utils.getBit(0, this, Config._capnp.defaultStructuredLogging); + } + set structuredLogging(value: boolean) { + $.utils.setBit(0, value, this, Config._capnp.defaultStructuredLogging); + } toString(): string { return "Config_" + super.toString(); } @@ -952,6 +966,7 @@ export const Worker_Binding_Type_Which = { QUEUE: 11, ANALYTICS_ENGINE: 12, HYPERDRIVE: 13, + DURABLE_OBJECT_CLASS: 14, } as const; export type Worker_Binding_Type_Which = (typeof Worker_Binding_Type_Which)[keyof typeof Worker_Binding_Type_Which]; @@ -975,6 +990,8 @@ export class Worker_Binding_Type extends $.Struct { static readonly QUEUE = Worker_Binding_Type_Which.QUEUE; static readonly ANALYTICS_ENGINE = Worker_Binding_Type_Which.ANALYTICS_ENGINE; static readonly HYPERDRIVE = Worker_Binding_Type_Which.HYPERDRIVE; + static readonly DURABLE_OBJECT_CLASS = + Worker_Binding_Type_Which.DURABLE_OBJECT_CLASS; static readonly _capnp = { displayName: "Type", id: "8906a1296519bf8a", @@ -1094,6 +1111,12 @@ export class Worker_Binding_Type extends $.Struct { set hyperdrive(_: true) { $.utils.setUint16(0, 13, this); } + get _isDurableObjectClass(): boolean { + return $.utils.getUint16(0, this) === 14; + } + set durableObjectClass(_: true) { + $.utils.setUint16(0, 14, this); + } toString(): string { return "Worker_Binding_Type_" + super.toString(); } @@ -1698,6 +1721,39 @@ export class Worker_Binding_MemoryCache extends $.Struct { return "Worker_Binding_MemoryCache_" + super.toString(); } } +/** + * A binding representing the ability to dynamically load Workers from code presented at + * runtime. + * + * A Worker loader is not just a function that loads a Worker, but also serves as a + * cache of Workers, automatically unloading Workers that are not in use. To that end, each + * Worker must have a name, and if a Worker with that name already exists, it'll be reused. + * + */ +export class Worker_Binding_WorkerLoader extends $.Struct { + static readonly _capnp = { + displayName: "workerLoader", + id: "a3de996091635c4d", + size: new $.ObjectSize(8, 6), + }; + /** + * Optional: The identifier associated with this Worker loader. Multiple Workers can bind to + * the same ID in order to access the same loader, so that if they request the same name + * from it, they'll end up sharing the same loaded Worker. + * + * (If omitted, the binding will not share a cache with any other binding.) + * + */ + get id(): string { + return $.utils.getText(1, this); + } + set id(value: string) { + $.utils.setText(1, value, this); + } + toString(): string { + return "Worker_Binding_WorkerLoader_" + super.toString(); + } +} export const Worker_Binding_Which = { UNSPECIFIED: 0, /** @@ -1743,6 +1799,11 @@ export const Worker_Binding_Which = { * */ SERVICE: 7, + /** + * A binding representing access to an in-memory cache. + * + */ + DURABLE_OBJECT_CLASS: 19, /** * Binding to a named service (possibly, a worker). * @@ -1810,6 +1871,12 @@ export const Worker_Binding_Which = { * */ MEMORY_CACHE: 18, + /** + * A Durable Object class binding, without an actual storage namespace. This can be used to + * implement a facet. + * + */ + WORKER_LOADER: 20, } as const; export type Worker_Binding_Which = (typeof Worker_Binding_Which)[keyof typeof Worker_Binding_Which]; @@ -1822,6 +1889,8 @@ export class Worker_Binding extends $.Struct { static readonly WASM_MODULE = Worker_Binding_Which.WASM_MODULE; static readonly CRYPTO_KEY = Worker_Binding_Which.CRYPTO_KEY; static readonly SERVICE = Worker_Binding_Which.SERVICE; + static readonly DURABLE_OBJECT_CLASS = + Worker_Binding_Which.DURABLE_OBJECT_CLASS; static readonly DURABLE_OBJECT_NAMESPACE = Worker_Binding_Which.DURABLE_OBJECT_NAMESPACE; static readonly KV_NAMESPACE = Worker_Binding_Which.KV_NAMESPACE; @@ -1834,6 +1903,7 @@ export class Worker_Binding extends $.Struct { static readonly HYPERDRIVE = Worker_Binding_Which.HYPERDRIVE; static readonly UNSAFE_EVAL = Worker_Binding_Which.UNSAFE_EVAL; static readonly MEMORY_CACHE = Worker_Binding_Which.MEMORY_CACHE; + static readonly WORKER_LOADER = Worker_Binding_Which.WORKER_LOADER; static readonly Type = Worker_Binding_Type; static readonly DurableObjectNamespaceDesignator = Worker_Binding_DurableObjectNamespaceDesignator; @@ -2029,6 +2099,41 @@ export class Worker_Binding extends $.Struct { $.utils.setUint16(0, 7, this); $.utils.copyFrom(value, $.utils.getPointer(1, this)); } + _adoptDurableObjectClass(value: $.Orphan): void { + $.utils.setUint16(0, 19, this); + $.utils.adopt(value, $.utils.getPointer(1, this)); + } + _disownDurableObjectClass(): $.Orphan { + return $.utils.disown(this.durableObjectClass); + } + /** + * A Durable Object class binding, without an actual storage namespace. This can be used to + * implement a facet. + * + */ + get durableObjectClass(): ServiceDesignator { + $.utils.testWhich( + "durableObjectClass", + $.utils.getUint16(0, this), + 19, + this + ); + return $.utils.getStruct(1, ServiceDesignator, this); + } + _hasDurableObjectClass(): boolean { + return !$.utils.isNull($.utils.getPointer(1, this)); + } + _initDurableObjectClass(): ServiceDesignator { + $.utils.setUint16(0, 19, this); + return $.utils.initStructAt(1, ServiceDesignator, this); + } + get _isDurableObjectClass(): boolean { + return $.utils.getUint16(0, this) === 19; + } + set durableObjectClass(value: ServiceDesignator) { + $.utils.setUint16(0, 19, this); + $.utils.copyFrom(value, $.utils.getPointer(1, this)); + } _adoptDurableObjectNamespace( value: $.Orphan ): void { @@ -2318,6 +2423,29 @@ export class Worker_Binding extends $.Struct { set memoryCache(_: true) { $.utils.setUint16(0, 18, this); } + /** + * A binding representing the ability to dynamically load Workers from code presented at + * runtime. + * + * A Worker loader is not just a function that loads a Worker, but also serves as a + * cache of Workers, automatically unloading Workers that are not in use. To that end, each + * Worker must have a name, and if a Worker with that name already exists, it'll be reused. + * + */ + get workerLoader(): Worker_Binding_WorkerLoader { + $.utils.testWhich("workerLoader", $.utils.getUint16(0, this), 20, this); + return $.utils.getAs(Worker_Binding_WorkerLoader, this); + } + _initWorkerLoader(): Worker_Binding_WorkerLoader { + $.utils.setUint16(0, 20, this); + return $.utils.getAs(Worker_Binding_WorkerLoader, this); + } + get _isWorkerLoader(): boolean { + return $.utils.getUint16(0, this) === 20; + } + set workerLoader(_: true) { + $.utils.setUint16(0, 20, this); + } toString(): string { return "Worker_Binding_" + super.toString(); } diff --git a/packages/miniflare/src/runtime/config/workerd.ts b/packages/miniflare/src/runtime/config/workerd.ts index 048546f74e6f..e989228712f3 100644 --- a/packages/miniflare/src/runtime/config/workerd.ts +++ b/packages/miniflare/src/runtime/config/workerd.ts @@ -21,6 +21,7 @@ export interface Config { v8Flags?: string[]; extensions?: Extension[]; autogates?: string[]; + structuredLogging?: boolean; } export type Socket = { diff --git a/packages/miniflare/test/index.spec.ts b/packages/miniflare/test/index.spec.ts index 22d632f78dcb..734f0915113f 100644 --- a/packages/miniflare/test/index.spec.ts +++ b/packages/miniflare/test/index.spec.ts @@ -3386,3 +3386,96 @@ test("Miniflare: MINIFLARE_WORKERD_CONFIG_DEBUG controls workerd config file cre ); await mf.dispose(); }); + +test("Miniflare: logs are treated as standard stdout/stderr chunks be default", async (t) => { + const collected = { + stdout: "", + stderr: "", + }; + const mf = new Miniflare({ + modules: true, + handleRuntimeStdio(stdout, stderr) { + stdout.forEach((data) => { + collected.stdout += `${data}`; + }); + stderr.forEach((error) => { + collected.stderr += `${error}`; + }); + }, + script: ` + export default { + async fetch(req, env) { + console.log('__LOG__'); + console.warn('__WARN__'); + console.error('__ERROR__'); + console.info('__INFO__'); + console.debug('__DEBUG__'); + return new Response('Hello world!'); + } + }`, + }); + t.teardown(() => mf.dispose()); + + const response = await mf.dispatchFetch("http://localhost"); + await response.text(); + + t.is(collected.stdout, "__LOG__\n__INFO__\n__DEBUG__\n"); + t.is(collected.stderr, "__WARN__\n__ERROR__\n"); +}); + +test("Miniflare: logs are structured and all sent to stdout when structuredWorkerdLogs is true", async (t) => { + const collected = { + stdout: "", + stderr: "", + }; + const mf = new Miniflare({ + modules: true, + structuredWorkerdLogs: true, + handleRuntimeStdio(stdout, stderr) { + stdout.forEach((data) => { + collected.stdout += `${data}`; + }); + stderr.forEach((error) => { + collected.stderr += `${error}`; + }); + }, + script: ` + export default { + async fetch(req, env) { + console.log('__LOG__'); + console.warn('__WARN__'); + console.error('__ERROR__'); + console.info('__INFO__'); + console.debug('__DEBUG__'); + return new Response('Hello world!'); + } + }`, + }); + t.teardown(() => mf.dispose()); + + const response = await mf.dispatchFetch("http://localhost"); + await response.text(); + + t.regex( + collected.stdout, + /{"timestamp":\d+,"level":"log","message":"__LOG__"}/ + ); + t.regex( + collected.stdout, + /{"timestamp":\d+,"level":"warn","message":"__WARN__"}/ + ); + t.regex( + collected.stdout, + /{"timestamp":\d+,"level":"error","message":"__ERROR__"}/ + ); + t.regex( + collected.stdout, + /{"timestamp":\d+,"level":"info","message":"__INFO__"}/ + ); + t.regex( + collected.stdout, + /{"timestamp":\d+,"level":"debug","message":"__DEBUG__"}/ + ); + + t.is(collected.stderr, ""); +}); diff --git a/packages/wrangler/src/api/startDevWorker/ProxyController.ts b/packages/wrangler/src/api/startDevWorker/ProxyController.ts index f3f0ca657700..92d0f2af44ae 100644 --- a/packages/wrangler/src/api/startDevWorker/ProxyController.ts +++ b/packages/wrangler/src/api/startDevWorker/ProxyController.ts @@ -10,11 +10,8 @@ import { logConsoleMessage, maybeHandleNetworkLoadResource, } from "../../dev/inspect"; -import { - castLogLevel, - handleRuntimeStdio, - WranglerLog, -} from "../../dev/miniflare"; +import { castLogLevel, WranglerLog } from "../../dev/miniflare"; +import { handleRuntimeStdioWithStructuredLogs } from "../../dev/miniflare/stdio"; import { getHttpsOptions } from "../../https-options"; import { logger } from "../../logger"; import { getSourceMappedStack } from "../../sourcemap"; @@ -139,7 +136,8 @@ export class ProxyController extends Controller { }, this.localServerReady.promise ), - handleRuntimeStdio, + handleRuntimeStdio: handleRuntimeStdioWithStructuredLogs, + structuredWorkerdLogs: true, liveReload: false, }; diff --git a/packages/wrangler/src/dev/miniflare.ts b/packages/wrangler/src/dev/miniflare/index.ts similarity index 87% rename from packages/wrangler/src/dev/miniflare.ts rename to packages/wrangler/src/dev/miniflare/index.ts index efb4ce1540f2..fb89f5dd2467 100644 --- a/packages/wrangler/src/dev/miniflare.ts +++ b/packages/wrangler/src/dev/miniflare/index.ts @@ -7,29 +7,29 @@ import { EXTERNAL_AI_WORKER_NAME, EXTERNAL_AI_WORKER_SCRIPT, getAIFetcher, -} from "../ai/fetcher"; -import { ModuleTypeToRuleType } from "../deployment-bundle/module-collection"; -import { withSourceURLs } from "../deployment-bundle/source-url"; -import { UserError } from "../errors"; +} from "../../ai/fetcher"; +import { ModuleTypeToRuleType } from "../../deployment-bundle/module-collection"; +import { withSourceURLs } from "../../deployment-bundle/source-url"; +import { UserError } from "../../errors"; import { EXTERNAL_IMAGES_WORKER_NAME, EXTERNAL_IMAGES_WORKER_SCRIPT, getImagesRemoteFetcher, -} from "../images/fetcher"; -import { logger } from "../logger"; -import { getSourceMappedString } from "../sourcemap"; -import { updateCheck } from "../update-check"; -import { warnOrError } from "../utils/print-bindings"; +} from "../../images/fetcher"; +import { logger } from "../../logger"; +import { updateCheck } from "../../update-check"; +import { warnOrError } from "../../utils/print-bindings"; import { EXTERNAL_VECTORIZE_WORKER_NAME, EXTERNAL_VECTORIZE_WORKER_SCRIPT, MakeVectorizeFetcher, -} from "../vectorize/fetcher"; -import { getClassNamesWhichUseSQLite } from "./class-names-sqlite"; -import type { ServiceFetch } from "../api"; -import type { AssetsOptions } from "../assets"; -import type { Config } from "../config"; -import type { ContainerEngine } from "../config/environment"; +} from "../../vectorize/fetcher"; +import { getClassNamesWhichUseSQLite } from "../class-names-sqlite"; +import { handleRuntimeStdioWithStructuredLogs } from "./stdio"; +import type { ServiceFetch } from "../../api"; +import type { AssetsOptions } from "../../assets"; +import type { Config } from "../../config"; +import type { ContainerEngine } from "../../config/environment"; import type { CfD1Database, CfDispatchNamespace, @@ -43,11 +43,11 @@ import type { CfUnsafeBinding, CfWorkerInit, CfWorkflow, -} from "../deployment-bundle/worker"; -import type { WorkerRegistry } from "../dev-registry"; -import type { LoggerLevel } from "../logger"; -import type { LegacyAssetPaths } from "../sites"; -import type { EsbuildBundle } from "./use-esbuild"; +} from "../../deployment-bundle/worker"; +import type { WorkerRegistry } from "../../dev-registry"; +import type { LoggerLevel } from "../../logger"; +import type { LegacyAssetPaths } from "../../sites"; +import type { EsbuildBundle } from "../use-esbuild"; import type { DOContainerOptions, MiniflareOptions, @@ -56,7 +56,6 @@ import type { WorkerOptions, } from "miniflare"; import type { UUID } from "node:crypto"; -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 @@ -1159,137 +1158,6 @@ export function buildSitesOptions({ } } -export function handleRuntimeStdio(stdout: Readable, stderr: Readable) { - // ASSUMPTION: each chunk is a whole message from workerd - // This may not hold across OSes/architectures, but it seems to work on macOS M-line - // I'm going with this simple approach to avoid complicating this too early - // We can iterate on this heuristic in the future if it causes issues - const classifiers = { - // Is this chunk a big chonky barf from workerd that we want to hijack to cleanup/ignore? - isBarf(chunk: string) { - const containsLlvmSymbolizerWarning = chunk.includes( - "Not symbolizing stack traces because $LLVM_SYMBOLIZER is not set" - ); - const containsRecursiveIsolateLockWarning = chunk.includes( - "took recursive isolate lock" - ); - // Matches stack traces from workerd - // - on unix: groups of 9 hex digits separated by spaces - // - on windows: groups of 12 hex digits, or a single digit 0, separated by spaces - const containsHexStack = /stack:( (0|[a-f\d]{4,})){3,}/.test(chunk); - - return ( - containsLlvmSymbolizerWarning || - containsRecursiveIsolateLockWarning || - containsHexStack - ); - }, - // Is this chunk an Address In Use error? - isAddressInUse(chunk: string) { - return chunk.includes("Address already in use; toString() = "); - }, - isWarning(chunk: string) { - return /\.c\+\+:\d+: warning:/.test(chunk); - }, - isCodeMovedWarning(chunk: string) { - return /CODE_MOVED for unknown code block/.test(chunk); - }, - isAccessViolation(chunk: string) { - return chunk.includes("access violation;"); - }, - }; - - stdout.on("data", (chunk: Buffer | string) => { - chunk = chunk.toString().trim(); - - if (classifiers.isBarf(chunk)) { - // this is a big chonky barf from workerd that we want to hijack to cleanup/ignore - - // CLEANABLE: - // there are no known cases to cleanup yet - // but, as they are identified, we will do that here - - // IGNORABLE: - // anything else not handled above is considered ignorable - // so send it to the debug logs which are discarded unless - // the user explicitly sets a logLevel indicating they care - logger.debug(chunk); - } - - // known case: warnings are not info, log them as such - else if (classifiers.isWarning(chunk)) { - logger.warn(chunk); - } - - // anything not explicitly handled above should be logged as info (via stdout) - else { - logger.info(getSourceMappedString(chunk)); - } - }); - - stderr.on("data", (chunk: Buffer | string) => { - chunk = chunk.toString().trim(); - - if (classifiers.isBarf(chunk)) { - // this is a big chonky barf from workerd that we want to hijack to cleanup/ignore - - // CLEANABLE: - // known case to cleanup: Address in use errors - if (classifiers.isAddressInUse(chunk)) { - const address = chunk.match( - /Address already in use; toString\(\) = (.+)\n/ - )?.[1]; - - logger.error( - `Address already in use (${address}). Please check that you are not already running a server on this address or specify a different port with --port.` - ); - - // Log the original error to the debug logs. - logger.debug(chunk); - } - // In the past we have seen Access Violation errors on Windows, which may be caused by an outdated - // version of the Windows OS or the Microsoft Visual C++ Redistributable. - // See https://github.com/cloudflare/workers-sdk/issues/6170#issuecomment-2245209918 - else if (classifiers.isAccessViolation(chunk)) { - let error = "There was an access violation in the runtime."; - if (process.platform === "win32") { - error += - "\nOn Windows, this may be caused by an outdated Microsoft Visual C++ Redistributable library.\n" + - "Check that you have the latest version installed.\n" + - "See https://learn.microsoft.com/en-us/cpp/windows/latest-supported-vc-redist."; - } - logger.error(error); - - // Log the original error to the debug logs. - logger.debug(chunk); - } - - // 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 - else { - logger.debug(chunk); - } - } - - // known case: warnings are not errors, log them as such - else if (classifiers.isWarning(chunk)) { - logger.warn(chunk); - } - - // known case: "error: CODE_MOVED for unknown code block?", warning for workerd devs, not application devs - else if (classifiers.isCodeMovedWarning(chunk)) { - // ignore entirely, don't even send it to the debug log file - } - - // anything not explicitly handled above should be logged as an error (via stderr) - else { - logger.error(getSourceMappedString(chunk)); - } - }); -} - let didWarnMiniflareCronSupport = false; let didWarnMiniflareVectorizeSupport = false; let didWarnAiAccountUsage = false; @@ -1376,7 +1244,8 @@ export async function buildMiniflareOptions( logRequests: false, log, verbose: logger.loggerLevel === "debug", - handleRuntimeStdio, + handleRuntimeStdio: handleRuntimeStdioWithStructuredLogs, + structuredWorkerdLogs: true, defaultPersistRoot, workers: [ { diff --git a/packages/wrangler/src/dev/miniflare/stdio.ts b/packages/wrangler/src/dev/miniflare/stdio.ts new file mode 100644 index 000000000000..3953d4a8e658 --- /dev/null +++ b/packages/wrangler/src/dev/miniflare/stdio.ts @@ -0,0 +1,232 @@ +import { logger } from "../../logger"; +import { getSourceMappedString } from "../../sourcemap"; +import type { Readable } from "node:stream"; + +/** + * Handler function to pass to Miniflare instances for handling the Worker process stream. + * + * This function can be used when Miniflare's `structuredWorkerdLogs` option is set to `true`. + * + * @param stdout The stdout stream connected to Miniflare's Workerd process + * @param stderr The stderr stream connected to Miniflare's Workerd process + */ +export function handleRuntimeStdioWithStructuredLogs( + stdout: Readable, + stderr: Readable +) { + stdout.on("data", getProcessStreamDataListener("stdout")); + stderr.on("data", getProcessStreamDataListener("stderr")); +} + +/** + * Creates a listener for the "data" event of a process stream associated to Miniflare's Workerd process. + * + * This function can be used when Miniflare's `structuredWorkerdLogs` option is set to `true`. + * + * @param processStream The target process stream + * @returns the listener to set for the stream's "data" event + */ +function getProcessStreamDataListener(processStream: "stdout" | "stderr") { + let streamAccumulator = ""; + + return (chunk: Buffer | string) => { + const fullStreamOutput = `${streamAccumulator}${chunk}`; + + let currentLogsStr = ""; + + // Structured logs are divided by newlines so let's get the + // last one, we know that anything in between will include + // one or more structured logs + const lastNewlineIdx = fullStreamOutput.lastIndexOf("\n"); + + if (lastNewlineIdx > 0) { + // If we've found a newline we will take the structured logs + // up to that point, the rest (which is the beginning of a + // new structured log) will be saved for later + currentLogsStr = fullStreamOutput.slice(0, lastNewlineIdx); + streamAccumulator = fullStreamOutput.slice(lastNewlineIdx + 1); + } else { + // If we didn't find a newline we're dealing with a structured + // log that has been split, so let's save the whole thing for + // later (so that we can process the log once we've seen it + // in full) + streamAccumulator = fullStreamOutput; + } + + const lines = currentLogsStr.split("\n"); + + for (const line of lines) { + const structuredLog = parseStructuredLog(line); + if (structuredLog) { + logStructuredLog(structuredLog, processStream); + } else { + const level = processStream === "stdout" ? "log" : "error"; + // Unexpectedly we've received a line that is not a structured log, so we simply + // log it to the most likely appropriate logger level + logger[level](line); + } + } + }; +} + +type WorkerdStructuredLog = { + timestamp: number; + level: string; + message: string; +}; + +/** + * Parses a string to obtain the potential structured log the string represents. + * + * @param str Target string + * @returns The structured log extracted from the string or null is the string doesn't represent a structured log + */ +function parseStructuredLog(str: string): WorkerdStructuredLog | null { + try { + const maybeStructuredLog = JSON.parse(str) as Record; + + if (typeof maybeStructuredLog !== "object" || maybeStructuredLog === null) { + return null; + } + + const timestamp = parseInt(maybeStructuredLog.timestamp); + + if ( + isNaN(timestamp) || + typeof maybeStructuredLog.level !== "string" || + typeof maybeStructuredLog.message !== "string" + ) { + return null; + } + + return { + timestamp, + level: maybeStructuredLog.level, + message: maybeStructuredLog.message, + }; + } catch { + return null; + } +} + +/** + * Logs a structured log in the most appropriate way on the most appropriate log level. + * + * @param structuredLog The structured log to print + * @param processStream The process stream from where the structured log comes from + */ +function logStructuredLog( + { level, message }: WorkerdStructuredLog, + processStream: "stdout" | "stderr" +): void { + // TODO: the following code analyzes the message without considering its log level, + // ideally, in order to avoid false positives, we should run this logic scoped + // to the relevant log levels (as we do for `isCodeMovedWarning`) + if (messageClassifiers.isBarf(message)) { + // 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 (messageClassifiers.isAddressInUse(message)) { + const address = message.match( + /Address already in use; toString\(\) = (.+)\n/ + )?.[1]; + + logger.error( + `Address already in use (${address}). Please check that you are not already running a server on this address or specify a different port with --port.` + ); + + // Also log the original error to the debug logs. + return logger.debug(message); + } + + // In the past we have seen Access Violation errors on Windows, which may be caused by an outdated + // version of the Windows OS or the Microsoft Visual C++ Redistributable. + // See https://github.com/cloudflare/workers-sdk/issues/6170#issuecomment-2245209918 + if (messageClassifiers.isAccessViolation(message)) { + let error = "There was an access violation in the runtime."; + if (process.platform === "win32") { + error += + "\nOn Windows, this may be caused by an outdated Microsoft Visual C++ Redistributable library.\n" + + "Check that you have the latest version installed.\n" + + "See https://learn.microsoft.com/en-us/cpp/windows/latest-supported-vc-redist."; + } + logger.error(error); + + // Also log the original error to the debug logs. + return logger.debug(message); + } + + // 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 + return logger.debug(message); + } + + if ( + (level === "info" || level === "error") && + messageClassifiers.isCodeMovedWarning(message) + ) { + // known case: "error: CODE_MOVED for unknown code block?", warning for workerd devs, not application devs + // ignore entirely, don't even send it to the debug log file + // workerd references: + // - https://github.com/cloudflare/workerd/blob/d170f4d9b/src/workerd/jsg/setup.c%2B%2B#L566 + // - https://github.com/cloudflare/workerd/blob/d170f4d9b/src/workerd/jsg/setup.c%2B%2B#L572 + return; + } + + if (level === "warn") { + return logger.warn(message); + } + + if (level === "info") { + return logger.info(message); + } + + if (level === "debug") { + return logger.debug(message); + } + + if (level === "error") { + return logger.error(getSourceMappedString(message)); + } + + if (processStream === "stderr") { + return logger.error(getSourceMappedString(message)); + } else { + return logger.log(getSourceMappedString(message)); + } +} + +const messageClassifiers = { + // Is this chunk a big chonky barf from workerd that we want to hijack to cleanup/ignore? + isBarf(chunk: string) { + const containsLlvmSymbolizerWarning = chunk.includes( + "Not symbolizing stack traces because $LLVM_SYMBOLIZER is not set" + ); + const containsRecursiveIsolateLockWarning = chunk.includes( + "took recursive isolate lock" + ); + // Matches stack traces from workerd + // - on unix: groups of 9 hex digits separated by spaces + // - on windows: groups of 12 hex digits, or a single digit 0, separated by spaces + const containsHexStack = /stack:( (0|[a-f\d]{4,})){3,}/.test(chunk); + + return ( + containsLlvmSymbolizerWarning || + containsRecursiveIsolateLockWarning || + containsHexStack + ); + }, + // Is this chunk an Address In Use error? + isAddressInUse(chunk: string) { + return chunk.includes("Address already in use; toString() = "); + }, + isCodeMovedWarning(chunk: string) { + return /CODE_MOVED for unknown code block/.test(chunk); + }, + isAccessViolation(chunk: string) { + return chunk.includes("access violation;"); + }, +}; diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 0e735fc71cb1..c5eca7fa35d6 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -1156,6 +1156,21 @@ importers: specifier: workspace:* version: link:../../packages/wrangler + fixtures/worker-logs: + devDependencies: + '@cloudflare/workers-tsconfig': + specifier: workspace:^ + version: link:../../packages/workers-tsconfig + typescript: + specifier: catalog:default + version: 5.8.3 + vitest: + specifier: catalog:default + version: 3.2.3(@types/debug@4.1.12)(@types/node@20.19.9)(@vitest/ui@3.2.3)(jiti@2.4.2)(lightningcss@1.29.2)(msw@2.4.3(typescript@5.8.3))(supports-color@9.2.2) + wrangler: + specifier: workspace:* + version: link:../../packages/wrangler + fixtures/worker-ts: devDependencies: '@cloudflare/workers-types':