445 lines
13 KiB
TypeScript
445 lines
13 KiB
TypeScript
import { describe, expect, spyOn, test } from "bun:test";
|
|
import {
|
|
logKubernetesRequest,
|
|
logServerRequest,
|
|
processLogger,
|
|
} from "../../lib/request-log";
|
|
|
|
describe("process request lines", () => {
|
|
test("hides health GET access lines while preserving events and in-scope Kubernetes lines", async () => {
|
|
const output = spyOn(console, "log").mockImplementation(() => {});
|
|
const logs: Record<string, unknown>[] = [];
|
|
const logger = {
|
|
log(entry: Record<string, unknown>) {
|
|
logs.push(entry);
|
|
processLogger.log(entry);
|
|
},
|
|
};
|
|
try {
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/api/v2/health?probe=ready"),
|
|
"health-request",
|
|
async () => {
|
|
await logKubernetesRequest(
|
|
{ method: "GET", pathname: "/api/v1/health-dependency" },
|
|
async () => "ok",
|
|
);
|
|
return new Response(null, { status: 200 });
|
|
},
|
|
logger,
|
|
);
|
|
await expect(
|
|
logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/api/v2/health?probe=failed"),
|
|
"failed-health-request",
|
|
() => {
|
|
throw new Error("unavailable");
|
|
},
|
|
logger,
|
|
),
|
|
).rejects.toThrow("unavailable");
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/api/v2/health"),
|
|
"default-health-request",
|
|
() => new Response(null, { status: 200 }),
|
|
);
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/api/v2/health", {
|
|
method: "POST",
|
|
}),
|
|
"post-health-request",
|
|
() => new Response(null, { status: 405 }),
|
|
);
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/api/v2/other"),
|
|
"other-request",
|
|
() => new Response(null, { status: 200 }),
|
|
);
|
|
expect(output.mock.calls.map(([line]) => line)).toEqual([
|
|
" GET /api/v1/health-dependency 200",
|
|
"PST /api/v2/health 405",
|
|
"GET /api/v2/other 200",
|
|
]);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.request.end",
|
|
requestId: "health-request",
|
|
method: "GET",
|
|
pathname: "/api/v2/health",
|
|
status: 200,
|
|
}),
|
|
);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.request.failed",
|
|
requestId: "failed-health-request",
|
|
pathname: "/api/v2/health",
|
|
}),
|
|
);
|
|
} finally {
|
|
output.mockRestore();
|
|
}
|
|
});
|
|
|
|
test("prints one application line with pathname and completion status", async () => {
|
|
const output = spyOn(console, "log").mockImplementation(() => {});
|
|
try {
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/path/to/endpoint?token=secret"),
|
|
"get-request",
|
|
() => new Response(null, { status: 404 }),
|
|
);
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/path/to/another?key=value", {
|
|
method: "POST",
|
|
}),
|
|
"post-request",
|
|
() => new Response(null, { status: 200 }),
|
|
);
|
|
|
|
expect(output.mock.calls.map(([line]) => line)).toEqual([
|
|
"GET /path/to/endpoint 404",
|
|
"PST /path/to/another 200",
|
|
]);
|
|
} finally {
|
|
output.mockRestore();
|
|
}
|
|
});
|
|
|
|
test("only emits compact access lines from the default logger", async () => {
|
|
const output = spyOn(console, "log").mockImplementation(() => {});
|
|
const logs: Record<string, unknown>[] = [];
|
|
const logger = {
|
|
log(entry: Record<string, unknown>) {
|
|
logs.push(entry);
|
|
processLogger.log(entry);
|
|
},
|
|
};
|
|
try {
|
|
const request = new Request(
|
|
"https://kuber.astrxl.dev/items?token=query-private",
|
|
{
|
|
method: "POST",
|
|
headers: {
|
|
authorization: "Bearer header-private",
|
|
cookie: "session=cookie-private",
|
|
"x-api-key": "key-private",
|
|
},
|
|
body: "body-private",
|
|
},
|
|
);
|
|
await logServerRequest(
|
|
request,
|
|
"request-private",
|
|
() => {
|
|
processLogger.log({
|
|
event: "kuber.server.request.body",
|
|
headers: Object.fromEntries(request.headers),
|
|
body: { encoding: "base64", data: "Ym9keS1wcml2YXRl" },
|
|
});
|
|
return new Response(null, {
|
|
status: 201,
|
|
headers: { "set-cookie": "session=response-private" },
|
|
});
|
|
},
|
|
logger,
|
|
);
|
|
await expect(
|
|
logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/fail", {
|
|
headers: { authorization: "Bearer failure-private" },
|
|
}),
|
|
"failure-request",
|
|
() => {
|
|
throw new Error("failed");
|
|
},
|
|
logger,
|
|
),
|
|
).rejects.toThrow("failed");
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/items", {
|
|
headers: { cookie: "session=get-private" },
|
|
}),
|
|
"get-request",
|
|
() => new Response(null, { status: 200 }),
|
|
logger,
|
|
);
|
|
|
|
expect(output.mock.calls.map(([line]) => line)).toEqual([
|
|
"PST /items 201",
|
|
"GET /fail ERR",
|
|
"GET /items 200",
|
|
]);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.request.start",
|
|
headers: expect.objectContaining({
|
|
authorization: "Bearer header-private",
|
|
}),
|
|
}),
|
|
);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.request.end",
|
|
responseHeaders: expect.objectContaining({
|
|
"set-cookie": "session=response-private",
|
|
}),
|
|
}),
|
|
);
|
|
} finally {
|
|
output.mockRestore();
|
|
}
|
|
});
|
|
|
|
test("indents Kubernetes lines for incoming requests without a CLI marker", async () => {
|
|
const output = spyOn(console, "log").mockImplementation(() => {});
|
|
try {
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/workloads", {
|
|
headers: { "user-agent": "external-client" },
|
|
}),
|
|
"workloads-request",
|
|
async () => {
|
|
await logKubernetesRequest(
|
|
{ method: "GET", pathname: "/path/to/kubernetes/api" },
|
|
async () => "ok",
|
|
);
|
|
await logKubernetesRequest(
|
|
{ method: "POST", pathname: "/api/v1/pods" },
|
|
async () => "created",
|
|
);
|
|
return new Response(null, { status: 200 });
|
|
},
|
|
);
|
|
|
|
expect(output.mock.calls.map(([line]) => line)).toEqual([
|
|
" GET /path/to/kubernetes/api 200",
|
|
" PST /api/v1/pods 200",
|
|
"GET /workloads 200",
|
|
]);
|
|
} finally {
|
|
output.mockRestore();
|
|
}
|
|
});
|
|
|
|
test("keeps full methods in structured events and marks failures", async () => {
|
|
const logs: Record<string, unknown>[] = [];
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/items?q=private", {
|
|
method: "DELETE",
|
|
}),
|
|
"delete-request",
|
|
() => new Response(null, { status: 204 }),
|
|
{ log: (entry) => logs.push(entry) },
|
|
);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.request.end",
|
|
method: "DELETE",
|
|
pathname: "/items",
|
|
status: 204,
|
|
}),
|
|
);
|
|
|
|
const output = spyOn(console, "log").mockImplementation(() => {});
|
|
try {
|
|
await expect(
|
|
logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/failing"),
|
|
"failing-request",
|
|
async () => {
|
|
await logKubernetesRequest(
|
|
{ method: "CUSTOM", pathname: "/api/v1/fail" },
|
|
async () => {
|
|
throw new Error("unavailable");
|
|
},
|
|
);
|
|
},
|
|
),
|
|
).rejects.toThrow("unavailable");
|
|
expect(output.mock.calls.map(([line]) => line)).toEqual([
|
|
" CUS /api/v1/fail ERR",
|
|
"GET /failing ERR",
|
|
]);
|
|
processLogger.log({
|
|
event: "kuber.server.request.end",
|
|
method: "X",
|
|
pathname: "/short",
|
|
status: 200,
|
|
});
|
|
expect(output.mock.calls[2]?.[0]).toBe("X__ /short 200");
|
|
} finally {
|
|
output.mockRestore();
|
|
}
|
|
});
|
|
|
|
test("isolates concurrent requests from background work and closes completed contexts", async () => {
|
|
const output = spyOn(console, "log").mockImplementation(() => {});
|
|
const events: Record<string, unknown>[] = [];
|
|
let releaseFirst!: () => void;
|
|
const firstGate = new Promise<void>((resolve) => (releaseFirst = resolve));
|
|
let releaseSecond!: () => void;
|
|
const secondGate = new Promise<void>((resolve) => (releaseSecond = resolve));
|
|
let startedFirst!: () => void;
|
|
const firstStarted = new Promise<void>((resolve) => (startedFirst = resolve));
|
|
let startedSecond!: () => void;
|
|
const secondStarted = new Promise<void>(
|
|
(resolve) => (startedSecond = resolve),
|
|
);
|
|
let releaseDetached!: () => void;
|
|
const detachedGate = new Promise<void>(
|
|
(resolve) => (releaseDetached = resolve),
|
|
);
|
|
let detached!: Promise<string>;
|
|
const customLogger = {
|
|
log: (entry: Record<string, unknown>) => events.push(entry),
|
|
};
|
|
|
|
try {
|
|
const first = logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/first"),
|
|
"first",
|
|
async () => {
|
|
detached = (async () => {
|
|
await detachedGate;
|
|
return logKubernetesRequest(
|
|
{ method: "GET", pathname: "/detached" },
|
|
async () => "done",
|
|
);
|
|
})();
|
|
startedFirst();
|
|
await firstGate;
|
|
await logKubernetesRequest(
|
|
{ method: "PUT", pathname: "/first-k8s" },
|
|
async () => "done",
|
|
);
|
|
return new Response(null, { status: 200 });
|
|
},
|
|
);
|
|
await firstStarted;
|
|
const second = logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/second"),
|
|
"second",
|
|
async () => {
|
|
startedSecond();
|
|
await secondGate;
|
|
await logKubernetesRequest(
|
|
{ method: "GET", pathname: "/second-k8s" },
|
|
async () => "done",
|
|
);
|
|
return new Response(null, { status: 200 });
|
|
},
|
|
);
|
|
await secondStarted;
|
|
|
|
await logKubernetesRequest(
|
|
{ method: "GET", pathname: "/background" },
|
|
async () => "done",
|
|
customLogger,
|
|
);
|
|
await logKubernetesRequest(
|
|
{ method: "GET", pathname: "/background-default" },
|
|
async () => "done",
|
|
);
|
|
await expect(
|
|
logKubernetesRequest(
|
|
{ method: "DELETE", pathname: "/background-failed" },
|
|
async () => {
|
|
throw new Error("background failure");
|
|
},
|
|
),
|
|
).rejects.toThrow("background failure");
|
|
expect(events.map((entry) => entry.event)).toEqual([
|
|
"kuber.k8s.request.start",
|
|
"kuber.k8s.request.end",
|
|
]);
|
|
|
|
releaseFirst();
|
|
await first;
|
|
releaseDetached();
|
|
await detached;
|
|
releaseSecond();
|
|
await second;
|
|
await logKubernetesRequest(
|
|
{ method: "GET", pathname: "/after" },
|
|
async () => "done",
|
|
);
|
|
|
|
expect(output.mock.calls.map(([line]) => line)).toEqual([
|
|
" PUT /first-k8s 200",
|
|
"GET /first 200",
|
|
" GET /second-k8s 200",
|
|
"GET /second 200",
|
|
]);
|
|
} finally {
|
|
releaseFirst();
|
|
releaseSecond();
|
|
releaseDetached();
|
|
output.mockRestore();
|
|
}
|
|
});
|
|
});
|
|
|
|
describe("server response logging", () => {
|
|
test("does not consume streaming response bodies", async () => {
|
|
let pulls = 0;
|
|
const body = new ReadableStream<Uint8Array>({
|
|
pull(controller) {
|
|
pulls += 1;
|
|
controller.enqueue(new TextEncoder().encode('{"message":"live"}\n'));
|
|
},
|
|
});
|
|
const logs: Record<string, unknown>[] = [];
|
|
const response = new Response(body, {
|
|
headers: { "content-type": "application/x-ndjson; charset=utf-8" },
|
|
});
|
|
await Bun.sleep(0);
|
|
const pullsBeforeLogging = pulls;
|
|
const loggedResponse = await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/logs"),
|
|
"streaming-response",
|
|
() => response,
|
|
{ log: (entry) => logs.push(entry) },
|
|
);
|
|
|
|
expect(pulls).toBe(pullsBeforeLogging);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.response.body",
|
|
bodySkipped: true,
|
|
streaming: true,
|
|
}),
|
|
);
|
|
|
|
const reader = loggedResponse.body!.getReader();
|
|
expect(new TextDecoder().decode((await reader.read()).value)).toBe(
|
|
'{"message":"live"}\n',
|
|
);
|
|
await reader.cancel();
|
|
});
|
|
|
|
test("logs bounded non-streaming response bodies", async () => {
|
|
const logs: Record<string, unknown>[] = [];
|
|
await logServerRequest(
|
|
new Request("https://kuber.astrxl.dev/health"),
|
|
"bounded-response",
|
|
() =>
|
|
new Response("healthy", {
|
|
headers: {
|
|
"content-length": "7",
|
|
"content-type": "text/plain; charset=utf-8",
|
|
},
|
|
}),
|
|
{ log: (entry) => logs.push(entry) },
|
|
);
|
|
|
|
await Bun.sleep(0);
|
|
expect(logs).toContainEqual(
|
|
expect.objectContaining({
|
|
event: "kuber.server.response.body",
|
|
body: { encoding: "base64", data: "aGVhbHRoeQ==" },
|
|
}),
|
|
);
|
|
});
|
|
});
|