diff --git a/.changeset/demote-browser-request-logs.md b/.changeset/demote-browser-request-logs.md new file mode 100644 index 00000000000..070687f1edc --- /dev/null +++ b/.changeset/demote-browser-request-logs.md @@ -0,0 +1,10 @@ +--- +"miniflare": patch +"wrangler": patch +--- + +Log browser-made requests at debug level in dev + +A browser asks for `/favicon.ico` on its own, and Chrome DevTools probes `/.well-known/appspecific/com.chrome.devtools.json` on every page load. Neither is a request you made, and on a page you reload often they crowd out your app's own traffic in the `wrangler dev` request log. + +These are now logged at `debug` instead of `info`, so a default session stays quiet while `--log-level debug` still shows every request. If the Worker returns a 5xx serving one of them it stays at `info`, so a broken handler is never quietly demoted. diff --git a/.changeset/hide-vite-internals.md b/.changeset/hide-vite-internals.md new file mode 100644 index 00000000000..6a237e3b4cf --- /dev/null +++ b/.changeset/hide-vite-internals.md @@ -0,0 +1,10 @@ +--- +"miniflare": patch +"wrangler": patch +--- + +Keep Vite's internal requests out of the Observability views + +Under the Vite plugin, Vite makes its own requests to drive the module runner. Those were listed as traces alongside your app's, and their RPC dispatch showed up as logs — in one session that was 8 of 11 rows in the Traces list. They aren't requests you made and don't exist in a deployed Worker, so they're now left out of both lists. + +Failures are never hidden, and a plain `wrangler dev` session is unaffected. diff --git a/packages/local-explorer-ui/src/__tests__/observability/observability.test.ts b/packages/local-explorer-ui/src/__tests__/observability/observability.test.ts index 8a1834eb7e5..a22376078bf 100644 --- a/packages/local-explorer-ui/src/__tests__/observability/observability.test.ts +++ b/packages/local-explorer-ui/src/__tests__/observability/observability.test.ts @@ -1,4 +1,5 @@ -import { describe, test } from "vitest"; +import { beforeEach, describe, test, vi } from "vitest"; +import { observabilityQuery } from "../../api"; import { buildSpanTree, buildWaterfall, @@ -6,6 +7,8 @@ import { formatLogMessage, isRunning, isViteWrapperSpan, + listEvents, + listTraces, parseAttributes, spanIsError, stripDevRunnerSpans, @@ -15,6 +18,11 @@ import { } from "../../utils/observability"; import type { Span } from "../../utils/observability"; +vi.mock("../../api", () => ({ + observabilityQuery: vi.fn(), + observabilityClear: vi.fn(), +})); + function span(partial: Partial): Span { return { trace_id: "t", @@ -150,6 +158,81 @@ describe("isViteWrapperSpan", () => { }); }); +describe("listEvents filtering", () => { + beforeEach(() => { + vi.mocked(observabilityQuery).mockReset(); + vi.mocked(observabilityQuery).mockResolvedValue({ + data: { result: { columns: [], rows: [] } }, + } as never); + }); + + async function eventsSql(): Promise { + await listEvents(); + const call = vi.mocked(observabilityQuery).mock.calls.at(-1)?.[0]; + return String((call as { body?: { sql?: string } })?.body?.sql ?? ""); + } + + test("only hides executeCallback logs when the trace is really Vite dev", async ({ + expect, + }) => { + // A `wrangler dev` user can have their own executeCallback RPC method, so + // the shape rule must be paired with a wrapper-span check on the trace. + const sql = await eventsSql(); + expect(sql).toMatch( + /executeCallback[\s\S]*EXISTS[\s\S]*v\.trace_id = l\.trace_id/ + ); + }); + + test("filters in the WHERE clause, before LIMIT", async ({ expect }) => { + // Filtering after LIMIT would short-change the page and skew its count. + const sql = await eventsSql(); + const where = sql.indexOf("WHERE"); + expect(where).toBeGreaterThan(-1); + expect(sql.indexOf("executeCallback")).toBeGreaterThan(where); + expect(sql.lastIndexOf("LIMIT ?")).toBeGreaterThan( + sql.indexOf("executeCallback") + ); + }); +}); + +describe("listTraces filtering", () => { + beforeEach(() => { + vi.mocked(observabilityQuery).mockReset(); + vi.mocked(observabilityQuery).mockResolvedValue({ + data: { result: { columns: [], rows: [] } }, + } as never); + }); + + async function tracesSql(): Promise { + await listTraces(); + const call = vi.mocked(observabilityQuery).mock.calls.at(-1)?.[0]; + return String((call as { body?: { sql?: string } })?.body?.sql ?? ""); + } + + test("hides Vite's own internal requests by path", async ({ expect }) => { + const sql = await tracesSql(); + expect(sql).toContain("'/__vite_plugin_cloudflare'"); + }); + + test("doesn't marker-match the root span, which would hide real traffic", async ({ + expect, + }) => { + // Vite routes every request through __router-worker__, so a root-span + // marker match would blank out the user's own requests too. + const sql = await tracesSql(); + expect(sql).not.toContain("__router-worker__"); + }); + + test("keeps a hidden Vite request visible when it failed", async ({ + expect, + }) => { + // Only a 5xx (or an uncaught error) counts as a failure — a 404 is just how + // an unserved path answers. + const sql = await tracesSql(); + expect(sql).toMatch(/AND NOT COALESCE\([\s\S]*>= 500/); + }); +}); + describe("traceExtentMs", () => { test("measures latest end minus earliest start", ({ expect }) => { const spans = [ diff --git a/packages/local-explorer-ui/src/utils/observability.ts b/packages/local-explorer-ui/src/utils/observability.ts index d39ce2703a2..9957d93c7db 100644 --- a/packages/local-explorer-ui/src/utils/observability.ts +++ b/packages/local-explorer-ui/src/utils/observability.ts @@ -152,6 +152,9 @@ const VITE_WRAPPER_MARKERS = [ "__vite_plugin_cloudflare", // init + get-export-types internal paths ]; +/** Path prefix of the internal requests Vite makes to drive the module runner. */ +const VITE_INTERNAL_PATH_PREFIX = "/__vite_plugin_cloudflare"; + /** True if the span comes from Vite's runner/wrapper plumbing, not user code. */ export function isViteWrapperSpan( span: Pick @@ -160,6 +163,16 @@ export function isViteWrapperSpan( return VITE_WRAPPER_MARKERS.some((marker) => haystack.includes(marker)); } +/** + * The Vite dev module-runner's jsrpc dispatch method. User code is evaluated + * inside the runner Durable Object via `stub.executeCallback(id)`, which shows + * up as a `jsrpc` span with this method (verified against a real `vite dev` + * capture — these spans do NOT carry the runner class name in their attributes, + * so we recognise them by shape rather than by a `__VITE_RUNNER_OBJECT__` + * string). + */ +const RUNNER_DISPATCH_METHOD = "executeCallback"; + /** * Order spans into a depth-first waterfall: each span nested under its parent * (by `parent_id`), siblings ordered by start time, with a timeline offset/width @@ -333,6 +346,64 @@ export interface TraceFilters { // 4xx/5xx request otherwise looks like a successful ("ok") invocation. const SPAN_IS_ERROR = `(error IS NOT NULL OR (outcome IS NOT NULL AND outcome != 'ok') OR CAST(json_extract(json(attributes), '$."http.response.status_code"') AS INTEGER) >= 400)`; +/** SQL: the path of span `alias`'s request URL, without scheme, host or query. */ +function urlPathSql(alias: string): string { + const url = `json_extract(json(${alias}.attributes), '$."url.full"')`; + const afterScheme = `substr(${url}, instr(${url}, '//') + 2)`; + return `substr(${afterScheme}, instr(${afterScheme}, '/'))`; +} + +/** + * SQL: request `alias` didn't just go unserved, it broke — an uncaught error, a + * non-ok outcome, or a 5xx. Narrower than `SPAN_IS_ERROR`, which counts any 4xx: + * a hidden request that answers 404 is still just noise, so only a 5xx is worth + * pulling back into view. + */ +function isFailedRequestSql(alias: string): string { + const status = `CAST(json_extract(json(${alias}.attributes), '$."http.response.status_code"') AS INTEGER)`; + return `COALESCE(${alias}.error IS NOT NULL OR (${alias}.outcome IS NOT NULL AND ${alias}.outcome != 'ok') OR ${status} >= 500, 0)`; +} + +/** + * SQL: span `alias` is one of Vite's own internal requests (module init, + * export-type probing), which the developer never made. + * + * Matched on the request path, not the wrapper-service marker: Vite routes + * *every* request through its router worker, so marker-matching a root span + * would hide the user's real traffic along with the plumbing. + */ +function isViteInternalRequestSql(alias: string): string { + const url = `json_extract(json(${alias}.attributes), '$."url.full"')`; + return `(${url} IS NOT NULL AND instr(${urlPathSql(alias)}, '${VITE_INTERNAL_PATH_PREFIX}') = 1)`; +} + +/** SQL counterpart of `isViteWrapperSpan` for the span aliased `alias`. */ +function viteWrapperSpanSql(alias: string): string { + const haystack = `(COALESCE(${alias}.service, '') || ' ' || COALESCE(${alias}.name, '') || ' ' || COALESCE(json(${alias}.attributes), ''))`; + return `(${VITE_WRAPPER_MARKERS.map( + (marker) => `instr(${haystack}, '${marker}') > 0` + ).join(" OR ")})`; +} + +/** SQL counterpart of `isRunnerDispatchJsrpc` for the span aliased `alias`. */ +function runnerDispatchJsrpcSql(alias: string): string { + return `(${alias}.name = 'jsrpc' AND json_extract(json(${alias}.attributes), '$."jsrpc.method"') = '${RUNNER_DISPATCH_METHOD}')`; +} + +/** + * SQL: log `l` (joined to its emitting span `sp`) came from Vite's plumbing. + * + * As in `stripDevRunnerSpans`, the shape match only counts once the trace is + * known to be Vite dev — a `wrangler dev` user may have their own + * `executeCallback` RPC method, and hiding their logs would be silent data loss. + * COALESCE guards the NULL a span-less log would otherwise produce. + */ +const LOG_IS_VITE_INTERNAL = `COALESCE(${viteWrapperSpanSql("sp")} OR (${runnerDispatchJsrpcSql( + "sp" +)} AND EXISTS ( + SELECT 1 FROM spans v WHERE v.trace_id = l.trace_id AND ${viteWrapperSpanSql("v")} + )), 0)`; + // Chrome DevTools auto-probes this well-known path on every page load to look for // a workspace mapping; it's tooling traffic, not a request the developer made, so // keep it out of the trace list. Guard the NULL case so non-fetch roots (which @@ -477,6 +548,9 @@ const LOG_CLAUSE_COLUMNS: Record = { export function listTraces(filters: TraceFilters = {}): Promise { const limit = Number(filters.limit ?? 100); const where: string[] = ["s.parent_id IS NULL", HIDE_DEVTOOLS_PROBE]; + where.push( + `NOT (${isViteInternalRequestSql("s")} AND NOT ${isFailedRequestSql("s")})` + ); const params: unknown[] = []; if (filters.status === "success") { @@ -632,10 +706,13 @@ export function listEvents(filters: EventFilters = {}): Promise { } } + // Filter in SQL, not on the returned rows, so LIMIT counts only visible logs. + where.push(`(l.level = 'error' OR NOT ${LOG_IS_VITE_INTERNAL})`); + params.push(limit); const whereSql = where.length ? `WHERE ${where.join(" AND ")}` : ""; // The `logs` table has no service column, so resolve the owning worker name - // from the emitting span (matched by trace_id + span_id). + // from the emitting span. const sql = `SELECT l.trace_id, l.span_id, l.seq, l.ts_ms, l.level, l.message, l.operation, l.created_at, sp.service AS service FROM logs l LEFT JOIN spans sp ON sp.trace_id = l.trace_id AND sp.span_id = l.span_id @@ -709,16 +786,6 @@ export function operationLabel( return name; } -/** - * The Vite dev module-runner's jsrpc dispatch method. User code is evaluated - * inside the runner Durable Object via `stub.executeCallback(id)`, which shows - * up as a `jsrpc` span with this method (verified against a real `vite dev` - * capture — these spans do NOT carry the runner class name in their attributes, - * so we recognise them by shape rather than by a `__VITE_RUNNER_OBJECT__` - * string). - */ -const RUNNER_DISPATCH_METHOD = "executeCallback"; - /** True if a jsrpc span is the runner's "evaluate user code" dispatch. */ function isRunnerDispatchJsrpc(span: Span): boolean { if (span.name !== "jsrpc") { diff --git a/packages/miniflare/src/workers/core/entry.worker.ts b/packages/miniflare/src/workers/core/entry.worker.ts index 2ec9adfd2c3..1314cb9e166 100644 --- a/packages/miniflare/src/workers/core/entry.worker.ts +++ b/packages/miniflare/src/workers/core/entry.worker.ts @@ -395,6 +395,13 @@ function colourFromHTTPStatus(status: number): Colorize { const ADDITIONAL_RESPONSE_LOG_HEADER_NAME = "X-Mf-Additional-Response-Log"; +// Requests a browser makes on its own, which crowd out the app's own traffic. +// Logged at debug rather than dropped, so `--log-level debug` still shows them. +const LOG_NOISE_PATHS = new Set([ + "/favicon.ico", + "/.well-known/appspecific/com.chrome.devtools.json", +]); + function maybeLogRequest( req: Request, res: Response, @@ -411,6 +418,14 @@ function maybeLogRequest( if (env[CoreBindings.JSON_LOG_LEVEL] < LogLevel.INFO) return res; const url = new URL(req.url); + // An unserved path answers 404, so only a 5xx means the Worker actually broke + // and the request stays at info. + const level = + LOG_NOISE_PATHS.has(url.pathname) && res.status < 500 + ? LogLevel.DEBUG + : LogLevel.INFO; + if (env[CoreBindings.JSON_LOG_LEVEL] < level) return res; + const statusText = (res.statusText.trim() || STATUS_CODES[res.status]) ?? ""; const lines = [ `${bold(req.method)} ${url.pathname} `, @@ -425,7 +440,7 @@ function maybeLogRequest( ctx.waitUntil( env[CoreBindings.SERVICE_LOOPBACK].fetch("http://localhost/core/log", { method: "POST", - headers: { [SharedHeaders.LOG_LEVEL]: LogLevel.INFO.toString() }, + headers: { [SharedHeaders.LOG_LEVEL]: level.toString() }, body: message, }) ); diff --git a/packages/miniflare/test/index.spec.ts b/packages/miniflare/test/index.spec.ts index 9c8da79cfd4..f0b5081f8bf 100644 --- a/packages/miniflare/test/index.spec.ts +++ b/packages/miniflare/test/index.spec.ts @@ -17,6 +17,7 @@ import { DeferredPromise, fetch, kCurrentWorker, + LogLevel, Miniflare, MiniflareCoreError, Response, @@ -1611,6 +1612,79 @@ test("Miniflare: accepts https requests", async ({ expect }) => { expect(log.logs[0][1].startsWith("Ready on https://")); }); +test("Miniflare: logs browser-made requests at debug, not info", async ({ + expect, +}) => { + const log = new TestLog(); + + const mf = new Miniflare({ + log, + modules: true, + script: `export default { + fetch(request) { + const { pathname } = new URL(request.url); + if (pathname === "/boom") { + return new Response("boom", { status: 500 }); + } + return new Response("ok"); + } + }`, + }); + useDispose(mf); + + for (const path of [ + "/api", + "/favicon.ico", + "/.well-known/appspecific/com.chrome.devtools.json", + "/boom", + ]) { + const res = await mf.dispatchFetch(`http://localhost${path}`); + await res.arrayBuffer(); // (drain) + } + + // The request log is flushed via waitUntil, so key the wait on a real request. + await vi.waitFor(() => { + expect(log.logsAtLevel(LogLevel.INFO).some((l) => l.includes("/api"))).toBe( + true + ); + }); + + const info = log.logsAtLevel(LogLevel.INFO); + const debug = log.logsAtLevel(LogLevel.DEBUG); + + // Demoted, so a default session stays quiet but nothing is lost. + expect(info.some((l) => l.includes("/favicon.ico"))).toBe(false); + expect(debug.some((l) => l.includes("/favicon.ico"))).toBe(true); + expect(info.some((l) => l.includes("devtools.json"))).toBe(false); + expect(debug.some((l) => l.includes("devtools.json"))).toBe(true); +}); + +test("Miniflare: keeps a browser-made request at info when it fails", async ({ + expect, +}) => { + const log = new TestLog(); + + const mf = new Miniflare({ + log, + modules: true, + script: `export default { + fetch() { + return new Response("boom", { status: 500 }); + } + }`, + }); + useDispose(mf); + + const res = await mf.dispatchFetch("http://localhost/favicon.ico"); + await res.arrayBuffer(); // (drain) + + await vi.waitFor(() => { + expect( + log.logsAtLevel(LogLevel.INFO).some((l) => l.includes("/favicon.ico")) + ).toBe(true); + }); +}); + // Regression test for https://github.com/cloudflare/workers-sdk/issues/9357 test("Miniflare: throws error messages that reflect the actual issue", async ({ expect,