fix(logs): the browser's copy of a polled read is quiet too
The server now logs polled reads at DEBUG, and the browser's copy of each request line promises the server's level: at INFO the unread-count polls filled My log within minutes and, at Detailed, the shipped log. The server marks a line it logged at DEBUG with X-Log-Quiet, so the polled-route list stays in one place.
This commit is contained in:
@@ -738,6 +738,10 @@ async def log_requests(request, call_next):
|
|||||||
extra={**event("http.request", **attrs), **_request_owner(request, level)},
|
extra={**event("http.request", **attrs), **_request_owner(request, level)},
|
||||||
)
|
)
|
||||||
response.headers["X-Request-Id"] = rid
|
response.headers["X-Request-Id"] = rid
|
||||||
|
# The browser logs its own copy of this line (frontend lib/http.ts) and must pick the same level:
|
||||||
|
# it learns "this one is quiet" here instead of keeping a second copy of the polled-route list.
|
||||||
|
if level == logging.DEBUG:
|
||||||
|
response.headers["X-Log-Quiet"] = "1"
|
||||||
# The template, so the browser's copy of this line groups the same way (frontend lib/http.ts).
|
# The template, so the browser's copy of this line groups the same way (frontend lib/http.ts).
|
||||||
# Only a MATCHED route's: a template never carries a path parameter's value (a share token stays
|
# Only a MATCHED route's: a template never carries a path parameter's value (a share token stays
|
||||||
# `{token}`), while the raw-path fallback of an unmatched request could — the browser then
|
# `{token}`), while the raw-path fallback of an unmatched request could — the browser then
|
||||||
|
|||||||
@@ -337,10 +337,13 @@ def test_a_polled_read_is_debug_a_write_to_the_same_route_is_not(sink):
|
|||||||
http = logging.getLogger("siftlode.http")
|
http = logging.getLogger("siftlode.http")
|
||||||
http.setLevel(logs.TRACE)
|
http.setLevel(logs.TRACE)
|
||||||
client = _client()
|
client = _client()
|
||||||
client.get("/api/messages/unread_count")
|
r = client.get("/api/messages/unread_count")
|
||||||
assert sink.objects()[-1]["level"] == "DEBUG"
|
assert sink.objects()[-1]["level"] == "DEBUG"
|
||||||
client.post("/api/messages/unread_count")
|
# ...and says so, for the browser's copy of the line (frontend lib/http.ts).
|
||||||
|
assert r.headers["X-Log-Quiet"] == "1"
|
||||||
|
r = client.post("/api/messages/unread_count")
|
||||||
assert sink.objects()[-1]["level"] == "INFO"
|
assert sink.objects()[-1]["level"] == "INFO"
|
||||||
|
assert "X-Log-Quiet" not in r.headers
|
||||||
client.get("/api/videos/abc")
|
client.get("/api/videos/abc")
|
||||||
assert sink.objects()[-1]["level"] == "INFO"
|
assert sink.objects()[-1]["level"] == "INFO"
|
||||||
|
|
||||||
|
|||||||
@@ -7,7 +7,7 @@ import i18n from "../../i18n";
|
|||||||
import { formatBytes } from "../format";
|
import { formatBytes } from "../format";
|
||||||
import { reportError } from "../errorDialog";
|
import { reportError } from "../errorDialog";
|
||||||
import { activeAccountId, pinActiveAccount } from "../activeAccount";
|
import { activeAccountId, pinActiveAccount } from "../activeAccount";
|
||||||
import { logRequest, REQUEST_ID_HEADER, ROUTE_HEADER, send } from "../http";
|
import { logRequest, QUIET_HEADER, REQUEST_ID_HEADER, ROUTE_HEADER, send } from "../http";
|
||||||
import { newRequestId } from "../log";
|
import { newRequestId } from "../log";
|
||||||
|
|
||||||
/** The active UI language, as a bare code the server understands ("en"/"hu" — never "en-GB").
|
/** The active UI language, as a bare code the server understands ("en"/"hu" — never "en-GB").
|
||||||
@@ -374,6 +374,7 @@ export function uploadReq<T = unknown>(
|
|||||||
status: xhr.status,
|
status: xhr.status,
|
||||||
// Test doubles may not implement it; a real XHR always does.
|
// Test doubles may not implement it; a real XHR always does.
|
||||||
route: xhr.getResponseHeader?.(ROUTE_HEADER),
|
route: xhr.getResponseHeader?.(ROUTE_HEADER),
|
||||||
|
quiet: xhr.getResponseHeader?.(QUIET_HEADER) === "1",
|
||||||
});
|
});
|
||||||
if (!RETRIABLE_GATEWAY.has(xhr.status)) markConnectivityRestored(); // as in `req`
|
if (!RETRIABLE_GATEWAY.has(xhr.status)) markConnectivityRestored(); // as in `req`
|
||||||
if (xhr.status >= 200 && xhr.status < 300) {
|
if (xhr.status >= 200 && xhr.status < 300) {
|
||||||
|
|||||||
@@ -1,9 +1,10 @@
|
|||||||
import { afterEach, describe, expect, it, vi } from "vitest";
|
import { afterEach, describe, expect, it, vi } from "vitest";
|
||||||
|
|
||||||
import { pathTemplate, send } from "./http";
|
import { pathTemplate, send } from "./http";
|
||||||
import { clear, events } from "./log";
|
import { clear, events, setLevel } from "./log";
|
||||||
|
|
||||||
afterEach(() => {
|
afterEach(() => {
|
||||||
|
setLevel("INFO");
|
||||||
clear();
|
clear();
|
||||||
vi.unstubAllGlobals();
|
vi.unstubAllGlobals();
|
||||||
});
|
});
|
||||||
@@ -41,6 +42,18 @@ describe("send", () => {
|
|||||||
]);
|
]);
|
||||||
});
|
});
|
||||||
|
|
||||||
|
// The server logs the reads the app polls at DEBUG and says so (`X-Log-Quiet`); at INFO the
|
||||||
|
// browser's copies filled My log with unread-count polls within minutes (prod UAT 2026-09-19).
|
||||||
|
it("logs a read the server called quiet at DEBUG, so the base level keeps it out", async () => {
|
||||||
|
vi.stubGlobal("fetch", async () => answer(200, { "X-Log-Quiet": "1" }));
|
||||||
|
await send("/api/messages/unread_count");
|
||||||
|
expect(events()).toEqual([]);
|
||||||
|
|
||||||
|
setLevel("DEBUG");
|
||||||
|
await send("/api/messages/unread_count");
|
||||||
|
expect(events().map((e) => e.level)).toEqual(["DEBUG"]);
|
||||||
|
});
|
||||||
|
|
||||||
it("logs a network failure without the concrete path, and still rejects", async () => {
|
it("logs a network failure without the concrete path, and still rejects", async () => {
|
||||||
vi.stubGlobal("fetch", async () => {
|
vi.stubGlobal("fetch", async () => {
|
||||||
throw new TypeError("Failed to fetch");
|
throw new TypeError("Failed to fetch");
|
||||||
|
|||||||
@@ -12,6 +12,9 @@ import { log, newRequestId, type Level } from "./log";
|
|||||||
* Grouping by it is what makes a client line comparable, and it is safe by construction: a token in
|
* Grouping by it is what makes a client line comparable, and it is safe by construction: a token in
|
||||||
* the path (`/api/public/watch/{token}`) arrives already replaced by its parameter name. */
|
* the path (`/api/public/watch/{token}`) arrives already replaced by its parameter name. */
|
||||||
export const ROUTE_HEADER = "X-Route";
|
export const ROUTE_HEADER = "X-Route";
|
||||||
|
/** Set when the server logged this request at DEBUG (a polled read, the log console's own reads): the
|
||||||
|
* browser's copy of the line goes to DEBUG too, from the server's one list (`logs._POLLED_ROUTES`). */
|
||||||
|
export const QUIET_HEADER = "X-Log-Quiet";
|
||||||
export const REQUEST_ID_HEADER = "X-Request-Id";
|
export const REQUEST_ID_HEADER = "X-Request-Id";
|
||||||
|
|
||||||
// A static path word: kept. Anything else (an id, a channel id, a share token) becomes `{}`.
|
// A static path word: kept. Anything else (an id, a channel id, a share token) becomes `{}`.
|
||||||
@@ -29,9 +32,9 @@ export function pathTemplate(url: string): string {
|
|||||||
}
|
}
|
||||||
|
|
||||||
/** Level of a request line — the server's own rule (`logs.log_requests`), so both sides agree on
|
/** Level of a request line — the server's own rule (`logs.log_requests`), so both sides agree on
|
||||||
* what a 404 is. */
|
* what a 404 is, and on which successes are too routine for INFO (`quiet`, the server's say). */
|
||||||
function statusLevel(status: number): Level {
|
function statusLevel(status: number, quiet: boolean): Level {
|
||||||
return status >= 500 ? "ERROR" : status >= 400 ? "WARNING" : "INFO";
|
return status >= 500 ? "ERROR" : status >= 400 ? "WARNING" : quiet ? "DEBUG" : "INFO";
|
||||||
}
|
}
|
||||||
|
|
||||||
/** Record one request's outcome. `route` is the server's template when it sent one. */
|
/** Record one request's outcome. `route` is the server's template when it sent one. */
|
||||||
@@ -40,7 +43,9 @@ export function logRequest(
|
|||||||
method: string,
|
method: string,
|
||||||
url: string,
|
url: string,
|
||||||
started: number,
|
started: number,
|
||||||
outcome: { status: number; route?: string | null } | { failed: "network" | "aborted" },
|
outcome:
|
||||||
|
| { status: number; route?: string | null; quiet?: boolean }
|
||||||
|
| { failed: "network" | "aborted" },
|
||||||
extra: Record<string, unknown> = {},
|
extra: Record<string, unknown> = {},
|
||||||
): void {
|
): void {
|
||||||
const duration_ms = Math.round((performance.now() - started) * 10) / 10;
|
const duration_ms = Math.round((performance.now() - started) * 10) / 10;
|
||||||
@@ -56,7 +61,7 @@ export function logRequest(
|
|||||||
}
|
}
|
||||||
const path = outcome.route || pathTemplate(url);
|
const path = outcome.route || pathTemplate(url);
|
||||||
log.request(
|
log.request(
|
||||||
statusLevel(outcome.status),
|
statusLevel(outcome.status, outcome.quiet === true),
|
||||||
`${method} ${path} ${outcome.status}`,
|
`${method} ${path} ${outcome.status}`,
|
||||||
{ method, path, status: outcome.status, duration_ms, ...extra },
|
{ method, path, status: outcome.status, duration_ms, ...extra },
|
||||||
requestId,
|
requestId,
|
||||||
@@ -92,7 +97,11 @@ export async function send(
|
|||||||
method,
|
method,
|
||||||
url,
|
url,
|
||||||
started,
|
started,
|
||||||
{ status: r.status, route: headerOf(r, ROUTE_HEADER) },
|
{
|
||||||
|
status: r.status,
|
||||||
|
route: headerOf(r, ROUTE_HEADER),
|
||||||
|
quiet: headerOf(r, QUIET_HEADER) === "1",
|
||||||
|
},
|
||||||
extra,
|
extra,
|
||||||
);
|
);
|
||||||
return r;
|
return r;
|
||||||
|
|||||||
Reference in New Issue
Block a user