log-fanout.ts507 lines · main
| 1 | import { newId } from '@briven/shared'; |
| 2 | import { and, eq, isNull, lt, sql } from 'drizzle-orm'; |
| 3 | |
| 4 | import { getDb } from '../db/client.js'; |
| 5 | import { |
| 6 | auditLogs, |
| 7 | functionLogs, |
| 8 | projects, |
| 9 | webhookDeliveries, |
| 10 | webhookOutboundDeliveries, |
| 11 | type NewFunctionLog, |
| 12 | type ProjectTier, |
| 13 | } from '../db/schema.js'; |
| 14 | import { getRedis } from '../lib/redis.js'; |
| 15 | import { log } from '../lib/logger.js'; |
| 16 | |
| 17 | const BATCH_MAX = 500; |
| 18 | const BATCH_WINDOW_MS = 1_000; |
| 19 | const BLOCK_MS = 5_000; |
| 20 | const RECONNECT_BACKOFF_MS = [500, 1_000, 2_500, 5_000, 10_000]; |
| 21 | |
| 22 | /** |
| 23 | * Subscribes to every project's `logs:{projectId}` stream and fans |
| 24 | * entries out into the meta-DB `function_logs` table for durable storage |
| 25 | * and dashboard queries. Best-effort — a crashed worker may drop recent |
| 26 | * entries, which is acceptable for debug logs (audit logs use a separate |
| 27 | * pathway with stronger guarantees). |
| 28 | * |
| 29 | * Single worker per api process; Phase 3+ can split into a dedicated |
| 30 | * worker service if throughput demands. |
| 31 | */ |
| 32 | export function startLogFanoutWorker(): void { |
| 33 | void runLoop().catch((err: unknown) => { |
| 34 | log.error('log_fanout_worker_crashed', { |
| 35 | message: err instanceof Error ? err.message : String(err), |
| 36 | }); |
| 37 | }); |
| 38 | } |
| 39 | |
| 40 | async function runLoop(): Promise<void> { |
| 41 | let attempt = 0; |
| 42 | let lastId = '$'; // start from NEW entries on fresh boot |
| 43 | while (true) { |
| 44 | const sharedRedis = getRedis(); |
| 45 | if (!sharedRedis) { |
| 46 | // No redis = nothing to fan out. Sleep a minute, reconsider config. |
| 47 | await sleep(60_000); |
| 48 | continue; |
| 49 | } |
| 50 | const blocking = sharedRedis.duplicate(); |
| 51 | try { |
| 52 | log.info('log_fanout_connected'); |
| 53 | attempt = 0; |
| 54 | while (true) { |
| 55 | // Discover all active project streams. XREAD needs explicit stream |
| 56 | // names; Redis can't wildcard. Per project this is one SCAN cycle |
| 57 | // every BATCH_WINDOW_MS — cheap for <10k projects. |
| 58 | const streams = await scanStreams(sharedRedis); |
| 59 | if (streams.length === 0) { |
| 60 | await sleep(BATCH_WINDOW_MS); |
| 61 | continue; |
| 62 | } |
| 63 | const keys = streams.flat(); |
| 64 | const ids = streams.map(() => lastId); |
| 65 | |
| 66 | const reply = (await blocking.xread( |
| 67 | 'COUNT', |
| 68 | BATCH_MAX, |
| 69 | 'BLOCK', |
| 70 | BLOCK_MS, |
| 71 | 'STREAMS', |
| 72 | ...keys, |
| 73 | ...ids, |
| 74 | )) as Array<[string, Array<[string, string[]]>]> | null; |
| 75 | |
| 76 | if (!reply) continue; |
| 77 | |
| 78 | const rows: NewFunctionLog[] = []; |
| 79 | for (const [key, entries] of reply) { |
| 80 | const projectId = key.slice('logs:'.length); |
| 81 | for (const [id, flat] of entries) { |
| 82 | const fields = parseFields(flat); |
| 83 | if (fields.kind !== 'invocation') continue; |
| 84 | rows.push(toRow(projectId, fields)); |
| 85 | lastId = id; |
| 86 | } |
| 87 | } |
| 88 | if (rows.length > 0) { |
| 89 | await persist(rows); |
| 90 | } |
| 91 | } |
| 92 | } catch (err) { |
| 93 | log.warn('log_fanout_disconnected', { |
| 94 | message: err instanceof Error ? err.message : String(err), |
| 95 | }); |
| 96 | blocking.disconnect(); |
| 97 | const delay = RECONNECT_BACKOFF_MS[Math.min(attempt, RECONNECT_BACKOFF_MS.length - 1)]!; |
| 98 | attempt += 1; |
| 99 | await sleep(delay); |
| 100 | } |
| 101 | } |
| 102 | } |
| 103 | |
| 104 | async function scanStreams(redis: ReturnType<typeof getRedis>): Promise<string[][]> { |
| 105 | if (!redis) return []; |
| 106 | const out: string[][] = []; |
| 107 | let cursor = '0'; |
| 108 | do { |
| 109 | const [next, batch] = (await redis.scan(cursor, 'MATCH', 'logs:*', 'COUNT', 200)) as [ |
| 110 | string, |
| 111 | string[], |
| 112 | ]; |
| 113 | for (const key of batch) { |
| 114 | // Exclude subscriber counters and other non-stream keys. |
| 115 | if (key.startsWith('logs:subscribers:')) continue; |
| 116 | out.push([key]); |
| 117 | } |
| 118 | cursor = next; |
| 119 | } while (cursor !== '0'); |
| 120 | return out; |
| 121 | } |
| 122 | |
| 123 | async function persist(rows: NewFunctionLog[]): Promise<void> { |
| 124 | try { |
| 125 | await getDb().insert(functionLogs).values(rows); |
| 126 | } catch (err) { |
| 127 | log.error('log_fanout_insert_failed', { |
| 128 | count: rows.length, |
| 129 | message: err instanceof Error ? err.message : String(err), |
| 130 | }); |
| 131 | } |
| 132 | } |
| 133 | |
| 134 | function toRow(projectId: string, f: Record<string, string>): NewFunctionLog { |
| 135 | return { |
| 136 | id: newId('fn'), |
| 137 | projectId, |
| 138 | deploymentId: f.deploymentId ?? '', |
| 139 | invocationId: f.invocationId ?? '', |
| 140 | functionName: (f.functionName ?? '').slice(0, 128), |
| 141 | status: (f.status ?? 'err').slice(0, 8), |
| 142 | durationMs: (f.durationMs ?? '0').slice(0, 12), |
| 143 | touchedTables: (f.touchedTables ?? '').split(',').filter(Boolean), |
| 144 | userLogsJson: safeJson(f.logs) ?? [], |
| 145 | errCode: f.errCode ?? null, |
| 146 | errMessage: f.errMessage ?? null, |
| 147 | }; |
| 148 | } |
| 149 | |
| 150 | function safeJson(raw: string | undefined): unknown { |
| 151 | if (!raw) return null; |
| 152 | try { |
| 153 | return JSON.parse(raw); |
| 154 | } catch { |
| 155 | return null; |
| 156 | } |
| 157 | } |
| 158 | |
| 159 | function parseFields(flat: string[]): Record<string, string> { |
| 160 | const out: Record<string, string> = {}; |
| 161 | for (let i = 0; i < flat.length; i += 2) { |
| 162 | const k = flat[i]; |
| 163 | const v = flat[i + 1]; |
| 164 | if (typeof k === 'string' && typeof v === 'string') out[k] = v; |
| 165 | } |
| 166 | return out; |
| 167 | } |
| 168 | |
| 169 | /** Days of function-log retention per tier. Used by `pruneOldFunctionLogs`. */ |
| 170 | export const RETENTION_DAYS_BY_TIER: Record<ProjectTier, number> = { |
| 171 | free: 7, |
| 172 | pro: 30, |
| 173 | team: 90, |
| 174 | }; |
| 175 | |
| 176 | /** |
| 177 | * Retention: drop `function_log` rows older than the per-tier cutoff. The |
| 178 | * `projects.tier` column is the denormalised tier; we group projects by |
| 179 | * tier (only three groups) and issue one DELETE per tier with that |
| 180 | * tier's cutoff. A project that's been soft-deleted is treated as `free` |
| 181 | * (shortest retention) — its data is on the way out anyway. |
| 182 | * |
| 183 | * Returns the total deleted-row count summed across tiers. |
| 184 | */ |
| 185 | export async function pruneOldFunctionLogs(): Promise<number> { |
| 186 | const db = getDb(); |
| 187 | let total = 0; |
| 188 | const now = Date.now(); |
| 189 | |
| 190 | for (const [tier, days] of Object.entries(RETENTION_DAYS_BY_TIER) as Array< |
| 191 | [ProjectTier, number] |
| 192 | >) { |
| 193 | const cutoff = new Date(now - days * 86_400_000); |
| 194 | // Subquery: every project on this tier that isn't soft-deleted. |
| 195 | // Soft-deleted projects fall through to the `free` (shortest) branch. |
| 196 | const tierProjects = db |
| 197 | .select({ id: projects.id }) |
| 198 | .from(projects) |
| 199 | .where(and(eq(projects.tier, tier), isNull(projects.deletedAt))); |
| 200 | |
| 201 | const res = await db |
| 202 | .delete(functionLogs) |
| 203 | .where( |
| 204 | and( |
| 205 | lt(functionLogs.createdAt, cutoff), |
| 206 | sql`${functionLogs.projectId} IN ${tierProjects}`, |
| 207 | ), |
| 208 | ) |
| 209 | .returning({ id: functionLogs.id }); |
| 210 | total += res.length; |
| 211 | if (res.length > 0) { |
| 212 | log.info('function_logs_pruned', { |
| 213 | tier, |
| 214 | days, |
| 215 | count: res.length, |
| 216 | cutoff: cutoff.toISOString(), |
| 217 | }); |
| 218 | } |
| 219 | } |
| 220 | |
| 221 | // Catch-all: soft-deleted projects + any projects whose tier somehow |
| 222 | // doesn't match free|pro|team (data corruption hedge). Apply the |
| 223 | // shortest retention. |
| 224 | const freeCutoff = new Date(now - RETENTION_DAYS_BY_TIER.free * 86_400_000); |
| 225 | const knownTiers = sql.raw( |
| 226 | Object.keys(RETENTION_DAYS_BY_TIER).map((t) => `'${t}'`).join(','), |
| 227 | ); |
| 228 | const orphans = db |
| 229 | .select({ id: projects.id }) |
| 230 | .from(projects) |
| 231 | .where(sql`${projects.deletedAt} IS NOT NULL OR ${projects.tier} NOT IN (${knownTiers})`); |
| 232 | const orphanRes = await db |
| 233 | .delete(functionLogs) |
| 234 | .where( |
| 235 | and( |
| 236 | lt(functionLogs.createdAt, freeCutoff), |
| 237 | sql`${functionLogs.projectId} IN ${orphans}`, |
| 238 | ), |
| 239 | ) |
| 240 | .returning({ id: functionLogs.id }); |
| 241 | total += orphanRes.length; |
| 242 | if (orphanRes.length > 0) { |
| 243 | log.info('function_logs_pruned', { |
| 244 | tier: 'orphan', |
| 245 | days: RETENTION_DAYS_BY_TIER.free, |
| 246 | count: orphanRes.length, |
| 247 | cutoff: freeCutoff.toISOString(), |
| 248 | }); |
| 249 | } |
| 250 | |
| 251 | return total; |
| 252 | } |
| 253 | |
| 254 | const RETENTION_TICK_MS = 6 * 60 * 60 * 1000; |
| 255 | |
| 256 | export function startLogRetentionCron(): void { |
| 257 | const run = (): void => { |
| 258 | void pruneOldFunctionLogs().catch((err: unknown) => { |
| 259 | log.warn('function_logs_prune_failed', { |
| 260 | message: err instanceof Error ? err.message : String(err), |
| 261 | }); |
| 262 | }); |
| 263 | }; |
| 264 | // Run once shortly after boot (so a restart doesn't skip a whole day if |
| 265 | // the previous tick fired a few minutes before), then every 6h. |
| 266 | setTimeout(run, 30_000); |
| 267 | setInterval(run, RETENTION_TICK_MS); |
| 268 | } |
| 269 | |
| 270 | /* ─── audit-log retention (privacy policy §5) ───────────────────────── */ |
| 271 | // Privacy policy commits to a 13-month audit retention window. Anything |
| 272 | // older gets deleted on a daily sweep. Volume is low (a few hundred rows |
| 273 | // per day at our current scale) so we don't need batched deletes; the |
| 274 | // single statement runs in ms. |
| 275 | |
| 276 | export const AUDIT_RETENTION_DAYS = 30 * 13; // 13 months ≈ 390 days |
| 277 | |
| 278 | /** |
| 279 | * Cutoff date for audit-log retention based on `now`. Extracted so the |
| 280 | * boundary logic is unit-testable without standing up the DB. |
| 281 | */ |
| 282 | export function auditRetentionCutoff(nowMs: number): Date { |
| 283 | return new Date(nowMs - AUDIT_RETENTION_DAYS * 86_400_000); |
| 284 | } |
| 285 | |
| 286 | export async function pruneOldAuditLogs(): Promise<number> { |
| 287 | const db = getDb(); |
| 288 | const cutoff = auditRetentionCutoff(Date.now()); |
| 289 | const res = await db |
| 290 | .delete(auditLogs) |
| 291 | .where(lt(auditLogs.createdAt, cutoff)) |
| 292 | .returning({ id: auditLogs.id }); |
| 293 | if (res.length > 0) { |
| 294 | log.info('audit_logs_pruned', { |
| 295 | count: res.length, |
| 296 | retentionDays: AUDIT_RETENTION_DAYS, |
| 297 | cutoff: cutoff.toISOString(), |
| 298 | }); |
| 299 | } |
| 300 | return res.length; |
| 301 | } |
| 302 | |
| 303 | // 24h between runs. Audit volume is low so checking more often wastes |
| 304 | // db round-trips for no operational benefit. |
| 305 | const AUDIT_RETENTION_TICK_MS = 24 * 60 * 60 * 1000; |
| 306 | |
| 307 | export function startAuditRetentionCron(): void { |
| 308 | const run = (): void => { |
| 309 | void pruneOldAuditLogs().catch((err: unknown) => { |
| 310 | log.warn('audit_logs_prune_failed', { |
| 311 | message: err instanceof Error ? err.message : String(err), |
| 312 | }); |
| 313 | }); |
| 314 | }; |
| 315 | // 60s after boot (small offset from function-logs cron at 30s so a |
| 316 | // fresh boot doesn't fire both simultaneously), then daily. |
| 317 | setTimeout(run, 60_000); |
| 318 | setInterval(run, AUDIT_RETENTION_TICK_MS); |
| 319 | } |
| 320 | |
| 321 | /* ─── webhook-delivery retention ────────────────────────────────────── */ |
| 322 | // webhook_deliveries grows one row per inbound POST. A leaked endpoint |
| 323 | // can amplify that into a real cost without bounded retention. We reuse |
| 324 | // RETENTION_DAYS_BY_TIER (same scheme as function_logs) — short enough |
| 325 | // to keep the table small, long enough for operators to debug yesterday's |
| 326 | // failed signatures. |
| 327 | |
| 328 | export async function pruneOldWebhookDeliveries(): Promise<number> { |
| 329 | const db = getDb(); |
| 330 | let total = 0; |
| 331 | const now = Date.now(); |
| 332 | |
| 333 | for (const [tier, days] of Object.entries(RETENTION_DAYS_BY_TIER) as Array< |
| 334 | [ProjectTier, number] |
| 335 | >) { |
| 336 | const cutoff = new Date(now - days * 86_400_000); |
| 337 | const tierProjects = db |
| 338 | .select({ id: projects.id }) |
| 339 | .from(projects) |
| 340 | .where(and(eq(projects.tier, tier), isNull(projects.deletedAt))); |
| 341 | |
| 342 | const res = await db |
| 343 | .delete(webhookDeliveries) |
| 344 | .where( |
| 345 | and( |
| 346 | lt(webhookDeliveries.createdAt, cutoff), |
| 347 | sql`${webhookDeliveries.projectId} IN ${tierProjects}`, |
| 348 | ), |
| 349 | ) |
| 350 | .returning({ id: webhookDeliveries.id }); |
| 351 | total += res.length; |
| 352 | if (res.length > 0) { |
| 353 | log.info('webhook_deliveries_pruned', { |
| 354 | tier, |
| 355 | days, |
| 356 | count: res.length, |
| 357 | cutoff: cutoff.toISOString(), |
| 358 | }); |
| 359 | } |
| 360 | } |
| 361 | |
| 362 | // Catch-all for soft-deleted / unknown-tier projects. Same shortest- |
| 363 | // retention treatment as function_logs. |
| 364 | const freeCutoff = new Date(now - RETENTION_DAYS_BY_TIER.free * 86_400_000); |
| 365 | const knownTiers = sql.raw( |
| 366 | Object.keys(RETENTION_DAYS_BY_TIER) |
| 367 | .map((t) => `'${t}'`) |
| 368 | .join(','), |
| 369 | ); |
| 370 | const orphans = db |
| 371 | .select({ id: projects.id }) |
| 372 | .from(projects) |
| 373 | .where(sql`${projects.deletedAt} IS NOT NULL OR ${projects.tier} NOT IN (${knownTiers})`); |
| 374 | const orphanRes = await db |
| 375 | .delete(webhookDeliveries) |
| 376 | .where( |
| 377 | and( |
| 378 | lt(webhookDeliveries.createdAt, freeCutoff), |
| 379 | sql`${webhookDeliveries.projectId} IN ${orphans}`, |
| 380 | ), |
| 381 | ) |
| 382 | .returning({ id: webhookDeliveries.id }); |
| 383 | total += orphanRes.length; |
| 384 | if (orphanRes.length > 0) { |
| 385 | log.info('webhook_deliveries_pruned', { |
| 386 | tier: 'orphan', |
| 387 | days: RETENTION_DAYS_BY_TIER.free, |
| 388 | count: orphanRes.length, |
| 389 | cutoff: freeCutoff.toISOString(), |
| 390 | }); |
| 391 | } |
| 392 | |
| 393 | return total; |
| 394 | } |
| 395 | |
| 396 | const WEBHOOK_DELIVERIES_RETENTION_TICK_MS = 6 * 60 * 60 * 1000; |
| 397 | |
| 398 | export function startWebhookDeliveriesRetentionCron(): void { |
| 399 | const run = (): void => { |
| 400 | void pruneOldWebhookDeliveries().catch((err: unknown) => { |
| 401 | log.warn('webhook_deliveries_prune_failed', { |
| 402 | message: err instanceof Error ? err.message : String(err), |
| 403 | }); |
| 404 | }); |
| 405 | }; |
| 406 | // 90s after boot — offset from the other retention crons so a fresh |
| 407 | // boot doesn't fire all three simultaneously and hold connection |
| 408 | // pool capacity that the api request path also needs. |
| 409 | setTimeout(run, 90_000); |
| 410 | setInterval(run, WEBHOOK_DELIVERIES_RETENTION_TICK_MS); |
| 411 | } |
| 412 | |
| 413 | /* ─── outbound-delivery retention ───────────────────────────────────── */ |
| 414 | // webhook_outbound_deliveries grows under retry storms — each event |
| 415 | // emission inserts one row per subscriber, and a failing endpoint can |
| 416 | // keep a row pending for ~30 min while attempts back off. Same per-tier |
| 417 | // cutoff as function_logs + inbound deliveries (free=7d, pro=30d, |
| 418 | // team=90d). Terminal rows (ok/failed/cancelled) prune by created_at; |
| 419 | // pending rows are spared regardless of age — they're still on the |
| 420 | // dispatcher's retry path until terminal. |
| 421 | |
| 422 | export async function pruneOldOutboundWebhookDeliveries(): Promise<number> { |
| 423 | const db = getDb(); |
| 424 | let total = 0; |
| 425 | const now = Date.now(); |
| 426 | |
| 427 | for (const [tier, days] of Object.entries(RETENTION_DAYS_BY_TIER) as Array< |
| 428 | [ProjectTier, number] |
| 429 | >) { |
| 430 | const cutoff = new Date(now - days * 86_400_000); |
| 431 | const tierProjects = db |
| 432 | .select({ id: projects.id }) |
| 433 | .from(projects) |
| 434 | .where(and(eq(projects.tier, tier), isNull(projects.deletedAt))); |
| 435 | const res = await db |
| 436 | .delete(webhookOutboundDeliveries) |
| 437 | .where( |
| 438 | and( |
| 439 | lt(webhookOutboundDeliveries.createdAt, cutoff), |
| 440 | sql`${webhookOutboundDeliveries.projectId} IN ${tierProjects}`, |
| 441 | sql`${webhookOutboundDeliveries.status} <> 'pending'`, |
| 442 | ), |
| 443 | ) |
| 444 | .returning({ id: webhookOutboundDeliveries.id }); |
| 445 | total += res.length; |
| 446 | if (res.length > 0) { |
| 447 | log.info('outbound_deliveries_pruned', { |
| 448 | tier, |
| 449 | days, |
| 450 | count: res.length, |
| 451 | cutoff: cutoff.toISOString(), |
| 452 | }); |
| 453 | } |
| 454 | } |
| 455 | |
| 456 | // Orphan sweep — soft-deleted projects + unknown tiers, shortest cutoff. |
| 457 | const freeCutoff = new Date(now - RETENTION_DAYS_BY_TIER.free * 86_400_000); |
| 458 | const knownTiers = sql.raw( |
| 459 | Object.keys(RETENTION_DAYS_BY_TIER) |
| 460 | .map((t) => `'${t}'`) |
| 461 | .join(','), |
| 462 | ); |
| 463 | const orphans = db |
| 464 | .select({ id: projects.id }) |
| 465 | .from(projects) |
| 466 | .where(sql`${projects.deletedAt} IS NOT NULL OR ${projects.tier} NOT IN (${knownTiers})`); |
| 467 | const orphanRes = await db |
| 468 | .delete(webhookOutboundDeliveries) |
| 469 | .where( |
| 470 | and( |
| 471 | lt(webhookOutboundDeliveries.createdAt, freeCutoff), |
| 472 | sql`${webhookOutboundDeliveries.projectId} IN ${orphans}`, |
| 473 | sql`${webhookOutboundDeliveries.status} <> 'pending'`, |
| 474 | ), |
| 475 | ) |
| 476 | .returning({ id: webhookOutboundDeliveries.id }); |
| 477 | total += orphanRes.length; |
| 478 | if (orphanRes.length > 0) { |
| 479 | log.info('outbound_deliveries_pruned', { |
| 480 | tier: 'orphan', |
| 481 | days: RETENTION_DAYS_BY_TIER.free, |
| 482 | count: orphanRes.length, |
| 483 | cutoff: freeCutoff.toISOString(), |
| 484 | }); |
| 485 | } |
| 486 | return total; |
| 487 | } |
| 488 | |
| 489 | const OUTBOUND_RETENTION_TICK_MS = 6 * 60 * 60 * 1000; |
| 490 | |
| 491 | export function startOutboundWebhookDeliveriesRetentionCron(): void { |
| 492 | const run = (): void => { |
| 493 | void pruneOldOutboundWebhookDeliveries().catch((err: unknown) => { |
| 494 | log.warn('outbound_deliveries_prune_failed', { |
| 495 | message: err instanceof Error ? err.message : String(err), |
| 496 | }); |
| 497 | }); |
| 498 | }; |
| 499 | // 105s after boot — offset from the inbound retention cron (90s) so |
| 500 | // the two retention sweeps don't race for the same connection pool. |
| 501 | setTimeout(run, 105_000); |
| 502 | setInterval(run, OUTBOUND_RETENTION_TICK_MS); |
| 503 | } |
| 504 | |
| 505 | function sleep(ms: number): Promise<void> { |
| 506 | return new Promise((resolve) => setTimeout(resolve, ms)); |
| 507 | } |