malpercio.dev
WIP! A BB-style forum, on the ATmosphere!
We're still working... we'll be back soon when we have something to show off!
node
typescript
hono
htmx
atproto
1import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
2import { createLogger } from "../setup.js";
3import { StructuredLogExporter } from "../exporter.js";
4import { ExportResultCode } from "@opentelemetry/core";
5import { SeverityNumber } from "@opentelemetry/api-logs";
6import type { ReadableLogRecord } from "@opentelemetry/sdk-logs";
7
8// ─── Helpers ──────────────────────────────────────────────────────────────────
9
10/**
11 * Capture all lines written to process.stdout during the callback.
12 * Returns parsed NDJSON objects.
13 */
14async function captureStdout(fn: () => void | Promise<void>): Promise<Record<string, unknown>[]> {
15 const lines: string[] = [];
16 const spy = vi.spyOn(process.stdout, "write").mockImplementation((chunk: unknown) => {
17 if (typeof chunk === "string") {
18 lines.push(...chunk.split("\n").filter(Boolean));
19 }
20 return true;
21 });
22
23 try {
24 await fn();
25 } finally {
26 spy.mockRestore();
27 }
28
29 return lines.map((line) => JSON.parse(line));
30}
31
32// ─── createLogger / AppLogger ─────────────────────────────────────────────────
33
34describe("createLogger", () => {
35 it("emits a valid NDJSON line for info()", async () => {
36 const logger = createLogger({ service: "test-svc" });
37
38 const lines = await captureStdout(() => {
39 logger.info("hello world", { requestId: "abc" });
40 });
41
42 expect(lines).toHaveLength(1);
43 const entry = lines[0];
44 expect(entry.level).toBe("info");
45 expect(entry.message).toBe("hello world");
46 expect(entry.service).toBe("test-svc");
47 expect(entry.requestId).toBe("abc");
48 expect(typeof entry.timestamp).toBe("string");
49 // timestamp must be a valid ISO-8601 date
50 expect(new Date(entry.timestamp as string).toISOString()).toBe(entry.timestamp);
51 });
52
53 it("emits correct level text for each severity method", async () => {
54 const logger = createLogger({ service: "test-svc", level: "debug" });
55
56 for (const [method, expectedLevel] of [
57 ["debug", "debug"],
58 ["info", "info"],
59 ["warn", "warn"],
60 ["error", "error"],
61 ["fatal", "fatal"],
62 ] as const) {
63 const lines = await captureStdout(() => {
64 logger[method](`${method} message`);
65 });
66
67 expect(lines).toHaveLength(1);
68 expect(lines[0].level).toBe(expectedLevel);
69 expect(lines[0].message).toBe(`${method} message`);
70 }
71 });
72
73 it("includes version and environment in output when provided", async () => {
74 const logger = createLogger({
75 service: "test-svc",
76 version: "1.2.3",
77 environment: "staging",
78 });
79
80 const lines = await captureStdout(() => {
81 logger.info("tagged message");
82 });
83
84 expect(lines[0].version).toBe("1.2.3");
85 expect(lines[0].environment).toBe("staging");
86 });
87
88 it("omits version and environment when not provided", async () => {
89 const logger = createLogger({ service: "test-svc" });
90
91 const lines = await captureStdout(() => {
92 logger.info("bare message");
93 });
94
95 expect(Object.keys(lines[0])).not.toContain("version");
96 expect(Object.keys(lines[0])).not.toContain("environment");
97 });
98
99 it("spreads numeric and boolean attributes into top-level fields", async () => {
100 const logger = createLogger({ service: "test-svc" });
101
102 const lines = await captureStdout(() => {
103 logger.info("typed attrs", { count: 42, success: true });
104 });
105
106 expect(lines[0].count).toBe(42);
107 expect(lines[0].success).toBe(true);
108 });
109});
110
111// ─── Level filtering ──────────────────────────────────────────────────────────
112
113describe("AppLogger level filtering", () => {
114 it("suppresses messages below the configured level", async () => {
115 const logger = createLogger({ service: "test-svc", level: "warn" });
116
117 const lines = await captureStdout(() => {
118 logger.debug("suppressed debug");
119 logger.info("suppressed info");
120 logger.warn("allowed warn");
121 logger.error("allowed error");
122 });
123
124 expect(lines).toHaveLength(2);
125 expect(lines[0].level).toBe("warn");
126 expect(lines[1].level).toBe("error");
127 });
128
129 it("emits all levels when level is debug", async () => {
130 const logger = createLogger({ service: "test-svc", level: "debug" });
131
132 const lines = await captureStdout(() => {
133 logger.debug("d");
134 logger.info("i");
135 logger.warn("w");
136 logger.error("e");
137 logger.fatal("f");
138 });
139
140 expect(lines).toHaveLength(5);
141 });
142
143 it("only emits fatal when level is fatal", async () => {
144 const logger = createLogger({ service: "test-svc", level: "fatal" });
145
146 const lines = await captureStdout(() => {
147 logger.debug("d");
148 logger.info("i");
149 logger.warn("w");
150 logger.error("e");
151 logger.fatal("f");
152 });
153
154 expect(lines).toHaveLength(1);
155 expect(lines[0].level).toBe("fatal");
156 });
157});
158
159// ─── child() attribute inheritance ───────────────────────────────────────────
160
161describe("AppLogger child()", () => {
162 it("inherits base attributes from parent", async () => {
163 const logger = createLogger({ service: "test-svc" });
164 const child = logger.child({ requestId: "req-123", component: "auth" });
165
166 const lines = await captureStdout(() => {
167 child.info("child message");
168 });
169
170 expect(lines[0].requestId).toBe("req-123");
171 expect(lines[0].component).toBe("auth");
172 expect(lines[0].message).toBe("child message");
173 });
174
175 it("call-site attributes override child base attributes", async () => {
176 const logger = createLogger({ service: "test-svc" });
177 const child = logger.child({ requestId: "base-id" });
178
179 const lines = await captureStdout(() => {
180 child.info("override", { requestId: "override-id" });
181 });
182
183 expect(lines[0].requestId).toBe("override-id");
184 });
185
186 it("parent logger is not affected by child attributes", async () => {
187 const logger = createLogger({ service: "test-svc" });
188 logger.child({ requestId: "req-123" }); // create child to ensure isolation
189
190 const lines = await captureStdout(() => {
191 logger.info("parent message");
192 });
193
194 expect(Object.keys(lines[0])).not.toContain("requestId");
195 });
196
197 it("child of child accumulates attributes from both ancestors", async () => {
198 const logger = createLogger({ service: "test-svc" });
199 const child = logger.child({ layer: "A" });
200 const grandchild = child.child({ layer: "B", extra: "yes" });
201
202 const lines = await captureStdout(() => {
203 grandchild.info("deep");
204 });
205
206 // layer from grandchild overrides layer from child
207 expect(lines[0].layer).toBe("B");
208 expect(lines[0].extra).toBe("yes");
209 });
210});
211
212// ─── StructuredLogExporter ────────────────────────────────────────────────────
213
214describe("StructuredLogExporter", () => {
215 it("calls resultCallback with SUCCESS on normal export", () => {
216 const exporter = new StructuredLogExporter();
217 const writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true);
218
219 const callback = vi.fn();
220 exporter.export([], callback);
221
222 expect(callback).toHaveBeenCalledWith({ code: ExportResultCode.SUCCESS });
223 writeSpy.mockRestore();
224 });
225
226 it("calls resultCallback with FAILED when stdout.write throws", () => {
227 const exporter = new StructuredLogExporter();
228 const writeSpy = vi.spyOn(process.stdout, "write").mockImplementation(() => {
229 throw new Error("EPIPE");
230 });
231
232 const record = {
233 hrTime: [1700000000, 0] as [number, number],
234 severityNumber: SeverityNumber.INFO,
235 body: "test",
236 resource: { attributes: {} },
237 attributes: {},
238 } as unknown as ReadableLogRecord;
239
240 const callback = vi.fn();
241 exporter.export([record], callback);
242
243 expect(callback).toHaveBeenCalledWith({ code: ExportResultCode.FAILED });
244 writeSpy.mockRestore();
245 });
246
247 it("calls resultCallback with FAILED when JSON.stringify throws (circular ref)", () => {
248 const exporter = new StructuredLogExporter();
249 const writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true);
250
251 // Create a log record whose attributes contain a circular reference
252 const circular: Record<string, unknown> = {};
253 circular.self = circular;
254
255 const record = {
256 hrTime: [1700000000, 0] as [number, number],
257 severityNumber: SeverityNumber.INFO,
258 body: "circular test",
259 resource: { attributes: {} },
260 attributes: circular,
261 } as unknown as ReadableLogRecord;
262
263 const callback = vi.fn();
264 exporter.export([record], callback);
265
266 expect(callback).toHaveBeenCalledWith({ code: ExportResultCode.FAILED });
267 writeSpy.mockRestore();
268 });
269
270 describe("hrTimeToISO arithmetic", () => {
271 it("converts [seconds, nanoseconds] to correct ISO string", () => {
272 const exporter = new StructuredLogExporter();
273 const writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true);
274 const lines: Record<string, unknown>[] = [];
275
276 writeSpy.mockImplementation((chunk) => {
277 if (typeof chunk === "string") {
278 lines.push(...chunk.split("\n").filter(Boolean).map((l) => JSON.parse(l)));
279 }
280 return true;
281 });
282
283 const epochSeconds = 1700000000;
284 const nanoseconds = 500_000_000; // 0.5 seconds
285
286 const record = {
287 hrTime: [epochSeconds, nanoseconds] as [number, number],
288 severityNumber: SeverityNumber.INFO,
289 body: "time test",
290 resource: { attributes: {} },
291 attributes: {},
292 } as unknown as ReadableLogRecord;
293
294 const callback = vi.fn();
295 exporter.export([record], callback);
296
297 const expectedMs = epochSeconds * 1000 + nanoseconds / 1_000_000;
298 expect(lines[0].timestamp).toBe(new Date(expectedMs).toISOString());
299
300 writeSpy.mockRestore();
301 });
302 });
303});
304
305// ─── requestLogger middleware ─────────────────────────────────────────────────
306
307describe("requestLogger middleware", () => {
308 // eslint-disable-next-line @typescript-eslint/no-explicit-any
309 let writeSpy: any;
310
311 beforeEach(() => {
312 writeSpy = vi.spyOn(process.stdout, "write").mockReturnValue(true);
313 });
314
315 afterEach(() => {
316 writeSpy.mockRestore();
317 });
318
319 function captureLines(): Record<string, unknown>[] {
320 const lines: Record<string, unknown>[] = [];
321 writeSpy.mockImplementation((chunk: unknown) => {
322 if (typeof chunk === "string") {
323 lines.push(...chunk.split("\n").filter(Boolean).map((l) => JSON.parse(l)));
324 }
325 return true;
326 });
327 return lines;
328 }
329
330 it("logs 'Request received' at debug and 'Request completed' at info for 2xx", async () => {
331 const { requestLogger } = await import("../middleware.js");
332 const { Hono } = await import("hono");
333
334 const logger = createLogger({ service: "test-svc", level: "debug" });
335 const lines = captureLines();
336
337 const app = new Hono();
338 app.use("*", requestLogger(logger));
339 app.get("/ok", (c) => c.json({ ok: true }));
340
341 await app.request("/ok");
342
343 const received = lines.find((l) => l.message === "Request received");
344 const completed = lines.find((l) => l.message === "Request completed");
345
346 expect(received).toBeDefined();
347 expect(received?.level).toBe("debug");
348 expect(completed).toBeDefined();
349 expect(completed?.level).toBe("info");
350 expect(completed?.status).toBe(200);
351 expect(typeof completed?.duration_ms).toBe("number");
352 });
353
354 it("logs 'Request completed' at warn for 4xx responses", async () => {
355 const { requestLogger } = await import("../middleware.js");
356 const { Hono } = await import("hono");
357
358 const logger = createLogger({ service: "test-svc", level: "debug" });
359 const lines = captureLines();
360
361 const app = new Hono();
362 app.use("*", requestLogger(logger));
363 app.get("/bad", (c) => c.json({ error: "bad request" }, 400));
364
365 await app.request("/bad");
366
367 const completed = lines.find((l) => l.message === "Request completed");
368 expect(completed?.level).toBe("warn");
369 expect(completed?.status).toBe(400);
370 });
371
372 it("logs 'Request completed' at error for 5xx responses", async () => {
373 const { requestLogger } = await import("../middleware.js");
374 const { Hono } = await import("hono");
375
376 const logger = createLogger({ service: "test-svc", level: "debug" });
377 const lines = captureLines();
378
379 const app = new Hono();
380 app.use("*", requestLogger(logger));
381 app.get("/err", (c) => c.json({ error: "server error" }, 500));
382
383 await app.request("/err");
384
385 const completed = lines.find((l) => l.message === "Request completed");
386 expect(completed?.level).toBe("error");
387 expect(completed?.status).toBe(500);
388 });
389
390 it("logs 'Request completed' at error level when handler throws (Hono catches internally)", async () => {
391 const { requestLogger } = await import("../middleware.js");
392 const { Hono } = await import("hono");
393
394 const logger = createLogger({ service: "test-svc", level: "debug" });
395 const lines = captureLines();
396
397 const app = new Hono();
398 app.use("*", requestLogger(logger));
399 app.get("/throw", () => {
400 throw new Error("handler crashed");
401 });
402
403 // Hono's internal onError catches the throw and returns 500.
404 // The middleware sees next() return normally with c.res.status = 500.
405 const res = await app.request("/throw");
406 expect(res.status).toBe(500);
407
408 // Middleware logs "Request completed" at error (status >= 500), not "Request failed"
409 const completed = lines.find((l) => l.message === "Request completed");
410 expect(completed).toBeDefined();
411 expect(completed?.level).toBe("error");
412 expect(completed?.status).toBe(500);
413 });
414
415 it("includes method and path in child logger context", async () => {
416 const { requestLogger } = await import("../middleware.js");
417 const { Hono } = await import("hono");
418
419 const logger = createLogger({ service: "test-svc", level: "debug" });
420 const lines = captureLines();
421
422 const app = new Hono();
423 app.use("*", requestLogger(logger));
424 app.get("/api/forum", (c) => c.json({ ok: true }));
425
426 await app.request("/api/forum");
427
428 const completed = lines.find((l) => l.message === "Request completed");
429 expect(completed?.method).toBe("GET");
430 expect(completed?.path).toBe("/api/forum");
431 });
432});