diff --git a/package-lock.json b/package-lock.json index a0969ce..e825a78 100644 --- a/package-lock.json +++ b/package-lock.json @@ -13,6 +13,7 @@ "@privacybydesign/yivi-core": "^1.0.0", "@privacybydesign/yivi-css": "^1.0.1", "@privacybydesign/yivi-web": "^1.0.1", + "pino": "^10.3.1", "sass": "^1.100.0", "svelte-i18n": "^4.0.1" }, @@ -1690,6 +1691,12 @@ "url": "https://opencollective.com/parcel" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@playwright/test": { "version": "1.60.0", "resolved": "https://registry.npmjs.org/@playwright/test/-/test-1.60.0.tgz", @@ -3068,6 +3075,15 @@ "node": ">=12" } }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/axobject-query": { "version": "4.1.0", "resolved": "https://registry.npmjs.org/axobject-query/-/axobject-query-4.1.0.tgz", @@ -5164,6 +5180,15 @@ ], "license": "MIT" }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/optionator": { "version": "0.9.4", "resolved": "https://registry.npmjs.org/optionator/-/optionator-0.9.4.tgz", @@ -5276,6 +5301,43 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.3.1.tgz", + "integrity": "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, "node_modules/playwright": { "version": "1.60.0", "resolved": "https://registry.npmjs.org/playwright/-/playwright-1.60.0.tgz", @@ -5508,6 +5570,22 @@ "svelte": "^5.0.0" } }, + "node_modules/process-warning": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.0.0.tgz", + "integrity": "sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/punycode": { "version": "2.3.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.3.1.tgz", @@ -5535,6 +5613,12 @@ "node": ">=10.13.0" } }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/readdirp": { "version": "4.1.2", "resolved": "https://registry.npmjs.org/readdirp/-/readdirp-4.1.2.tgz", @@ -5549,6 +5633,15 @@ "url": "https://paulmillr.com/funding/" } }, + "node_modules/real-require": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-0.2.0.tgz", + "integrity": "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==", + "license": "MIT", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/require-directory": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/require-directory/-/require-directory-2.1.1.tgz", @@ -5694,6 +5787,15 @@ "node": ">=6" } }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/sass": { "version": "1.100.0", "resolved": "https://registry.npmjs.org/sass/-/sass-1.100.0.tgz", @@ -5813,6 +5915,15 @@ "node": ">=18" } }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map": { "version": "0.6.1", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", @@ -5843,6 +5954,15 @@ "source-map": "^0.6.0" } }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "engines": { + "node": ">= 10.x" + } + }, "node_modules/stackback": { "version": "0.0.2", "resolved": "https://registry.npmjs.org/stackback/-/stackback-0.0.2.tgz", @@ -6516,6 +6636,24 @@ "@types/estree": "^1.0.6" } }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, + "node_modules/thread-stream/node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, "node_modules/timers-ext": { "version": "0.1.8", "resolved": "https://registry.npmjs.org/timers-ext/-/timers-ext-0.1.8.tgz", @@ -6999,24 +7137,6 @@ "integrity": "sha512-JKhqTOwSrqNA1NY5lSztJ1GrBiUodLMmIZuLiDaMRJ+itFd+ABVE8XBjOvIWL+rSqNDC74LCSFmlb/U4UZ4hJQ==", "license": "ISC" }, - "node_modules/yaml": { - "version": "2.8.4", - "resolved": "https://registry.npmjs.org/yaml/-/yaml-2.8.4.tgz", - "integrity": "sha512-ml/JPOj9fOQK8RNnWojA67GbZ0ApXAUlN2UQclwv2eVgTgn7O9gg9o7paZWKMp4g0H3nTLtS9LVzhkpOFIKzog==", - "dev": true, - "license": "ISC", - "optional": true, - "peer": true, - "bin": { - "yaml": "bin.mjs" - }, - "engines": { - "node": ">= 14.6" - }, - "funding": { - "url": "https://github.com/sponsors/eemeli" - } - }, "node_modules/yargs": { "version": "15.4.1", "resolved": "https://registry.npmjs.org/yargs/-/yargs-15.4.1.tgz", diff --git a/package.json b/package.json index dd8c9d6..7033a9a 100644 --- a/package.json +++ b/package.json @@ -53,6 +53,7 @@ "@privacybydesign/yivi-core": "^1.0.0", "@privacybydesign/yivi-css": "^1.0.1", "@privacybydesign/yivi-web": "^1.0.1", + "pino": "^10.3.1", "sass": "^1.100.0", "svelte-i18n": "^4.0.1" }, diff --git a/src/app.d.ts b/src/app.d.ts index 7490b59..a9aad4c 100644 --- a/src/app.d.ts +++ b/src/app.d.ts @@ -14,6 +14,8 @@ declare global { yiviAttributes: Record; } | null; locale: string; + requestId: string; + log: import('$lib/server/logger').Logger; } // interface PageData {} // interface PageState {} diff --git a/src/hooks.server.ts b/src/hooks.server.ts index d66d9a2..420b9c6 100644 --- a/src/hooks.server.ts +++ b/src/hooks.server.ts @@ -1,8 +1,25 @@ -import type { Handle } from '@sveltejs/kit'; +import type { Handle, HandleServerError } from '@sveltejs/kit'; import { resolveSession } from '$lib/server/auth/session'; import { normalizeLocale } from '$lib/i18n'; +import { logger } from '$lib/server/logger'; + +const REQUEST_ID_MAX = 64; + +// Use a client-supplied X-Request-Id when present (sanitised), otherwise mint +// one. Keeps correlation across a proxy without trusting arbitrary input. +function resolveRequestId(header: string | null): string { + if (header) { + const cleaned = header.replace(/[^a-zA-Z0-9_-]/g, '').slice(0, REQUEST_ID_MAX); + if (cleaned) return cleaned; + } + return crypto.randomUUID(); +} export const handle: Handle = async ({ event, resolve }) => { + const requestId = resolveRequestId(event.request.headers.get('x-request-id')); + event.locals.requestId = requestId; + event.locals.log = logger.child({ requestId }); + const token = event.cookies.get('pg_session'); if (token) { @@ -19,12 +36,39 @@ export const handle: Handle = async ({ event, resolve }) => { // per-request inside `+layout.ts`. event.locals.locale = normalizeLocale(event.request.headers.get('accept-language')); + const start = performance.now(); const response = await resolve(event); + const durationMs = Math.round(performance.now() - start); + response.headers.set('X-Request-Id', requestId); response.headers.set('X-Frame-Options', 'DENY'); response.headers.set('X-Content-Type-Options', 'nosniff'); response.headers.set('Referrer-Policy', 'strict-origin-when-cross-origin'); response.headers.set('Permissions-Policy', 'camera=(), microphone=(), geolocation=()'); + // Skip the noisy liveness/readiness probes. + const path = event.url.pathname; + if (path !== '/health' && path !== '/readyz') { + event.locals.log.info( + { method: event.request.method, path, status: response.status, durationMs }, + 'request' + ); + } + return response; }; + +export const handleError: HandleServerError = ({ error, event, status, message }) => { + logger.error( + { + requestId: event.locals.requestId, + method: event.request.method, + path: event.url.pathname, + status, + err: error instanceof Error ? { message: error.message, stack: error.stack } : String(error) + }, + 'unhandled error' + ); + + return { message }; +}; diff --git a/src/lib/server/logger.ts b/src/lib/server/logger.ts new file mode 100644 index 0000000..cdd12bd --- /dev/null +++ b/src/lib/server/logger.ts @@ -0,0 +1,12 @@ +import pino from 'pino'; +import { env } from '$env/dynamic/private'; + +// Structured JSON logger to stdout. No transport is configured, which keeps it +// robust under the bundled adapter-node server; set LOG_LEVEL to control +// verbosity (default: info). Request-scoped child loggers (carrying a +// requestId) are created in hooks.server.ts and exposed via `event.locals.log`. +export const logger = pino({ + level: env.LOG_LEVEL ?? 'info' +}); + +export type Logger = typeof logger; diff --git a/src/lib/server/services/dns-verification.ts b/src/lib/server/services/dns-verification.ts index 532ea2d..251c128 100644 --- a/src/lib/server/services/dns-verification.ts +++ b/src/lib/server/services/dns-verification.ts @@ -3,6 +3,7 @@ import { dnsVerifications } from '$lib/server/db/schema'; import { eq } from 'drizzle-orm'; import { randomBytes } from 'crypto'; import { resolve } from 'dns/promises'; +import { logger } from '$lib/server/logger'; export async function getOrCreateDnsVerification(orgId: string, domain: string) { const existing = await db @@ -64,12 +65,15 @@ export async function verifyDns(orgId: string): Promise<{ } } catch (err) { const code = (err as NodeJS.ErrnoException)?.code; - console.error('[dns-verification] resolve failed', { - orgId, - domain: record.domain, - code, - message: err instanceof Error ? err.message : String(err) - }); + logger.error( + { + orgId, + domain: record.domain, + code, + err: err instanceof Error ? err.message : String(err) + }, + 'dns resolve failed' + ); await db .update(dnsVerifications) .set({ lastCheckedAt: new Date() }) diff --git a/src/routes/api/csp-report/+server.ts b/src/routes/api/csp-report/+server.ts index fc82317..0384ed8 100644 --- a/src/routes/api/csp-report/+server.ts +++ b/src/routes/api/csp-report/+server.ts @@ -1,9 +1,9 @@ import type { RequestHandler } from './$types'; -export const POST: RequestHandler = async ({ request }) => { +export const POST: RequestHandler = async ({ request, locals }) => { try { const text = await request.text(); - console.warn('[csp-report]', text.slice(0, 4096)); + locals.log.warn({ report: text.slice(0, 4096) }, 'csp violation'); } catch { // ignore — best-effort } diff --git a/tests/unit/dns-verification.test.ts b/tests/unit/dns-verification.test.ts index 3736f7f..d3a9aaa 100644 --- a/tests/unit/dns-verification.test.ts +++ b/tests/unit/dns-verification.test.ts @@ -1,6 +1,6 @@ import { describe, it, expect, vi, beforeEach } from 'vitest'; -const { resolveMock, selectLimitMock, updateWhereMock, dbMock } = vi.hoisted(() => { +const { resolveMock, selectLimitMock, updateWhereMock, dbMock, loggerMock } = vi.hoisted(() => { const selectLimitMock = vi.fn(); const updateWhereMock = vi.fn().mockResolvedValue(undefined); const dbMock = { @@ -18,11 +18,13 @@ const { resolveMock, selectLimitMock, updateWhereMock, dbMock } = vi.hoisted(() }), insert: vi.fn() }; + const loggerMock = { error: vi.fn(), warn: vi.fn(), info: vi.fn(), debug: vi.fn() }; return { resolveMock: vi.fn(), selectLimitMock, updateWhereMock, - dbMock + dbMock, + loggerMock }; }); @@ -40,6 +42,8 @@ vi.mock('drizzle-orm', () => ({ eq: (a: unknown, b: unknown) => ({ a, b }) })); +vi.mock('$lib/server/logger', () => ({ logger: loggerMock })); + import { verifyDns } from '$lib/server/services/dns-verification'; const record = { @@ -53,19 +57,18 @@ beforeEach(() => { resolveMock.mockReset(); selectLimitMock.mockReset(); updateWhereMock.mockClear(); + loggerMock.error.mockClear(); selectLimitMock.mockResolvedValue([record]); }); describe('verifyDns', () => { it('returns verified: true when the TXT record matches', async () => { resolveMock.mockResolvedValueOnce([[record.txtRecord]]); - const errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); const result = await verifyDns('org-1'); expect(result).toEqual({ verified: true }); - expect(errSpy).not.toHaveBeenCalled(); - errSpy.mockRestore(); + expect(loggerMock.error).not.toHaveBeenCalled(); }); it('returns the "not found in DNS" message when no TXT matches', async () => { @@ -84,52 +87,46 @@ describe('verifyDns', () => { code: 'ENOTFOUND' }); resolveMock.mockRejectedValueOnce(enotfound); - const errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); const result = await verifyDns('org-1'); expect(result.verified).toBe(false); expect(result.error).toBe(`Domain ${record.domain} not found`); - expect(errSpy).toHaveBeenCalledTimes(1); - expect(errSpy.mock.calls[0][1]).toMatchObject({ + expect(loggerMock.error).toHaveBeenCalledTimes(1); + expect(loggerMock.error.mock.calls[0][0]).toMatchObject({ orgId: 'org-1', domain: record.domain, code: 'ENOTFOUND' }); expect(updateWhereMock).toHaveBeenCalledTimes(1); - errSpy.mockRestore(); }); it('returns a "no TXT records" message and logs when resolve throws ENODATA', async () => { const enodata = Object.assign(new Error('queryTxt ENODATA example.com'), { code: 'ENODATA' }); resolveMock.mockRejectedValueOnce(enodata); - const errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); const result = await verifyDns('org-1'); expect(result.verified).toBe(false); expect(result.error).toBe(`No TXT records found for ${record.domain}`); - expect(errSpy).toHaveBeenCalledTimes(1); - expect(errSpy.mock.calls[0][1]).toMatchObject({ code: 'ENODATA' }); - errSpy.mockRestore(); + expect(loggerMock.error).toHaveBeenCalledTimes(1); + expect(loggerMock.error.mock.calls[0][0]).toMatchObject({ code: 'ENODATA' }); }); it('falls back to the generic message and logs when resolve throws a plain Error', async () => { resolveMock.mockRejectedValueOnce(new Error('something else')); - const errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); const result = await verifyDns('org-1'); expect(result.verified).toBe(false); expect(result.error).toBe(`Could not resolve DNS for ${record.domain}`); - expect(errSpy).toHaveBeenCalledTimes(1); - expect(errSpy.mock.calls[0][1]).toMatchObject({ + expect(loggerMock.error).toHaveBeenCalledTimes(1); + expect(loggerMock.error.mock.calls[0][0]).toMatchObject({ orgId: 'org-1', domain: record.domain, - message: 'something else' + err: 'something else' }); expect(updateWhereMock).toHaveBeenCalledTimes(1); - errSpy.mockRestore(); }); it('returns the "no verification record" message when none exists for the org', async () => {