feat(db): add structured logging for database connection pool events …

src/utils/db-pool-log.utils.test.ts

@@ -0,0 +1,177 @@
+import { logDbPoolAcquire, logDbPoolRelease } from './db-pool-log.utils';
+import { logger } from './logger.utils';
+
+jest.mock('./logger.utils', () => ({
+   logger: {
+      debug: jest.fn(),
+      info: jest.fn(),
+      warn: jest.fn(),
+      error: jest.fn(),
+   },
+}));
+
+describe('Database Connection Pool Event Logger (#764)', () => {
+   beforeEach(() => {
+      jest.clearAllMocks();
+   });
+
+   describe('logDbPoolAcquire', () => {
+      it('emits a DEBUG log with pool_size, idle_count, wait_time_ms, and acquired_at fields', () => {
+         const acquiredAt = new Date('2026-08-25T10:00:00.000Z');
+         logDbPoolAcquire({
+            poolSize: 10,
+            idleCount: 7,
+            waitTimeMs: 25,
+            acquiredAt,
+         });
+
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+         expect(logger.info).not.toHaveBeenCalled();
+         expect(logger.warn).not.toHaveBeenCalled();
+
+         const [logPayload, message] = (logger.debug as jest.Mock).mock
+            .calls[0];
+         expect(message).toBe('Database connection acquired');
+         expect(logPayload).toMatchObject({
+            event: 'db_pool_acquire',
+            pool_size: 10,
+            idle_count: 7,
+            wait_time_ms: 25,
+            acquired_at: acquiredAt.toISOString(),
+         });
+      });
+
+      it('formats acquired_at as an ISO 8601 string when given a Date object', () => {
+         const now = new Date();
+         logDbPoolAcquire({
+            poolSize: 15,
+            idleCount: 14,
+            waitTimeMs: 5,
+            acquiredAt: now,
+         });
+
+         const [logPayload] = (logger.debug as jest.Mock).mock.calls[0];
+         expect(logPayload.acquired_at).toBe(now.toISOString());
+      });
+
+      it('uses string timestamp as acquired_at directly if provided as string', () => {
+         const isoStr = '2026-08-25T12:34:56.789Z';
+         logDbPoolAcquire({
+            poolSize: 5,
+            idleCount: 2,
+            waitTimeMs: 10,
+            acquiredAt: isoStr,
+         });
+
+         const [logPayload] = (logger.debug as jest.Mock).mock.calls[0];
+         expect(logPayload.acquired_at).toBe(isoStr);
+      });
+
+      it('does NOT emit a WARN log when wait_time_ms is below 1000ms', () => {
+         logDbPoolAcquire({
+            poolSize: 10,
+            idleCount: 9,
+            waitTimeMs: 500,
+         });
+
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+         expect(logger.warn).not.toHaveBeenCalled();
+      });
+
+      it('boundary test: does NOT emit a WARN log at exactly 1000ms wait_time_ms', () => {
+         logDbPoolAcquire({
+            poolSize: 10,
+            idleCount: 5,
+            waitTimeMs: 1000,
+         });
+
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+         expect(logger.warn).not.toHaveBeenCalled();
+      });
+
+      it('boundary test: DOES emit a WARN log at 1001ms wait_time_ms (>1000ms threshold)', () => {
+         const acquiredAt = new Date('2026-08-25T10:00:00.000Z');
+         logDbPoolAcquire({
+            poolSize: 10,
+            idleCount: 2,
+            waitTimeMs: 1001,
+            acquiredAt,
+         });
+
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+         expect(logger.warn).toHaveBeenCalledTimes(1);
+
+         const [warnPayload, warnMsg] = (logger.warn as jest.Mock).mock
+            .calls[0];
+         expect(warnMsg).toContain('1001ms');
+         expect(warnMsg).toContain('1000ms threshold');
+         expect(warnPayload).toMatchObject({
+            event: 'db_pool_wait_warning',
+            pool_size: 10,
+            idle_count: 2,
+            wait_time_ms: 1001,
+            acquired_at: acquiredAt.toISOString(),
+         });
+      });
+
+      it('emits a WARN log when wait_time_ms is significantly higher than 1000ms (e.g. 2500ms)', () => {
+         logDbPoolAcquire({
+            poolSize: 10,
+            idleCount: 0,
+            waitTimeMs: 2500,
+         });
+
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+         expect(logger.warn).toHaveBeenCalledTimes(1);
+
+         const [warnPayload] = (logger.warn as jest.Mock).mock.calls[0];
+         expect(warnPayload.wait_time_ms).toBe(2500);
+      });
+
+      it('emits normal path events at DEBUG level, not INFO level', () => {
+         logDbPoolAcquire({
+            poolSize: 10,
+            idleCount: 8,
+            waitTimeMs: 10,
+         });
+
+         expect(logger.info).not.toHaveBeenCalled();
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+      });
+   });
+
+   describe('logDbPoolRelease', () => {
+      it('emits a DEBUG log with pool_size, idle_count, and held_for_ms fields', () => {
+         logDbPoolRelease({
+            poolSize: 10,
+            idleCount: 10,
+            heldForMs: 150,
+         });
+
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+         expect(logger.info).not.toHaveBeenCalled();
+         expect(logger.warn).not.toHaveBeenCalled();
+
+         const [logPayload, message] = (logger.debug as jest.Mock).mock
+            .calls[0];
+         expect(message).toBe('Database connection released');
+         expect(logPayload).toMatchObject({
+            event: 'db_pool_release',
+            pool_size: 10,
+            idle_count: 10,
+            held_for_ms: 150,
+         });
+      });
+
+      it('emits normal path release events at DEBUG level, not INFO level', () => {
+         logDbPoolRelease({
+            poolSize: 20,
+            idleCount: 15,
+            heldForMs: 45,
+         });
+
+         expect(logger.info).not.toHaveBeenCalled();
+         expect(logger.debug).toHaveBeenCalledTimes(1);
+      });
+   });
+});

