From 3052f7b799bfa4b4b3a1a5f23269c54146b4bf38 Mon Sep 17 00:00:00 2001 From: Ramadhan Sjamsani Date: Mon, 25 May 2026 22:09:14 +0800 Subject: [PATCH] Xendit webhook: metadata.app routing + survival audit log + rolling fallback file MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every Xendit invoice now carries metadata: { app: 'halobestie_v2' } so an external webhook router (no DB access) can fan out v1/v2 traffic purely off the echoed payload. Every inbound webhook lands in a new webhook_logs table BEFORE auth or business logic, so a forensic row survives 401/409/unknown/exception paths. Primary fields are parsed as columns; raw_body keeps the full payload verbatim. The handler captures outcome in closure-scoped vars and stamps http_status/processing_result/processing_error in a single update before the lone reply.send() — Fastify flushes reply.send() immediately, which defeated the original finally-block stamp. A non-UUID external_id no longer crashes the Postgres cast; it ACKs with ignored_non_uuid_external_id so Xendit stops retrying legacy old-app IDs. When the DB log itself fails, an optional rolling JSONL file sink absorbs the event. Disabled by default — opt in via XENDIT_WEBHOOK_FALLBACK_ENABLED. Naming: -YYYY-MM-DD.jsonl in XENDIT_WEBHOOK_FALLBACK_DIR (default ./logs), basename XENDIT_WEBHOOK_FALLBACK_NAME (default xendit-webhook-fallback). No stdout fallback by design. Co-Authored-By: Claude Opus 4.7 (1M context) --- backend/.env.example | 14 + backend/src/db/migrate.js | 59 +++++ .../public/shared.payment-webhooks.routes.js | 244 +++++++++++++----- backend/src/services/payment.service.js | 3 + backend/src/services/webhook-log.service.js | 166 ++++++++++++ backend/test/helpers/db.js | 1 + .../shared.payment-webhooks.routes.test.js | 175 +++++++++++++ .../test/services/webhook-log.service.test.js | 184 +++++++++++++ 8 files changed, 783 insertions(+), 63 deletions(-) create mode 100644 backend/src/services/webhook-log.service.js create mode 100644 backend/test/services/webhook-log.service.test.js diff --git a/backend/.env.example b/backend/.env.example index 612ddb9..ea277bb 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -71,3 +71,17 @@ XENDIT_SECRET_KEY= XENDIT_WEBHOOK_TOKEN= XENDIT_SUCCESS_REDIRECT_URL= XENDIT_FAILURE_REDIRECT_URL= + +# --- Xendit webhook survival sink (optional file-based fallback) --- +# +# When the primary DB log (`webhook_logs` table) is unreachable, the route can +# spill each inbound webhook to a daily-rolling JSONL file instead. Disabled +# by default — production opts in by mounting a persistent volume / GCS sync +# and flipping XENDIT_WEBHOOK_FALLBACK_ENABLED=true. The handler will NOT +# fall back to stdout; if both DB and this sink are unavailable the event is +# dropped. +# +# Filename pattern: "-YYYY-MM-DD.jsonl" (UTC day boundary). +XENDIT_WEBHOOK_FALLBACK_ENABLED=false +XENDIT_WEBHOOK_FALLBACK_DIR=./logs +XENDIT_WEBHOOK_FALLBACK_NAME=xendit-webhook-fallback diff --git a/backend/src/db/migrate.js b/backend/src/db/migrate.js index 026059c..9a4965e 100644 --- a/backend/src/db/migrate.js +++ b/backend/src/db/migrate.js @@ -1086,6 +1086,65 @@ const migrate = async () => { AND product_type = 'chat_session' ` + // 10. webhook_logs — survival/audit table for every inbound payment-provider + // webhook. The route handler inserts a row BEFORE auth checks or business + // logic so a forensic record exists even when the request is rejected, + // the body is malformed, or processing throws. + // + // Primary fields are extracted as columns (queryable in CC, indexed where + // useful); the full body is kept in `raw_body` JSONB so we can replay or + // diff later. `provider` is a string column (not enum) so adding a new + // payment provider doesn't require a migration. + // + // No FK to payment_requests — logs must survive even if the matching + // payment row was wiped, never existed, or arrives for a product/event + // type we don't yet model. + await sql` + CREATE TABLE IF NOT EXISTS webhook_logs ( + id UUID PRIMARY KEY DEFAULT gen_random_uuid(), + provider TEXT NOT NULL DEFAULT 'xendit', + received_at TIMESTAMPTZ NOT NULL DEFAULT NOW(), + + -- Parsed primary fields (Xendit Invoice callback shape — NULL for other event types) + xendit_event_id TEXT, + external_id TEXT, + payment_request_id UUID, + status TEXT, + amount BIGINT, + currency TEXT, + payment_method TEXT, + paid_at TIMESTAMPTZ, + metadata_app TEXT, + + -- Integrity + verbatim record + callback_token_valid BOOLEAN NOT NULL, + headers JSONB NOT NULL, + raw_body JSONB NOT NULL, + + -- Outcome (filled by the handler after processing). Leaving these NULL + -- is itself a useful signal — it means the handler crashed before the + -- finally block could stamp the result. + http_status SMALLINT, + processing_result TEXT, + processing_error TEXT, + processed_at TIMESTAMPTZ + ) + ` + await sql` + CREATE INDEX IF NOT EXISTS idx_webhook_logs_received_at + ON webhook_logs (received_at DESC) + ` + await sql` + CREATE INDEX IF NOT EXISTS idx_webhook_logs_external_id + ON webhook_logs (external_id) + WHERE external_id IS NOT NULL + ` + await sql` + CREATE INDEX IF NOT EXISTS idx_webhook_logs_payment_request + ON webhook_logs (payment_request_id) + WHERE payment_request_id IS NOT NULL + ` + console.log('Migration complete.') await sql.end() } diff --git a/backend/src/routes/public/shared.payment-webhooks.routes.js b/backend/src/routes/public/shared.payment-webhooks.routes.js index 6c3b2cd..3ac44e2 100644 --- a/backend/src/routes/public/shared.payment-webhooks.routes.js +++ b/backend/src/routes/public/shared.payment-webhooks.routes.js @@ -6,87 +6,205 @@ // `x-callback-token` header verified against env XENDIT_WEBHOOK_TOKEN. // // Body shape from Xendit Invoice callback (relevant fields only): -// { id, external_id, status, amount, payment_method, paid_at, ... } +// { id, external_id, status, amount, payment_method, paid_at, metadata, ... } // // Handled statuses: PAID (→ confirmPayment), EXPIRED (→ expirePayment). // Anything else ACKs with `{ ok: true, ignored: }` for forward-compat. // -// All state transitions go through payment.service.js — this handler is just -// the entry point. Events emit from inside the service, not from here. +// SURVIVAL LOGGING — every inbound webhook lands in `webhook_logs` BEFORE the +// auth check or any business logic, so we keep a forensic record even when: +// • the token is wrong (401) +// • the body is malformed / missing external_id +// • the referenced payment_request doesn't exist +// • amount mismatches and we reject (409) +// • downstream processing throws (500) +// +// If the DB insert itself fails, an optional rolling-file sink can absorb the +// event (see WEBHOOK_FALLBACK_* env vars in webhook-log.service.js). The sink +// is disabled by default — production opts in by mounting a persistent volume +// and flipping WEBHOOK_FALLBACK_ENABLED=true. We deliberately do NOT fall +// back to stdout; operators decide if/where survival writes happen. +// +// CONTROL FLOW NOTE — branches set `result` + `httpStatus` + `responseBody` +// into closure vars rather than calling `reply.send()` directly. Fastify +// flushes the response on `reply.send()` and `app.inject` resolves before any +// post-send finally would run, which would lose the outcome columns. We +// instead update the log once at the end, then send the reply once. import { confirmPayment, expirePayment, getPayment, verifyWebhookToken } from '../../services/payment.service.js' +import { + insertWebhookLog, + sanitizeHeaders, + updateWebhookLog, + writeWebhookFallback, +} from '../../services/webhook-log.service.js' + +// Our payment_requests.id is a UUID. A non-UUID external_id is either a legacy +// old-app invoice (should have been filtered by the router) or a stray Xendit +// event for a product we don't model. Skip the DB lookup (it would throw on +// the cast) and ACK so Xendit stops retrying. +const UUID_RE = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i export const paymentWebhookRoutes = async (app) => { app.post('/webhooks/xendit', async (request, reply) => { - const headerToken = request.headers['x-callback-token'] - if (!verifyWebhookToken(headerToken)) { - request.log.warn('xendit webhook: bad token') - return reply.code(401).send({ error: 'invalid_token' }) - } - const body = request.body ?? {} - const invoiceId = body.id - const paymentRequestId = body.external_id - const status = body.status - const amount = typeof body.amount === 'number' ? body.amount : null - const paymentMethod = body.payment_method ?? null - - request.log.info( - { paymentRequestId, invoiceId, status, amount, paymentMethod }, - 'xendit webhook received', - ) - - if (!paymentRequestId) { - // Forward-compat: future Xendit event types may not carry external_id - return reply.send({ ok: true, ignored: 'no_external_id' }) - } - - const existing = await getPayment(paymentRequestId) - if (!existing) { - // Unknown payment — could be stale orphan from a wiped dev DB. ACK so Xendit - // stops retrying; warn so we notice if this becomes common in prod. - request.log.warn({ paymentRequestId, invoiceId }, 'unknown payment_request — ACKing') - return reply.send({ ok: true, ignored: 'unknown_payment_request' }) - } - - if (status === 'PAID') { - // Defensive: amount mismatch = either tampering or config drift. Refuse to confirm. - if (amount !== null && amount !== existing.amount) { - request.log.error( - { paymentRequestId, expected: existing.amount, got: amount }, - 'xendit webhook: amount mismatch', - ) - return reply.code(409).send({ error: 'amount_mismatch' }) - } + const headerToken = request.headers['x-callback-token'] + const tokenValid = verifyWebhookToken(headerToken) + const sanitizedHeaders = sanitizeHeaders(request.headers) + // --- STEP 1: survival log ---------------------------------------------- + // Insert before doing anything else. If this throws, attempt the optional + // rolling-file sink (env-gated, off by default). If that ALSO fails or is + // disabled, we silently continue — no stdout fallback by design, the + // operator's env config decides where survival writes go. + let logId = null + try { + logId = await insertWebhookLog({ + provider: 'xendit', + headers: sanitizedHeaders, + rawBody: body, + callbackTokenValid: tokenValid, + }) + } catch (dbErr) { try { - await confirmPayment(paymentRequestId, { invoiceId, paymentMethod, amount }) - } catch (err) { - // INVALID_STATE = already confirmed/consumed (Xendit retry); CONFLICT = race lost. ACK. - // EXPIRED = customer paid AFTER our sweeper expired the row — painful, manual recovery - // needed. Log loud so we notice. (D5 alignment should keep this rare.) - if (err.code === 'INVALID_STATE' || err.code === 'CONFLICT') { - request.log.info( - { paymentRequestId, code: err.code, prevStatus: existing.status }, - 'xendit webhook: already in terminal state, ACKing', - ) - } else if (err.code === 'EXPIRED') { - request.log.error( - { paymentRequestId, expiredAt: existing.expires_at }, - 'xendit webhook: PAID after expiry — manual recovery needed', - ) + await writeWebhookFallback({ + provider: 'xendit', + headers: sanitizedHeaders, + rawBody: body, + callbackTokenValid: tokenValid, + dbErrorMessage: dbErr?.message, + }) + } catch { + // Both sinks down. Nothing left to try — proceed without an audit + // trail. The operator chose this configuration; failure here is + // their disk/permission/config issue to monitor externally. + } + } + + // --- STEP 2: process --------------------------------------------------- + // Defaults match the "uncaught exception in processing" case — finally + // (well, the post-try outcome stamp below) will stamp these into the log. + let result = 'error' + let httpStatus = 500 + let responseBody = { error: 'internal_error' } + let errorMsg = null + + try { + if (!tokenValid) { + request.log.warn('xendit webhook: bad token') + result = 'rejected_invalid_token' + httpStatus = 401 + responseBody = { error: 'invalid_token' } + } else { + const invoiceId = body.id + const paymentRequestId = body.external_id + const status = body.status + const amount = typeof body.amount === 'number' ? body.amount : null + const paymentMethod = body.payment_method ?? null + + request.log.info( + { paymentRequestId, invoiceId, status, amount, paymentMethod }, + 'xendit webhook received', + ) + + if (!paymentRequestId) { + // Forward-compat: future Xendit event types may not carry external_id + result = 'ignored_no_external_id' + httpStatus = 200 + responseBody = { ok: true, ignored: 'no_external_id' } + } else if (!UUID_RE.test(paymentRequestId)) { + // Not one of ours — see UUID_RE comment above. + request.log.warn({ paymentRequestId, invoiceId }, 'non-UUID external_id — ACKing') + result = 'ignored_non_uuid_external_id' + httpStatus = 200 + responseBody = { ok: true, ignored: 'non_uuid_external_id' } } else { - throw err + const existing = await getPayment(paymentRequestId) + if (!existing) { + // Unknown payment — could be stale orphan from a wiped dev DB. ACK so Xendit + // stops retrying; warn so we notice if this becomes common in prod. + request.log.warn({ paymentRequestId, invoiceId }, 'unknown payment_request — ACKing') + result = 'ignored_unknown_payment_request' + httpStatus = 200 + responseBody = { ok: true, ignored: 'unknown_payment_request' } + } else if (status === 'PAID') { + // Defensive: amount mismatch = either tampering or config drift. Refuse to confirm. + if (amount !== null && amount !== existing.amount) { + request.log.error( + { paymentRequestId, expected: existing.amount, got: amount }, + 'xendit webhook: amount mismatch', + ) + result = 'rejected_amount_mismatch' + httpStatus = 409 + responseBody = { error: 'amount_mismatch' } + } else { + try { + await confirmPayment(paymentRequestId, { invoiceId, paymentMethod, amount }) + result = 'confirmed' + } catch (err) { + // INVALID_STATE = already confirmed/consumed (Xendit retry); CONFLICT = race lost. ACK. + // EXPIRED = customer paid AFTER our sweeper expired the row — painful, manual + // recovery needed. Log loud so we notice. (D5 alignment should keep + // this rare.) + if (err.code === 'INVALID_STATE' || err.code === 'CONFLICT') { + request.log.info( + { paymentRequestId, code: err.code, prevStatus: existing.status }, + 'xendit webhook: already in terminal state, ACKing', + ) + result = `idempotent_${err.code.toLowerCase()}` + } else if (err.code === 'EXPIRED') { + request.log.error( + { paymentRequestId, expiredAt: existing.expires_at }, + 'xendit webhook: PAID after expiry — manual recovery needed', + ) + result = 'paid_after_expiry' + } else { + throw err + } + } + httpStatus = 200 + responseBody = { ok: true } + } + } else if (status === 'EXPIRED') { + await expirePayment(paymentRequestId) + result = 'expired' + httpStatus = 200 + responseBody = { ok: true } + } else { + result = `ignored_${status}` + httpStatus = 200 + responseBody = { ok: true, ignored: status } + } } } - return reply.send({ ok: true }) + } catch (err) { + // Anything that bubbles out of the processing block lands here. We do NOT + // re-throw — instead we ACK to ourselves (logged loudly) and return 500 + // so Xendit retries on its own schedule. The forensic row records why. + errorMsg = err?.message ?? String(err) + request.log.error( + { err: errorMsg, paymentRequestId: body.external_id }, + 'xendit webhook: unhandled exception during processing', + ) + // Defaults already at result='error', httpStatus=500, responseBody=error } - if (status === 'EXPIRED') { - await expirePayment(paymentRequestId) - return reply.send({ ok: true }) + // --- STEP 3: outcome stamp + reply ------------------------------------- + // Awaited so the log row is consistent before we hand control back to the + // framework. Wrapped in its own try/catch: a failed update must never + // prevent us from responding to Xendit. + if (logId) { + try { + await updateWebhookLog(logId, { + httpStatus, + processingResult: result, + processingError: errorMsg, + }) + } catch (updErr) { + request.log.error({ err: updErr?.message, logId }, 'webhook_log update failed') + } } - return reply.send({ ok: true, ignored: status }) + return reply.code(httpStatus).send(responseBody) }) } diff --git a/backend/src/services/payment.service.js b/backend/src/services/payment.service.js index 1287402..c79738e 100644 --- a/backend/src/services/payment.service.js +++ b/backend/src/services/payment.service.js @@ -98,6 +98,9 @@ const createXenditInvoice = async ({ paymentRequestId, amount, ttlMinutes, descr currency: 'IDR', successRedirectUrl: successRedirectUrl || undefined, failureRedirectUrl: failureRedirectUrl || undefined, + // Stamped so a shared webhook router (no DB access) can route v1 vs v2 traffic + // purely from the echoed payload. Keep this string stable — it is a routing key. + metadata: { app: 'halobestie_v2' }, // paymentMethods omitted → honor dashboard config (operator picks methods without a deploy) }, }) diff --git a/backend/src/services/webhook-log.service.js b/backend/src/services/webhook-log.service.js new file mode 100644 index 0000000..8285276 --- /dev/null +++ b/backend/src/services/webhook-log.service.js @@ -0,0 +1,166 @@ +// Provider-agnostic webhook audit log. Every inbound provider webhook (Xendit +// today; others later) gets a row in `webhook_logs` BEFORE we run any auth or +// business logic, so a forensic record survives rejection, malformed bodies, +// and processing exceptions. +// +// Primary fields are parsed as columns (queryable / indexed); the entire body +// stays in `raw_body` JSONB verbatim so we can replay or diff later. Outcome +// columns are stamped by the route after processing. +// +// SECONDARY SINK — when the DB insert itself fails (DB outage, schema drift), +// an optional file-based sink writes one JSONL line per event to a daily +// rolling file. Disabled by default; opt in via env. We deliberately do NOT +// fall back to stdout — operators who want survival pick the file sink. +// +// This module exposes only what the route needs: +// sanitizeHeaders(headers) → header dict with secrets redacted +// insertWebhookLog({...}) → returns inserted row id +// updateWebhookLog(id, {...}) → stamps outcome columns +// writeWebhookFallback({...}) → optional file sink on DB failure +// getWebhookLog(id) [test/CC use] → row or null + +import { appendFile, mkdir } from 'node:fs/promises' +import path from 'node:path' +import { getDb } from '../db/client.js' + +const sql = getDb() + +// Header values we never persist. We still keep the *names* so callers can see +// which auth scheme the request used — only the secret material is dropped. +const SECRET_HEADER_NAMES = new Set([ + 'x-callback-token', + 'authorization', + 'cookie', + 'set-cookie', + 'proxy-authorization', +]) + +export const sanitizeHeaders = (headers) => { + const out = {} + for (const [k, v] of Object.entries(headers ?? {})) { + const key = k.toLowerCase() + out[key] = SECRET_HEADER_NAMES.has(key) ? '[REDACTED]' : v + } + return out +} + +const UUID_RE = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i +const isUuid = (s) => typeof s === 'string' && UUID_RE.test(s) +const str = (v) => (typeof v === 'string' ? v : null) +const num = (v) => (typeof v === 'number' && Number.isFinite(v) ? v : null) + +const parseTimestamp = (v) => { + if (typeof v !== 'string') return null + const d = new Date(v) + return Number.isFinite(d.getTime()) ? d.toISOString() : null +} + +/** + * Insert the survival row. Throws only if the DB itself is unreachable — the + * caller wraps this in try/catch and falls through to a structured-log + * fallback so a misbehaving DB never causes Xendit to retry forever. + */ +export const insertWebhookLog = async ({ provider, headers, rawBody, callbackTokenValid }) => { + const body = rawBody ?? {} + const externalId = str(body.external_id) + const paymentRequestId = isUuid(externalId) ? externalId : null + const [row] = await sql` + INSERT INTO webhook_logs ( + provider, headers, raw_body, callback_token_valid, + xendit_event_id, external_id, payment_request_id, + status, amount, currency, payment_method, paid_at, metadata_app + ) VALUES ( + ${provider}, + ${sql.json(headers ?? {})}, + ${sql.json(body)}, + ${callbackTokenValid}, + ${str(body.id)}, + ${externalId}, + ${paymentRequestId}, + ${str(body.status)}, + ${num(body.amount)}, + ${str(body.currency)}, + ${str(body.payment_method)}, + ${parseTimestamp(body.paid_at)}, + ${str(body?.metadata?.app)} + ) + RETURNING id + ` + return row.id +} + +/** + * Stamp outcome columns once the handler has decided a response. Wrapped by + * the caller in its own try/catch so a failed update never replaces the + * original processing error. + */ +export const updateWebhookLog = async (logId, { httpStatus, processingResult, processingError }) => { + await sql` + UPDATE webhook_logs + SET http_status = ${httpStatus ?? null}, + processing_result = ${processingResult ?? null}, + processing_error = ${processingError ?? null}, + processed_at = NOW() + WHERE id = ${logId} + ` +} + +export const getWebhookLog = async (logId) => { + const rows = await sql`SELECT * FROM webhook_logs WHERE id = ${logId}` + return rows[0] ?? null +} + +// --- Secondary sink: rolling JSONL file -------------------------------------- +// +// Only used when the DB insert above fails. Env-controlled so production can +// opt in (e.g. mount a persistent volume + tail with logrotate) without +// affecting dev/test machines. By default the sink is OFF — the handler will +// silently skip it and rely on the DB as the sole audit trail. +// +// Config (xendit_ prefix groups these with the other XENDIT_* vars): +// XENDIT_WEBHOOK_FALLBACK_ENABLED — "true" to enable; anything else = off (default off) +// XENDIT_WEBHOOK_FALLBACK_DIR — directory the JSONL files live in (default "./logs") +// XENDIT_WEBHOOK_FALLBACK_NAME — basename for rolling files (default "xendit-webhook-fallback") +// +// Rolling pattern: one file per UTC day, named "-YYYY-MM-DD.jsonl". +// Old files accumulate — pair with logrotate / GCS sync if you need retention +// limits. We don't size-rotate inside Node because the fallback only fires on +// DB outage, which should be rare enough that daily granularity is plenty. + +export const getWebhookFallbackConfig = () => ({ + enabled: process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED === 'true', + dir: process.env.XENDIT_WEBHOOK_FALLBACK_DIR || './logs', + name: process.env.XENDIT_WEBHOOK_FALLBACK_NAME || 'xendit-webhook-fallback', +}) + +export const rollingFallbackFilename = (name, now = new Date()) => { + const yyyy = now.getUTCFullYear() + const mm = String(now.getUTCMonth() + 1).padStart(2, '0') + const dd = String(now.getUTCDate()).padStart(2, '0') + return `${name}-${yyyy}-${mm}-${dd}.jsonl` +} + +/** + * Append one JSONL line to the rolling fallback file. Returns true if the + * write happened, false if the sink is disabled. Throws on real I/O errors — + * the caller decides whether to swallow. + */ +export const writeWebhookFallback = async ({ provider, headers, rawBody, callbackTokenValid, dbErrorMessage }) => { + const cfg = getWebhookFallbackConfig() + if (!cfg.enabled) return false + + const filename = rollingFallbackFilename(cfg.name) + const filepath = path.join(cfg.dir, filename) + const line = JSON.stringify({ + received_at: new Date().toISOString(), + provider, + callback_token_valid: callbackTokenValid, + headers, + raw_body: rawBody, + db_error: dbErrorMessage ?? null, + }) + '\n' + + await mkdir(cfg.dir, { recursive: true }) + await appendFile(filepath, line, 'utf8') + return true +} diff --git a/backend/test/helpers/db.js b/backend/test/helpers/db.js index 39717d5..0985157 100644 --- a/backend/test/helpers/db.js +++ b/backend/test/helpers/db.js @@ -19,6 +19,7 @@ export const db = () => getDb() * force every test to re-create users (slow + noisy). */ const TRUNCATE_TABLES = [ + 'webhook_logs', 'pairing_failures', 'payment_requests', 'chat_request_notifications', diff --git a/backend/test/routes/shared.payment-webhooks.routes.test.js b/backend/test/routes/shared.payment-webhooks.routes.test.js index cff266b..988ef4a 100644 --- a/backend/test/routes/shared.payment-webhooks.routes.test.js +++ b/backend/test/routes/shared.payment-webhooks.routes.test.js @@ -187,4 +187,179 @@ describe('POST /api/shared/payment/webhooks/xendit', () => { const [row] = await db()`SELECT status FROM payment_requests WHERE id = ${session.id}` expect(row.status).toBe(PaymentRequestStatus.PENDING) }) + + // --- Survival logging -------------------------------------------------- + // Every inbound webhook lands in `webhook_logs` BEFORE auth/validation, so + // we keep a forensic record on rejects, unknown payments, and exceptions. + describe('webhook_logs survival audit', () => { + const latestLog = async () => { + const rows = await db()`SELECT * FROM webhook_logs ORDER BY received_at DESC LIMIT 1` + return rows[0] + } + + it('PAID: logs row with parsed primary fields + outcome stamped', async () => { + const session = await requestPayment({ + productType: 'chat_session', + customerId: customer.id, durationMinutes: 12, amount: 50_000, + }) + + await fireWebhook(app, { + id: 'inv_log_paid', + external_id: session.id, + status: 'PAID', + amount: 50_000, + currency: 'IDR', + payment_method: 'BCA', + paid_at: '2026-05-25T10:00:00.000Z', + metadata: { app: 'halobestie_v2' }, + }) + + const log = await latestLog() + expect(log.provider).toBe('xendit') + expect(log.callback_token_valid).toBe(true) + expect(log.xendit_event_id).toBe('inv_log_paid') + expect(log.external_id).toBe(session.id) + expect(log.payment_request_id).toBe(session.id) + expect(log.status).toBe('PAID') + expect(Number(log.amount)).toBe(50_000) + expect(log.currency).toBe('IDR') + expect(log.payment_method).toBe('BCA') + expect(log.paid_at).not.toBeNull() + expect(log.metadata_app).toBe('halobestie_v2') + expect(log.http_status).toBe(200) + expect(log.processing_result).toBe('confirmed') + expect(log.processing_error).toBeNull() + expect(log.processed_at).not.toBeNull() + // raw_body is verbatim — unknown future fields would land here + expect(log.raw_body.metadata.app).toBe('halobestie_v2') + }) + + it('401 invalid token still logs a row with callback_token_valid=false', async () => { + const res = await fireWebhook( + app, + { id: 'inv_log_401', external_id: 'whatever', status: 'PAID', amount: 1 }, + 'wrong-token-but-same-length-padding', + ) + expect(res.statusCode).toBe(401) + + const log = await latestLog() + expect(log.callback_token_valid).toBe(false) + expect(log.http_status).toBe(401) + expect(log.processing_result).toBe('rejected_invalid_token') + // Raw body still captured even though the request was rejected + expect(log.raw_body.id).toBe('inv_log_401') + }) + + it('redacts x-callback-token in stored headers', async () => { + await fireWebhook(app, { id: 'inv_redact', external_id: 'x', status: 'PAID', amount: 1 }) + const log = await latestLog() + expect(log.headers['x-callback-token']).toBe('[REDACTED]') + // Non-secret headers are kept (e.g. content-type) + expect(log.headers['content-type']).toMatch(/application\/json/) + }) + + it('amount mismatch (409) logs rejected_amount_mismatch', async () => { + const session = await requestPayment({ + productType: 'chat_session', + customerId: customer.id, durationMinutes: 12, amount: 50_000, + }) + const res = await fireWebhook(app, { + id: 'inv_log_mismatch', external_id: session.id, status: 'PAID', amount: 999, + }) + expect(res.statusCode).toBe(409) + + const log = await latestLog() + expect(log.http_status).toBe(409) + expect(log.processing_result).toBe('rejected_amount_mismatch') + expect(Number(log.amount)).toBe(999) + }) + + it('unknown payment_request still logs ignored_unknown_payment_request', async () => { + await fireWebhook(app, { + id: 'inv_log_orphan', + external_id: '00000000-0000-0000-0000-000000000000', + status: 'PAID', + amount: 50_000, + }) + const log = await latestLog() + expect(log.processing_result).toBe('ignored_unknown_payment_request') + expect(log.payment_request_id).toBe('00000000-0000-0000-0000-000000000000') + }) + + it('missing external_id logs ignored_no_external_id with payment_request_id NULL', async () => { + await fireWebhook(app, { id: 'evt_nox', status: 'SOMETHING' }) + const log = await latestLog() + expect(log.processing_result).toBe('ignored_no_external_id') + expect(log.external_id).toBeNull() + expect(log.payment_request_id).toBeNull() + }) + + it('non-UUID external_id ACKs 200 and logs ignored_non_uuid_external_id', async () => { + const res = await fireWebhook(app, { + id: 'inv_log_legacy', + external_id: 'legacy-old-app-id-42', + status: 'PAID', + amount: 1, + }) + expect(res.statusCode).toBe(200) + expect(res.json().ignored).toBe('non_uuid_external_id') + + const log = await latestLog() + expect(log.external_id).toBe('legacy-old-app-id-42') + expect(log.payment_request_id).toBeNull() + expect(log.processing_result).toBe('ignored_non_uuid_external_id') + expect(log.http_status).toBe(200) + }) + + it('logs raw_body verbatim including unknown fields', async () => { + const session = await requestPayment({ + productType: 'chat_session', + customerId: customer.id, durationMinutes: 12, amount: 50_000, + }) + await fireWebhook(app, { + id: 'inv_log_extra', + external_id: session.id, + status: 'PAID', + amount: 50_000, + future_field_we_dont_know_yet: { nested: ['anything', 42] }, + metadata: { app: 'halobestie_v2', extra: 'preserved' }, + }) + const log = await latestLog() + expect(log.raw_body.future_field_we_dont_know_yet.nested).toEqual(['anything', 42]) + expect(log.raw_body.metadata.extra).toBe('preserved') + expect(log.metadata_app).toBe('halobestie_v2') + }) + + it('survives processing exceptions: logs processing_error + http_status=500', async () => { + // Force an exception by stubbing getPayment to throw. The survival + // contract is that even when the handler errors, the forensic row is + // intact and stamped — Xendit will retry on its own, but we have the + // record either way. + const paymentSvc = await import('../../src/services/payment.service.js') + const orig = paymentSvc.getPayment + const stub = vi.spyOn(paymentSvc, 'getPayment').mockImplementation(async () => { + throw new Error('synthetic_db_outage') + }) + try { + const res = await fireWebhook(app, { + id: 'inv_boom', + external_id: '11111111-1111-1111-1111-111111111111', + status: 'PAID', + amount: 50_000, + }) + expect(res.statusCode).toBe(500) + + const log = await latestLog() + expect(log.http_status).toBe(500) + expect(log.processing_result).toBe('error') + expect(log.processing_error).toBe('synthetic_db_outage') + expect(log.xendit_event_id).toBe('inv_boom') + // Raw body is still there even though processing blew up + expect(log.raw_body.id).toBe('inv_boom') + } finally { + stub.mockRestore() + void orig + } + }) + }) }) diff --git a/backend/test/services/webhook-log.service.test.js b/backend/test/services/webhook-log.service.test.js new file mode 100644 index 0000000..993a28a --- /dev/null +++ b/backend/test/services/webhook-log.service.test.js @@ -0,0 +1,184 @@ +import { describe, it, expect, afterEach, beforeEach } from 'vitest' +import { mkdtemp, readFile, rm, readdir } from 'node:fs/promises' +import { tmpdir } from 'node:os' +import path from 'node:path' + +const { + rollingFallbackFilename, + getWebhookFallbackConfig, + writeWebhookFallback, + sanitizeHeaders, +} = await import('../../src/services/webhook-log.service.js') + +describe('webhook-log.service helpers', () => { + describe('sanitizeHeaders', () => { + it('redacts secret-bearing headers but keeps their names', () => { + const out = sanitizeHeaders({ + 'x-callback-token': 'shhhh', + 'Authorization': 'Bearer abc', + 'cookie': 'sid=xyz', + 'content-type': 'application/json', + 'x-request-id': 'req-1', + }) + expect(out['x-callback-token']).toBe('[REDACTED]') + expect(out['authorization']).toBe('[REDACTED]') + expect(out['cookie']).toBe('[REDACTED]') + expect(out['content-type']).toBe('application/json') + expect(out['x-request-id']).toBe('req-1') + }) + + it('lowercases keys so lookups are consistent', () => { + const out = sanitizeHeaders({ 'X-Callback-Token': 't', 'Content-Type': 'app/json' }) + expect(out['x-callback-token']).toBe('[REDACTED]') + expect(out['content-type']).toBe('app/json') + expect(out['X-Callback-Token']).toBeUndefined() + }) + }) + + describe('rollingFallbackFilename', () => { + it('produces "-YYYY-MM-DD.jsonl" using UTC day boundary', () => { + const d = new Date(Date.UTC(2026, 4, 25, 10, 30)) + expect(rollingFallbackFilename('xendit', d)).toBe('xendit-2026-05-25.jsonl') + }) + + it('zero-pads single-digit months and days', () => { + const d = new Date(Date.UTC(2026, 0, 3, 0, 0)) + expect(rollingFallbackFilename('wh', d)).toBe('wh-2026-01-03.jsonl') + }) + + it('a date right before UTC midnight stays on the current day', () => { + const d = new Date(Date.UTC(2026, 4, 25, 23, 59, 59)) + expect(rollingFallbackFilename('x', d)).toBe('x-2026-05-25.jsonl') + }) + }) + + describe('getWebhookFallbackConfig', () => { + const originalEnv = { ...process.env } + afterEach(() => { + // Restore only the vars this suite touches — leaving the rest alone. + for (const k of ['XENDIT_WEBHOOK_FALLBACK_ENABLED', 'XENDIT_WEBHOOK_FALLBACK_DIR', 'XENDIT_WEBHOOK_FALLBACK_NAME']) { + if (originalEnv[k] === undefined) delete process.env[k] + else process.env[k] = originalEnv[k] + } + }) + + it('defaults to disabled with sensible dir/name', () => { + delete process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED + delete process.env.XENDIT_WEBHOOK_FALLBACK_DIR + delete process.env.XENDIT_WEBHOOK_FALLBACK_NAME + expect(getWebhookFallbackConfig()).toEqual({ + enabled: false, + dir: './logs', + name: 'xendit-webhook-fallback', + }) + }) + + it('only the literal string "true" enables the sink', () => { + process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED = '1' + expect(getWebhookFallbackConfig().enabled).toBe(false) + process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED = 'yes' + expect(getWebhookFallbackConfig().enabled).toBe(false) + process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED = 'true' + expect(getWebhookFallbackConfig().enabled).toBe(true) + }) + + it('honors custom dir/name', () => { + process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED = 'true' + process.env.XENDIT_WEBHOOK_FALLBACK_DIR = '/var/log/webhooks' + process.env.XENDIT_WEBHOOK_FALLBACK_NAME = 'xendit-prod' + expect(getWebhookFallbackConfig()).toEqual({ + enabled: true, + dir: '/var/log/webhooks', + name: 'xendit-prod', + }) + }) + }) + + describe('writeWebhookFallback', () => { + let workDir + const originalEnv = { ...process.env } + + beforeEach(async () => { + workDir = await mkdtemp(path.join(tmpdir(), 'webhook-fallback-')) + }) + + afterEach(async () => { + for (const k of ['XENDIT_WEBHOOK_FALLBACK_ENABLED', 'XENDIT_WEBHOOK_FALLBACK_DIR', 'XENDIT_WEBHOOK_FALLBACK_NAME']) { + if (originalEnv[k] === undefined) delete process.env[k] + else process.env[k] = originalEnv[k] + } + await rm(workDir, { recursive: true, force: true }) + }) + + it('returns false and writes nothing when disabled', async () => { + delete process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED + const ok = await writeWebhookFallback({ + provider: 'xendit', + headers: { 'content-type': 'application/json' }, + rawBody: { id: 'inv_x' }, + callbackTokenValid: true, + }) + expect(ok).toBe(false) + expect(await readdir(workDir)).toEqual([]) + }) + + it('appends one JSONL line per call to the rolling daily file', async () => { + process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED = 'true' + process.env.XENDIT_WEBHOOK_FALLBACK_DIR = workDir + process.env.XENDIT_WEBHOOK_FALLBACK_NAME = 'test-fallback' + + await writeWebhookFallback({ + provider: 'xendit', + headers: { 'content-type': 'application/json', 'x-callback-token': '[REDACTED]' }, + rawBody: { id: 'inv_a', external_id: 'pr-1', status: 'PAID' }, + callbackTokenValid: true, + dbErrorMessage: 'connection refused', + }) + await writeWebhookFallback({ + provider: 'xendit', + headers: {}, + rawBody: { id: 'inv_b', status: 'EXPIRED' }, + callbackTokenValid: false, + }) + + const files = await readdir(workDir) + expect(files).toHaveLength(1) + expect(files[0]).toMatch(/^test-fallback-\d{4}-\d{2}-\d{2}\.jsonl$/) + + const contents = await readFile(path.join(workDir, files[0]), 'utf8') + const lines = contents.trim().split('\n') + expect(lines).toHaveLength(2) + + const first = JSON.parse(lines[0]) + expect(first.provider).toBe('xendit') + expect(first.callback_token_valid).toBe(true) + expect(first.raw_body.id).toBe('inv_a') + expect(first.raw_body.external_id).toBe('pr-1') + expect(first.db_error).toBe('connection refused') + expect(first.headers['x-callback-token']).toBe('[REDACTED]') + expect(first.received_at).toMatch(/^\d{4}-\d{2}-\d{2}T/) + + const second = JSON.parse(lines[1]) + expect(second.raw_body.id).toBe('inv_b') + expect(second.callback_token_valid).toBe(false) + expect(second.db_error).toBeNull() + }) + + it('creates the destination directory if it does not exist', async () => { + process.env.XENDIT_WEBHOOK_FALLBACK_ENABLED = 'true' + const nested = path.join(workDir, 'does', 'not', 'exist', 'yet') + process.env.XENDIT_WEBHOOK_FALLBACK_DIR = nested + process.env.XENDIT_WEBHOOK_FALLBACK_NAME = 'nested' + + const ok = await writeWebhookFallback({ + provider: 'xendit', + headers: {}, + rawBody: { id: 'inv_n' }, + callbackTokenValid: true, + }) + expect(ok).toBe(true) + const files = await readdir(nested) + expect(files).toHaveLength(1) + }) + }) +})