From f9caef82e67454054c9f014039cf98cca4a2fedc Mon Sep 17 00:00:00 2001 From: Hoid Date: Fri, 6 Mar 2026 11:08:06 +0100 Subject: [PATCH] feat: add PDF render timing to convert and demo routes - renderPdf() and renderUrlPdf() now return { pdf, durationMs } - Timing wraps the actual render with Date.now() - Log render duration via logger.info - Add X-Render-Time response header in convert and demo routes - Update all callers in convert, demo, templates routes - Add TDD tests in render-timing.test.ts - Update existing test mocks for new return shape --- src/__tests__/body-limits.test.ts | 2 +- src/__tests__/browser-pool.test.ts | 11 +- src/__tests__/convert-sanitized.test.ts | 4 +- src/__tests__/convert.test.ts | 4 +- src/__tests__/demo.test.ts | 2 +- src/__tests__/render-timing.test.ts | 126 ++++++++++++++++++ src/__tests__/setup.ts | 4 +- .../templates-render-validation.test.ts | 2 +- src/__tests__/templates-route.test.ts | 2 +- src/routes/convert.ts | 9 +- src/routes/demo.ts | 6 +- src/routes/templates.ts | 2 +- src/services/browser.ts | 14 +- 13 files changed, 165 insertions(+), 23 deletions(-) create mode 100644 src/__tests__/render-timing.test.ts diff --git a/src/__tests__/body-limits.test.ts b/src/__tests__/body-limits.test.ts index cbbbdcd..be524e5 100644 --- a/src/__tests__/body-limits.test.ts +++ b/src/__tests__/body-limits.test.ts @@ -52,7 +52,7 @@ describe("Body size limits", () => { vi.resetModules(); const { renderPdf } = await import("../services/browser.js"); - vi.mocked(renderPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock")); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 10 }); const { demoRouter } = await import("../routes/demo.js"); const { convertRouter } = await import("../routes/convert.js"); diff --git a/src/__tests__/browser-pool.test.ts b/src/__tests__/browser-pool.test.ts index 1252f4c..d0a68e5 100644 --- a/src/__tests__/browser-pool.test.ts +++ b/src/__tests__/browser-pool.test.ts @@ -150,8 +150,11 @@ describe("browser pool", () => { it("generates a PDF buffer from HTML", async () => { await browserModule.initBrowser(); const result = await browserModule.renderPdf("

Hello

"); - expect(Buffer.isBuffer(result)).toBe(true); - expect(result.toString()).toContain("%PDF"); + expect(result).toHaveProperty("pdf"); + expect(result).toHaveProperty("durationMs"); + expect(Buffer.isBuffer(result.pdf)).toBe(true); + expect(result.pdf.toString()).toContain("%PDF"); + expect(typeof result.durationMs).toBe("number"); }); it("sets content and disables JS on the page", async () => { @@ -237,7 +240,9 @@ describe("browser pool", () => { it("navigates to URL and generates PDF", async () => { await browserModule.initBrowser(); const result = await browserModule.renderUrlPdf("https://example.com"); - expect(Buffer.isBuffer(result)).toBe(true); + expect(result).toHaveProperty("pdf"); + expect(result).toHaveProperty("durationMs"); + expect(Buffer.isBuffer(result.pdf)).toBe(true); const usedPage = mockBrowsers .flatMap((b: any) => b._pages.slice(0, 2)) .find((p: any) => p.goto.mock.calls.length > 0); diff --git a/src/__tests__/convert-sanitized.test.ts b/src/__tests__/convert-sanitized.test.ts index 58002fd..a7aaa92 100644 --- a/src/__tests__/convert-sanitized.test.ts +++ b/src/__tests__/convert-sanitized.test.ts @@ -14,8 +14,8 @@ beforeEach(async () => { vi.resetModules(); const { renderPdf, renderUrlPdf } = await import("../services/browser.js"); - vi.mocked(renderPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock")); - vi.mocked(renderUrlPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock url")); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 10 }); + vi.mocked(renderUrlPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock url"), durationMs: 10 }); const dns = await import("node:dns/promises"); vi.mocked(dns.default.lookup).mockResolvedValue({ address: "93.184.216.34", family: 4 } as any); diff --git a/src/__tests__/convert.test.ts b/src/__tests__/convert.test.ts index 507107b..f97aaa1 100644 --- a/src/__tests__/convert.test.ts +++ b/src/__tests__/convert.test.ts @@ -15,8 +15,8 @@ beforeEach(async () => { vi.resetModules(); const { renderPdf, renderUrlPdf } = await import("../services/browser.js"); - vi.mocked(renderPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock")); - vi.mocked(renderUrlPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock url")); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 10 }); + vi.mocked(renderUrlPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock url"), durationMs: 10 }); const dns = await import("node:dns/promises"); vi.mocked(dns.default.lookup).mockResolvedValue({ address: "93.184.216.34", family: 4 } as any); diff --git a/src/__tests__/demo.test.ts b/src/__tests__/demo.test.ts index 295f90c..f6a3ec4 100644 --- a/src/__tests__/demo.test.ts +++ b/src/__tests__/demo.test.ts @@ -14,7 +14,7 @@ beforeEach(async () => { vi.resetModules(); const { renderPdf } = await import("../services/browser.js"); - vi.mocked(renderPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock")); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 10 }); const { demoRouter } = await import("../routes/demo.js"); app = express(); diff --git a/src/__tests__/render-timing.test.ts b/src/__tests__/render-timing.test.ts new file mode 100644 index 0000000..79b1355 --- /dev/null +++ b/src/__tests__/render-timing.test.ts @@ -0,0 +1,126 @@ +import { describe, it, expect, vi, beforeEach } from "vitest"; +import express from "express"; +import request from "supertest"; + +// Mock browser service to return { pdf, durationMs } +vi.mock("../services/browser.js", () => ({ + renderPdf: vi.fn(), + renderUrlPdf: vi.fn(), +})); + +describe("PDF render timing", () => { + describe("browser service return type", () => { + it("renderPdf returns { pdf, durationMs }", async () => { + // Reset modules to get unmocked version for this test + vi.restoreAllMocks(); + vi.resetModules(); + // We can't easily test the real renderPdf without a browser, + // so we test the shape via the mock contract and integration tests below + }); + }); + + describe("convert routes set X-Render-Time header", () => { + let app: express.Express; + + beforeEach(async () => { + vi.clearAllMocks(); + vi.resetModules(); + + const { renderPdf, renderUrlPdf } = await import("../services/browser.js"); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 42 } as any); + vi.mocked(renderUrlPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 55 } as any); + + const { convertRouter } = await import("../routes/convert.js"); + app = express(); + app.use(express.json({ limit: "500kb" })); + app.use((req, _res, next) => { + (req as any).apiKey = { id: "test-key", name: "test", tier: "free", active: true }; + (req as any).keyRow = { id: "test-key", name: "test", tier: "free", active: true, owner_email: "test@test.com" }; + next(); + }); + app.use("/v1/convert", convertRouter); + }); + + it("POST /v1/convert/html sets X-Render-Time header", async () => { + const res = await request(app) + .post("/v1/convert/html") + .set("content-type", "application/json") + .send({ html: "

Hello

" }); + expect(res.status).toBe(200); + expect(res.headers["x-render-time"]).toBe("42"); + }); + + it("POST /v1/convert/markdown sets X-Render-Time header", async () => { + const res = await request(app) + .post("/v1/convert/markdown") + .set("content-type", "application/json") + .send({ markdown: "# Hello" }); + expect(res.status).toBe(200); + expect(res.headers["x-render-time"]).toBe("42"); + }); + }); + + describe("demo routes set X-Render-Time header", () => { + let app: express.Express; + + beforeEach(async () => { + vi.clearAllMocks(); + vi.resetModules(); + + const { renderPdf } = await import("../services/browser.js"); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 99 } as any); + + const { demoRouter } = await import("../routes/demo.js"); + app = express(); + app.use(express.json({ limit: "500kb" })); + app.use("/v1/demo", demoRouter); + }); + + it("POST /v1/demo/html sets X-Render-Time header", async () => { + const res = await request(app) + .post("/v1/demo/html") + .set("content-type", "application/json") + .send({ html: "

Hello

" }); + expect(res.status).toBe(200); + expect(res.headers["x-render-time"]).toBe("99"); + }); + + it("POST /v1/demo/markdown sets X-Render-Time header", async () => { + const res = await request(app) + .post("/v1/demo/markdown") + .set("content-type", "application/json") + .send({ markdown: "# Hello" }); + expect(res.status).toBe(200); + expect(res.headers["x-render-time"]).toBe("99"); + }); + }); + + describe("templates route destructures correctly", () => { + // Templates route doesn't need X-Render-Time header per task, + // but must correctly destructure { pdf, durationMs } + let app: express.Express; + + beforeEach(async () => { + vi.clearAllMocks(); + vi.resetModules(); + + const { renderPdf } = await import("../services/browser.js"); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 30 } as any); + + const dbMod = await import("../services/db.js"); + if (vi.isMockFunction(dbMod.default?.prepare)) { + // db is already mocked elsewhere + } + }); + + it("templates route still returns valid PDF after refactor", async () => { + // This is covered by existing templates-route tests; + // we just verify the mock shape works + const { renderPdf } = await import("../services/browser.js"); + const result = await vi.mocked(renderPdf)("

test

"); + expect(result).toHaveProperty("pdf"); + expect(result).toHaveProperty("durationMs"); + expect((result as any).durationMs).toBe(30); + }); + }); +}); diff --git a/src/__tests__/setup.ts b/src/__tests__/setup.ts index 1c319c6..90a9690 100644 --- a/src/__tests__/setup.ts +++ b/src/__tests__/setup.ts @@ -56,8 +56,8 @@ vi.mock("../services/keys.js", () => { vi.mock("../services/browser.js", () => ({ initBrowser: vi.fn().mockResolvedValue(undefined), closeBrowser: vi.fn().mockResolvedValue(undefined), - renderPdf: vi.fn().mockResolvedValue(Buffer.from("%PDF-1.4 mock pdf content here")), - renderUrlPdf: vi.fn().mockResolvedValue(Buffer.from("%PDF-1.4 mock url pdf content")), + renderPdf: vi.fn().mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock pdf content here"), durationMs: 10 }), + renderUrlPdf: vi.fn().mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock url pdf content"), durationMs: 10 }), getPoolStats: vi.fn().mockReturnValue({ poolSize: 16, totalPages: 16, diff --git a/src/__tests__/templates-render-validation.test.ts b/src/__tests__/templates-render-validation.test.ts index 9730b0d..f1b847f 100644 --- a/src/__tests__/templates-render-validation.test.ts +++ b/src/__tests__/templates-render-validation.test.ts @@ -16,7 +16,7 @@ beforeEach(async () => { vi.clearAllMocks(); const { renderPdf } = await import("../services/browser.js"); - vi.mocked(renderPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock")); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 10 }); const { authMiddleware } = await import("../middleware/auth.js"); const { usageMiddleware } = await import("../middleware/usage.js"); diff --git a/src/__tests__/templates-route.test.ts b/src/__tests__/templates-route.test.ts index e21399e..e6c848f 100644 --- a/src/__tests__/templates-route.test.ts +++ b/src/__tests__/templates-route.test.ts @@ -8,7 +8,7 @@ beforeEach(async () => { vi.clearAllMocks(); const { renderPdf } = await import("../services/browser.js"); - vi.mocked(renderPdf).mockResolvedValue(Buffer.from("%PDF-1.4 mock")); + vi.mocked(renderPdf).mockResolvedValue({ pdf: Buffer.from("%PDF-1.4 mock"), durationMs: 10 }); const { authMiddleware } = await import("../middleware/auth.js"); const { usageMiddleware } = await import("../middleware/usage.js"); diff --git a/src/routes/convert.ts b/src/routes/convert.ts index 684c873..69a2dc3 100644 --- a/src/routes/convert.ts +++ b/src/routes/convert.ts @@ -113,13 +113,14 @@ convertRouter.post("/html", async (req: Request & { acquirePdfSlot?: () => Promi ? body.html : wrapHtml(body.html, body.css); - const pdf = await renderPdf(fullHtml, { + const { pdf, durationMs } = await renderPdf(fullHtml, { ...validation.sanitized, }); const filename = sanitizeFilename(body.filename || "document.pdf"); res.setHeader("Content-Type", "application/pdf"); res.setHeader("Content-Disposition", `inline; filename="${filename}"`); + res.setHeader("X-Render-Time", String(durationMs)); res.send(pdf); } catch (err: any) { logger.error({ err }, "Convert HTML error"); @@ -214,13 +215,14 @@ convertRouter.post("/markdown", async (req: Request & { acquirePdfSlot?: () => P } const html = markdownToHtml(body.markdown, body.css); - const pdf = await renderPdf(html, { + const { pdf, durationMs } = await renderPdf(html, { ...validation.sanitized, }); const filename = sanitizeFilename(body.filename || "document.pdf"); res.setHeader("Content-Type", "application/pdf"); res.setHeader("Content-Disposition", `inline; filename="${filename}"`); + res.setHeader("X-Render-Time", String(durationMs)); res.send(pdf); } catch (err: any) { logger.error({ err }, "Convert MD error"); @@ -345,7 +347,7 @@ convertRouter.post("/url", async (req: Request & { acquirePdfSlot?: () => Promis slotAcquired = true; } - const pdf = await renderUrlPdf(body.url, { + const { pdf, durationMs } = await renderUrlPdf(body.url, { ...validation.sanitized, hostResolverRules: `MAP ${parsed.hostname} ${resolvedAddress}`, }); @@ -353,6 +355,7 @@ convertRouter.post("/url", async (req: Request & { acquirePdfSlot?: () => Promis const filename = sanitizeFilename(body.filename || "page.pdf"); res.setHeader("Content-Type", "application/pdf"); res.setHeader("Content-Disposition", `inline; filename="${filename}"`); + res.setHeader("X-Render-Time", String(durationMs)); res.send(pdf); } catch (err: any) { logger.error({ err }, "Convert URL error"); diff --git a/src/routes/demo.ts b/src/routes/demo.ts index ab1862f..a60c4d1 100644 --- a/src/routes/demo.ts +++ b/src/routes/demo.ts @@ -133,7 +133,7 @@ router.post("/html", async (req: Request & { acquirePdfSlot?: () => Promise Promise Promise< printBackground: true, margin: { top: "0", right: "0", bottom: "0", left: "0" }, }; - const pdf = await renderPdf(fullHtml, { + const { pdf, durationMs } = await renderPdf(fullHtml, { ...defaultOpts, ...validation.sanitized, }); @@ -246,6 +247,7 @@ router.post("/markdown", async (req: Request & { acquirePdfSlot?: () => Promise< res.setHeader("Content-Type", "application/pdf"); res.setHeader("Content-Disposition", `attachment; filename="${filename}"`); res.setHeader("Content-Length", pdf.length); + res.setHeader("X-Render-Time", String(durationMs)); res.send(pdf); } catch (err: any) { if (err.message === "QUEUE_FULL") { diff --git a/src/routes/templates.ts b/src/routes/templates.ts index b02c60e..7653ba0 100644 --- a/src/routes/templates.ts +++ b/src/routes/templates.ts @@ -166,7 +166,7 @@ templatesRouter.post("/:id/render", async (req: Request, res: Response) => { const sanitizedPdf = { format: "A4" as string, ...validation.sanitized }; const html = renderTemplate(id, data); - const pdf = await renderPdf(html, sanitizedPdf); + const { pdf, durationMs } = await renderPdf(html, sanitizedPdf); const filename = sanitizeFilename(data._filename || `${id}.pdf`); res.setHeader("Content-Type", "application/pdf"); diff --git a/src/services/browser.ts b/src/services/browser.ts index becf34c..9bd894d 100644 --- a/src/services/browser.ts +++ b/src/services/browser.ts @@ -239,10 +239,11 @@ export interface PdfRenderOptions { export async function renderPdf( html: string, options: PdfRenderOptions = {} -): Promise { +): Promise<{ pdf: Buffer; durationMs: number }> { const { page, instance } = await acquirePage(); try { await page.setJavaScriptEnabled(false); + const startTime = Date.now(); const result = await Promise.race([ (async () => { await page.setContent(html, { waitUntil: "domcontentloaded", timeout: 15_000 }); @@ -267,7 +268,9 @@ export async function renderPdf( setTimeout(() => reject(new Error("PDF_TIMEOUT")), 30_000) ), ]); - return result; + const durationMs = Date.now() - startTime; + logger.info(`PDF rendered in ${durationMs}ms (html, ${result.length} bytes)`); + return { pdf: result, durationMs }; } finally { releasePage(page, instance); } @@ -279,7 +282,7 @@ export async function renderUrlPdf( waitUntil?: string; hostResolverRules?: string; } = {} -): Promise { +): Promise<{ pdf: Buffer; durationMs: number }> { const { page, instance } = await acquirePage(); try { await page.setJavaScriptEnabled(false); @@ -316,6 +319,7 @@ export async function renderUrlPdf( }); } } + const startTime = Date.now(); const result = await Promise.race([ (async () => { await page.goto(url, { @@ -342,7 +346,9 @@ export async function renderUrlPdf( setTimeout(() => reject(new Error("PDF_TIMEOUT")), 30_000) ), ]); - return result; + const durationMs = Date.now() - startTime; + logger.info(`PDF rendered in ${durationMs}ms (url, ${result.length} bytes)`); + return { pdf: result, durationMs }; } finally { releasePage(page, instance); }