src/utils/db-pool-log.utils.ts

@@ -0,0 +1,66 @@
+import { logger } from './logger.utils';
+import { buildLogFields } from './log-fields.utils';
+
+export interface DbPoolAcquireLogFields {
+   poolSize: number;
+   idleCount: number;
+   waitTimeMs: number;
+   acquiredAt?: Date | string;
+}
+
+export interface DbPoolReleaseLogFields {
+   poolSize: number;
+   idleCount: number;
+   heldForMs: number;
+}
+
+/**
+ * Emits a structured log when a database connection is acquired from the pool.
+ * Normal acquisitions emit a DEBUG level log with pool_size, idle_count, wait_time_ms, and acquired_at.
+ * If waitTimeMs > 1000, a WARN level log is also emitted.
+ */
+export function logDbPoolAcquire(fields: DbPoolAcquireLogFields): void {
+   const acquiredAtISO =
+      fields.acquiredAt instanceof Date
+         ? fields.acquiredAt.toISOString()
+         : typeof fields.acquiredAt === 'string'
+           ? fields.acquiredAt
+           : new Date().toISOString();
+
+   const logPayload = buildLogFields({
+      event: 'db_pool_acquire',
+      pool_size: fields.poolSize,
+      idle_count: fields.idleCount,
+      wait_time_ms: fields.waitTimeMs,
+      acquired_at: acquiredAtISO,
+   });
+
+   logger.debug(logPayload, 'Database connection acquired');
+
+   if (fields.waitTimeMs > 1000) {
+      logger.warn(
+         buildLogFields({
+            event: 'db_pool_wait_warning',
+            pool_size: fields.poolSize,
+            idle_count: fields.idleCount,
+            wait_time_ms: fields.waitTimeMs,
+            acquired_at: acquiredAtISO,
+         }),
+         `Database connection pool wait time (${fields.waitTimeMs}ms) exceeded 1000ms threshold`
+      );
+   }
+}
+
+/**
+ * Emits a structured DEBUG log when a database connection is released back to the pool.
+ */
+export function logDbPoolRelease(fields: DbPoolReleaseLogFields): void {
+   const logPayload = buildLogFields({
+      event: 'db_pool_release',
+      pool_size: fields.poolSize,
+      idle_count: fields.idleCount,
+      held_for_ms: fields.heldForMs,
+   });
+
+   logger.debug(logPayload, 'Database connection released');
+}

src/utils/prisma.utils.ts

@@ -3,6 +3,8 @@ import { createHash } from 'crypto';
 import { envConfig } from '../config';
 import { requestContextStorage } from './als.utils';
 import { logger } from './logger.utils';
+import { describeDatabasePoolConfig } from './db-pool-config.utils';
+import { logDbPoolAcquire, logDbPoolRelease } from './db-pool-log.utils';
 
 // Use global variable to prevent multiple instances in development
 declare global {
@@ -114,20 +116,43 @@ export const prisma = basePrisma.$extends({
             }, timeoutMs);
          });
 
+         const poolConfig = describeDatabasePoolConfig();
+         const poolSize =
+            typeof poolConfig.poolSize === 'number' ? poolConfig.poolSize : 10;
+
+         const acquiredAt = new Date();
+         const waitTimeMs = acquiredAt.getTime() - waitStart;
+         const acquireIdleCount = Math.max(0, poolSize - activeQueries);
+
+         logDbPoolAcquire({
+            poolSize,
+            idleCount: acquireIdleCount,
+            waitTimeMs,
+            acquiredAt,
+         });
+
          const start = Date.now();
          const queryPromise = query(args).finally(() => {
             clearTimeout(timeoutId);
             const waitTime = Date.now() - waitStart;
             activeQueries--;
             queryStartTimes.delete(queryId);
 
+            const heldForMs = Date.now() - acquiredAt.getTime();
+            const releaseIdleCount = Math.max(0, poolSize - activeQueries);
+            logDbPoolRelease({
+               poolSize,
+               idleCount: releaseIdleCount,
+               heldForMs,
+            });
+
             // Log if wait time exceeds thresholds
             if (waitTime > poolErrorThreshold) {
                logger.error(
                   {
                      type: 'database_pool_wait_exceeded',
                      waitTimeMs: waitTime,
-                     poolSize: 10, // Default Prisma pool size
+                     poolSize,
                      queueDepth: activeQueries,
                      endpoint: context?.path,
                      operation,
@@ -141,7 +166,7 @@ export const prisma = basePrisma.$extends({
                   {
                      type: 'database_pool_wait_exceeded',
                      waitTimeMs: waitTime,
-                     poolSize: 10, // Default Prisma pool size
+                     poolSize,
                      queueDepth: activeQueries,
                      endpoint: context?.path,
                      operation,