Skip to content

Commit b4d1373

Browse files
dario-piotrowiczdario-piotrowicz
authored
fix wrangler dev logs being logged on the incorrect level in some cases (#10004)
* [miniflare] add `structuredWorkerdLogs` option * fix `wrangler dev` logs being logged on the incorrect level in some cases
1 parent 354a001 commit b4d1373

File tree

19 files changed

+914
-162
lines changed

19 files changed

+914
-162
lines changed

‎.changeset/deep-lizards-move.md‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,35 @@
1+
---
2+
"wrangler": patch
3+
---
4+
5+
fix `wrangler dev` logs being logged on the incorrect level in some cases
6+
7+
currently the way `wrangler dev` prints logs is faulty, for example the following code
8+
9+
```js
10+
console.error("this is an error");
11+
console.warn("this is a warning");
12+
console.debug("this is a debug");
13+
```
14+
15+
inside a worker would cause the following logs:
16+
17+
```text
18+
✘ [ERROR] this is an error
19+
20+
✘ [ERROR] this is a warning
21+
22+
this is a debug
23+
```
24+
25+
(note that the warning is printed as an error and the debug log is printed even if by default it should not)
26+
27+
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:
28+
29+
```text
30+
✘ [ERROR] this is an error
31+
32+
▲ [WARNING] this is a warning
33+
```
34+
35+
(running `wrangler dev` with the `--log-level=debug` flag will also cause the debug log to be included as well)

‎.changeset/full-areas-lick.md‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
---
2+
"miniflare": minor
3+
---
4+
5+
add `structuredWorkerdLogs` option
6+
7+
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

‎fixtures/shared/src/run-wrangler-long-lived.ts‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -87,7 +87,9 @@ async function runLongLivedWrangler(
8787
chunks.push(chunk);
8888
});
8989
wranglerProcess.stderr?.on("data", (chunk) => {
90-
console.log(`[${command}]`, chunk.toString());
90+
if (process.env.WRANGLER_LOG === "debug") {
91+
console.log(`[${command}]`, chunk.toString());
92+
}
9193
chunks.push(chunk);
9294
});
9395
wranglerProcess.once("exit", (exitCode) => {

‎fixtures/worker-logs/package.json‎

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,22 @@
1+
{
2+
"name": "@fixture/worker-logs",
3+
"private": true,
4+
"scripts": {
5+
"check:type": "tsc",
6+
"dev": "pnpm dev.module",
7+
"dev.module": "wrangler dev -c wrangler.module.jsonc",
8+
"dev.service": "wrangler dev -c wrangler.service.jsonc",
9+
"start": "pnpm dev.module",
10+
"test:ci": "vitest run",
11+
"test:watch": "vitest"
12+
},
13+
"devDependencies": {
14+
"@cloudflare/workers-tsconfig": "workspace:^",
15+
"typescript": "catalog:default",
16+
"vitest": "catalog:default",
17+
"wrangler": "workspace:*"
18+
},
19+
"volta": {
20+
"extends": "../../package.json"
21+
}
22+
}

‎fixtures/worker-logs/src/module.js‎

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,25 @@
1+
export default {
2+
async fetch(request, env) {
3+
const response = new Response("Hello");
4+
5+
const customMessage = request.headers.get("x-custom-message");
6+
if (customMessage) {
7+
if (customMessage === "%__VERY_VERY_LONG_MESSAGE_%") {
8+
// We can't simply pass a huge long message as a header thus
9+
// why a placeholder is used here
10+
console.log("z".repeat(2 ** 20));
11+
} else {
12+
console.log(customMessage);
13+
}
14+
return response;
15+
}
16+
17+
console.log("<<<<<this is a log>>>>>");
18+
console.warn("<<<<<this is a warning>>>>>");
19+
console.error("<<<<<this is an error>>>>>");
20+
console.debug("<<<<<this is a debug message>>>>>");
21+
console.info("<<<<<this is an info message>>>>>");
22+
23+
return response;
24+
},
25+
};

‎fixtures/worker-logs/src/service.js‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,12 @@
1+
async function handler(request) {
2+
console.log("<<<<<this is a log>>>>>");
3+
console.warn("<<<<<this is a warning>>>>>");
4+
console.error("<<<<<this is an error>>>>>");
5+
console.debug("<<<<<this is a debug message>>>>>");
6+
console.info("<<<<<this is an info message>>>>>");
7+
return new Response("Hello");
8+
}
9+
10+
addEventListener("fetch", (event) => {
11+
event.respondWith(handler(event.request));
12+
});

‎fixtures/worker-logs/tests/index.test.ts‎

Lines changed: 273 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,273 @@
1+
import { setTimeout } from "node:timers/promises";
2+
import { resolve } from "path";
3+
import { describe, test } from "vitest";
4+
import { runWranglerDev } from "../../shared/src/run-wrangler-long-lived";
5+
6+
async function getWranglerDevOutput(
7+
type: "module" | "service",
8+
extraArgs: string[] = [],
9+
customMessage?: string,
10+
requests = 1,
11+
env = {}
12+
) {
13+
const { ip, port, stop, getOutput } = await runWranglerDev(
14+
resolve(__dirname, ".."),
15+
[
16+
`-c=wrangler.${type}.jsonc`,
17+
"--port=0",
18+
"--inspector-port=0",
19+
...extraArgs,
20+
],
21+
env
22+
);
23+
24+
const request = new Request(`http://${ip}:${port}`);
25+
if (customMessage) {
26+
request.headers.set("x-custom-message", customMessage);
27+
}
28+
29+
for (let i = 0; i < requests; i++) {
30+
const response = await fetch(request);
31+
await response.text();
32+
33+
// We wait for a bit for the output stream to be completely ready
34+
// (this is a bit slow but it's generic to be used by all tests
35+
// in this file, it also seems to make the tests very stable)
36+
await setTimeout(500);
37+
}
38+
39+
await stop();
40+
41+
let output = getOutput();
42+
43+
output = output
44+
// Windows gets a different marker for ✘, so let's normalize it here
45+
// so that these tests can be platform independent
46+
.replaceAll("✘", "X")
47+
// Let's also normalize Windows newlines
48+
.replaceAll("\r\n", "\n");
49+
50+
// Let's filter out lines we're not interested in
51+
output = output
52+
.split("\n")
53+
.filter((line) =>
54+
logLineToIgnoreRegexps.every((regex) => !regex.test(line))
55+
)
56+
// let's also sort the logs for more stability of the tests, ideally
57+
// we would want to test the log's ordering as well but that seems
58+
// to cause flakes in the CI runs
59+
.sort()
60+
.join("\n");
61+
62+
return output;
63+
}
64+
65+
describe("'wrangler dev' correctly displays logs", () => {
66+
describe("module workers", () => {
67+
test("default behavior", async ({ expect }) => {
68+
const output = await getWranglerDevOutput("module");
69+
expect(output).toMatchInlineSnapshot(`
70+
"X [ERROR] <<<<<this is an error>>>>>
71+
▲ [WARNING] <<<<<this is a warning>>>>>
72+
<<<<<this is a log>>>>>
73+
<<<<<this is an info message>>>>>"
74+
`);
75+
});
76+
77+
test("with --log-level=log", async ({ expect }) => {
78+
const output = await getWranglerDevOutput("module", ["--log-level=log"]);
79+
expect(output).toMatchInlineSnapshot(`
80+
"X [ERROR] <<<<<this is an error>>>>>
81+
▲ [WARNING] <<<<<this is a warning>>>>>
82+
<<<<<this is a log>>>>>
83+
<<<<<this is an info message>>>>>"
84+
`);
85+
});
86+
87+
test("with --log-level=info", async ({ expect }) => {
88+
const output = await getWranglerDevOutput("module", ["--log-level=info"]);
89+
expect(output).toMatchInlineSnapshot(`
90+
"X [ERROR] <<<<<this is an error>>>>>
91+
▲ [WARNING] <<<<<this is a warning>>>>>
92+
<<<<<this is an info message>>>>>"
93+
`);
94+
});
95+
96+
test("with --log-level=warn", async ({ expect }) => {
97+
const output = await getWranglerDevOutput("module", ["--log-level=warn"]);
98+
expect(output).toMatchInlineSnapshot(`
99+
"X [ERROR] <<<<<this is an error>>>>>
100+
▲ [WARNING] <<<<<this is a warning>>>>>"
101+
`);
102+
});
103+
104+
test("with --log-level=error", async ({ expect }) => {
105+
const output = await getWranglerDevOutput("module", [
106+
"--log-level=error",
107+
]);
108+
expect(output).toMatchInlineSnapshot(
109+
`"X [ERROR] <<<<<this is an error>>>>>"`
110+
);
111+
});
112+
113+
test("with --log-level=debug", async ({ expect }) => {
114+
const output = await getWranglerDevOutput(
115+
"module",
116+
["--log-level=debug"],
117+
undefined,
118+
// For some reason in debug mode two requests are
119+
// needed to trigger the log here...
120+
2
121+
);
122+
expect(output).toContain("<<<<<this is a debug message>>>>>");
123+
});
124+
125+
test('with WRANGLER_LOG="debug"', async ({ expect }) => {
126+
const output = await getWranglerDevOutput(
127+
"module",
128+
[],
129+
undefined,
130+
// For some reason in debug mode two requests are
131+
// needed to trigger the log here...
132+
2,
133+
{ WRANGLER_LOG: "debug" }
134+
);
135+
expect(output).toContain("<<<<<this is a debug message>>>>>");
136+
});
137+
138+
test("with --log-level=none", async ({ expect }) => {
139+
const output = await getWranglerDevOutput("module", ["--log-level=none"]);
140+
expect(output).toMatchInlineSnapshot(`""`);
141+
});
142+
143+
// the workerd structured logs follow this structure:
144+
// {"timestamp":<number>,"level":"<string>","message":"<string>"}
145+
// the following tests check for edge case scenario where the following
146+
// structure could not get detected correctly
147+
describe("edge case scenarios", () => {
148+
test("base case", async ({ expect }) => {
149+
const output = await getWranglerDevOutput("module", [], "hello");
150+
expect(output).toMatchInlineSnapshot(`"hello"`);
151+
});
152+
test("quotes in message", async ({ expect }) => {
153+
const output = await getWranglerDevOutput("module", [], 'hel"lo');
154+
expect(output).toMatchInlineSnapshot(`"hel"lo"`);
155+
});
156+
157+
test("braces in message", async ({ expect }) => {
158+
const output = await getWranglerDevOutput("module", [], "hel{}lo");
159+
expect(output).toMatchInlineSnapshot(`"hel{}lo"`);
160+
});
161+
162+
test("a workerd structured message in the message", async ({
163+
expect,
164+
}) => {
165+
const output = await getWranglerDevOutput(
166+
"module",
167+
[],
168+
'This is an example of a Workerd structured log: {"timestamp":1234567890,"level":"log","message":"Hello World!"}'
169+
);
170+
expect(output).toMatchInlineSnapshot(
171+
`"This is an example of a Workerd structured log: {"timestamp":1234567890,"level":"log","message":"Hello World!"}"`
172+
);
173+
});
174+
175+
test("a very very very long message (that gets split in multiple chunks)", async ({
176+
expect,
177+
}) => {
178+
const output = await getWranglerDevOutput(
179+
"module",
180+
[],
181+
"%__VERY_VERY_LONG_MESSAGE_%"
182+
);
183+
expect(output).toMatch(new RegExp(`^z{${2 ** 20}}$`));
184+
});
185+
});
186+
});
187+
188+
// Note: service workers logs are handled differently from standard logs (and are built on top of
189+
// inspector Runtime.consoleAPICalled events), they don't work as well as logs for module
190+
// workers. Service workers are also deprecated so it's not a huge deal, the following
191+
// tests are only here in place to make sure that the basic logging functionality of
192+
// service workers does work
193+
describe("service workers", () => {
194+
test("default behavior", async ({ expect }) => {
195+
const output = await getWranglerDevOutput("service");
196+
expect(output).toMatchInlineSnapshot(`
197+
"<<<<<this is a log>>>>>
198+
<<<<<this is a warning>>>>>
199+
<<<<<this is an error>>>>>
200+
<<<<<this is an info message>>>>>"
201+
`);
202+
});
203+
204+
test("with --log-level=log", async ({ expect }) => {
205+
const output = await getWranglerDevOutput("service", ["--log-level=log"]);
206+
expect(output).toMatchInlineSnapshot(`
207+
"<<<<<this is a log>>>>>
208+
<<<<<this is a warning>>>>>
209+
<<<<<this is an error>>>>>
210+
<<<<<this is an info message>>>>>"
211+
`);
212+
});
213+
214+
test("with --log-level=info", async ({ expect }) => {
215+
const output = await getWranglerDevOutput("service", [
216+
"--log-level=info",
217+
]);
218+
expect(output).toMatchInlineSnapshot(`
219+
"<<<<<this is a warning>>>>>
220+
<<<<<this is an error>>>>>
221+
<<<<<this is an info message>>>>>"
222+
`);
223+
});
224+
225+
test("with --log-level=warn", async ({ expect }) => {
226+
const output = await getWranglerDevOutput("service", [
227+
"--log-level=warn",
228+
]);
229+
expect(output).toMatchInlineSnapshot(`
230+
"<<<<<this is a warning>>>>>
231+
<<<<<this is an error>>>>>"
232+
`);
233+
});
234+
235+
test("with --log-level=error", async ({ expect }) => {
236+
const output = await getWranglerDevOutput("service", [
237+
"--log-level=error",
238+
]);
239+
expect(output).toMatchInlineSnapshot(`"<<<<<this is an error>>>>>"`);
240+
});
241+
242+
test("with --log-level=debug", async ({ expect }) => {
243+
const output = await getWranglerDevOutput("service", [
244+
"--log-level=debug",
245+
]);
246+
expect(output).toContain("<<<<<this is a debug message>>>>>");
247+
});
248+
249+
test("with --log-level=none", async ({ expect }) => {
250+
const output = await getWranglerDevOutput("service", [
251+
"--log-level=none",
252+
]);
253+
expect(output).toMatchInlineSnapshot(`""`);
254+
});
255+
});
256+
});
257+
258+
const logLineToIgnoreRegexps = [
259+
// let's skip empty lines
260+
/^\s*$/,
261+
// part of the wrangler banner
262+
/⛅️ wrangler/,
263+
// divisor after the wrangler banner
264+
/^─+$/,
265+
// wrangler logs such as ` ⎔ Starting local server...`
266+
/^\s*⎔/,
267+
// wrangler's ready on log
268+
/^\[wrangler:info\] Ready on http:\/\/[^:]+:\d+$/,
269+
// positive response to get request
270+
/^\[wrangler:info\] GET \/ 200 OK \(\d+ms\)$/,
271+
// let's skip the telemetry messages
272+
/^Cloudflare collects anonymous telemetry about your usage of Wrangler\. Learn more at https:\/\/.*$/,
273+
];

0 commit comments

Comments
 (0)