Add diagnostic logging to Discord bot advisory lock for production debugging

brandonkachen · brandonkachen · commit eba49bc05a36 · 2026-01-27T11:04:45.000-08:00
diff --git a/packages/internal/src/db/advisory-lock.ts b/packages/internal/src/db/advisory-lock.ts
@@ -14,6 +14,21 @@ export type AdvisoryLockId = (typeof ADVISORY_LOCK_IDS)[keyof typeof ADVISORY_LO
 
 const HEALTH_CHECK_INTERVAL_MS = 10_000 // 10 seconds
 
+// Diagnostic logging helper with timestamp and process info
+function logLock(level: 'info' | 'error' | 'warn', message: string, data?: Record<string, unknown>): void {
+  const timestamp = new Date().toISOString()
+  const pid = process.pid
+  const prefix = `[${timestamp}] [PID:${pid}] [advisory-lock]`
+  const dataStr = data ? ` ${JSON.stringify(data)}` : ''
+  if (level === 'error') {
+    console.error(`${prefix} ${message}${dataStr}`)
+  } else if (level === 'warn') {
+    console.warn(`${prefix} ${message}${dataStr}`)
+  } else {
+    console.log(`${prefix} ${message}${dataStr}`)
+  }
+}
+
 export interface LockHandle {
   /** Register a callback to be called if the lock is lost (connection dies) */
   onLost(callback: () => void): void
@@ -33,28 +48,38 @@ export async function tryAcquireAdvisoryLock(lockId: AdvisoryLockId): Promise<{
   acquired: boolean
   handle: LockHandle | null
 }> {
+  logLock('info', 'Attempting to acquire advisory lock', { lockId })
+  
   const connection = postgres(env.DATABASE_URL, {
     max: 1,
     idle_timeout: 0,
     connect_timeout: 10,
   })
 
   try {
+    logLock('info', 'Database connection established, attempting pg_try_advisory_lock')
     const result = await connection`SELECT pg_try_advisory_lock(${lockId}) as acquired`
     const acquired = result[0]?.acquired === true
 
+    logLock('info', 'Lock acquisition result', { acquired, lockId })
+
     if (!acquired) {
+      logLock('info', 'Lock not acquired (held by another process), closing connection')
       await connection.end()
       return { acquired: false, handle: null }
     }
 
+    logLock('info', 'Lock acquired successfully, setting up lock handle', { lockId })
+
     // Create the lock handle
     let lostCallback: (() => void) | null = null
     let isReleased = false
     let healthCheckTimer: ReturnType<typeof setInterval> | null = null
+    let healthCheckCount = 0
 
     const triggerLost = () => {
       if (isReleased) return
+      logLock('warn', 'Lock lost detected, triggering lost callback', { lockId, healthCheckCount })
       if (healthCheckTimer) {
         clearInterval(healthCheckTimer)
         healthCheckTimer = null
@@ -70,6 +95,7 @@ export async function tryAcquireAdvisoryLock(lockId: AdvisoryLockId): Promise<{
     // Start health check interval - verify we still hold the lock, not just connection liveness
     healthCheckTimer = setInterval(async () => {
       if (isReleased) return
+      healthCheckCount++
       try {
         // Query pg_locks to verify we still hold this specific advisory lock
         // This catches cases where the lock was lost but connection stayed alive
@@ -85,11 +111,14 @@ export async function tryAcquireAdvisoryLock(lockId: AdvisoryLockId): Promise<{
         `
         const stillHeld = result[0]?.held === true
         if (!stillHeld) {
-          console.error('Advisory lock health check failed - lock no longer held')
+          logLock('error', 'Advisory lock health check failed - lock no longer held', { lockId, healthCheckCount })
           triggerLost()
+        } else if (healthCheckCount % 6 === 0) {
+          // Log every minute (6 * 10s) to confirm we're still running
+          logLock('info', 'Advisory lock health check passed', { lockId, healthCheckCount, uptimeMinutes: healthCheckCount / 6 })
         }
-      } catch {
-        console.error('Advisory lock health check failed - connection lost')
+      } catch (error) {
+        logLock('error', 'Advisory lock health check failed - connection lost', { lockId, healthCheckCount, error: String(error) })
         triggerLost()
       }
     }, HEALTH_CHECK_INTERVAL_MS)
@@ -99,22 +128,36 @@ export async function tryAcquireAdvisoryLock(lockId: AdvisoryLockId): Promise<{
         lostCallback = callback
       },
       async release() {
-        if (isReleased) return
+        if (isReleased) {
+          logLock('info', 'Lock release called but already released', { lockId })
+          return
+        }
+        logLock('info', 'Releasing advisory lock', { lockId, healthCheckCount })
         isReleased = true
         if (healthCheckTimer) {
           clearInterval(healthCheckTimer)
           healthCheckTimer = null
         }
+        try {
+          // Explicitly release the advisory lock before closing connection
+          logLock('info', 'Calling pg_advisory_unlock', { lockId })
+          await connection`SELECT pg_advisory_unlock(${lockId})`
+          logLock('info', 'Advisory lock released via pg_advisory_unlock', { lockId })
+        } catch (error) {
+          logLock('error', 'Error during pg_advisory_unlock (continuing to close connection)', { lockId, error: String(error) })
+        }
         try {
           await connection.end()
+          logLock('info', 'Database connection closed', { lockId })
         } catch (error) {
-          console.error('Error releasing advisory lock:', error)
+          logLock('error', 'Error closing database connection', { lockId, error: String(error) })
         }
       },
     }
 
     return { acquired: true, handle }
   } catch (error) {
+    logLock('error', 'Error during lock acquisition', { lockId, error: String(error) })
     await connection.end().catch(() => {})
     throw error
   }
diff --git a/web/scripts/discord/index.ts b/web/scripts/discord/index.ts
@@ -2,6 +2,7 @@ import {
   ADVISORY_LOCK_IDS,
   tryAcquireAdvisoryLock,
 } from '@codebuff/internal/db'
+import os from 'os'
 
 import { startDiscordBot } from '../../src/discord/client'
 
@@ -15,45 +16,83 @@ let lockHandle: LockHandle | null = null
 let discordClient: Client | null = null
 let isShuttingDown = false
 
+// Diagnostic logging helper with timestamp and process info
+function log(level: 'info' | 'error' | 'warn', message: string, data?: Record<string, unknown>): void {
+  const timestamp = new Date().toISOString()
+  const pid = process.pid
+  const hostname = os.hostname()
+  const prefix = `[${timestamp}] [PID:${pid}] [host:${hostname}] [discord-bot]`
+  const dataStr = data ? ` ${JSON.stringify(data)}` : ''
+  if (level === 'error') {
+    console.error(`${prefix} ${message}${dataStr}`)
+  } else if (level === 'warn') {
+    console.warn(`${prefix} ${message}${dataStr}`)
+  } else {
+    console.log(`${prefix} ${message}${dataStr}`)
+  }
+}
+
 function sleep(ms: number): Promise<void> {
   return new Promise((resolve) => setTimeout(resolve, ms))
 }
 
-async function shutdown(exitCode: number = 0) {
-  if (isShuttingDown) return
+async function shutdown(exitCode: number = 0): Promise<void> {
+  if (isShuttingDown) {
+    log('warn', 'Shutdown already in progress, ignoring duplicate call')
+    return
+  }
   isShuttingDown = true
 
-  console.log('Shutting down Discord bot...')
+  log('info', 'Shutting down Discord bot...', { exitCode })
 
   if (discordClient) {
     try {
+      log('info', 'Destroying Discord client...')
       discordClient.destroy()
+      log('info', 'Discord client destroyed')
     } catch (error) {
-      console.error('Error destroying Discord client:', error)
+      log('error', 'Error destroying Discord client', { error: String(error) })
     }
     discordClient = null
   }
 
   if (lockHandle) {
+    log('info', 'Releasing advisory lock...')
     await lockHandle.release()
+    log('info', 'Advisory lock released')
     lockHandle = null
   }
 
+  log('info', 'Shutdown complete, exiting', { exitCode })
   process.exit(exitCode)
 }
 
 async function main() {
-  process.on('SIGTERM', () => shutdown(0))
-  process.on('SIGINT', () => shutdown(0))
+  const startTime = Date.now()
+  log('info', 'Discord bot script starting', {
+    pid: process.pid,
+    hostname: os.hostname(),
+    nodeVersion: process.version,
+    platform: process.platform,
+  })
+
+  // Handle SIGTERM/SIGINT - shutdown() handles deduplication internally
+  process.on('SIGTERM', () => {
+    log('info', 'Received SIGTERM signal')
+    void shutdown(0)
+  })
+  process.on('SIGINT', () => {
+    log('info', 'Received SIGINT signal')
+    void shutdown(0)
+  })
 
   let consecutiveErrors = 0
   let attemptCount = 0
 
   while (!isShuttingDown) {
     attemptCount++
-    console.log(
-      `Attempting to acquire Discord bot lock (attempt ${attemptCount})...`,
-    )
+    const elapsedSec = Math.round((Date.now() - startTime) / 1000)
+    log('info', `Attempting to acquire Discord bot lock`, { attemptCount, elapsedSeconds: elapsedSec })
 
     let acquired = false
     let handle: LockHandle | null = null
@@ -63,75 +102,83 @@ async function main() {
       acquired = result.acquired
       handle = result.handle
       consecutiveErrors = 0 // Reset on successful DB connection
+      log('info', 'Lock acquisition attempt completed', { acquired, consecutiveErrors })
     } catch (error) {
       consecutiveErrors++
-      console.error(
-        `Error acquiring lock (${consecutiveErrors}/${MAX_CONSECUTIVE_ERRORS}):`,
-        error,
-      )
+      log('error', `Error acquiring lock`, {
+        consecutiveErrors,
+        maxErrors: MAX_CONSECUTIVE_ERRORS,
+        error: String(error),
+      })
 
       if (consecutiveErrors >= MAX_CONSECUTIVE_ERRORS) {
-        console.error('Too many consecutive errors, exiting...')
+        log('error', 'Too many consecutive errors, exiting...')
         await shutdown(1)
         return
       }
 
+      log('info', `Will retry in ${LOCK_RETRY_INTERVAL_MS / 1000} seconds...`)
       await sleep(LOCK_RETRY_INTERVAL_MS)
       continue
     }
 
     if (!acquired || !handle) {
-      console.log(
-        `Another instance is already running the Discord bot. Retrying in ${LOCK_RETRY_INTERVAL_MS / 1000} seconds...`,
-      )
+      log('info', `Another instance is already running the Discord bot`, {
+        retryInSeconds: LOCK_RETRY_INTERVAL_MS / 1000,
+      })
       await sleep(LOCK_RETRY_INTERVAL_MS)
       continue
     }
 
     lockHandle = handle
-    console.log('Lock acquired. Starting Discord bot...')
+    log('info', 'Lock acquired! Starting Discord bot...')
 
     // Set up lock loss handler BEFORE starting the bot
     handle.onLost(() => {
-      console.error('Advisory lock lost! Another instance may have taken over.')
+      log('error', 'Advisory lock lost! Another instance may have taken over.')
       shutdown(1)
     })
 
     try {
       // Wait for bot to be ready - this is critical!
       // If login fails, we release the lock so another instance can try
+      log('info', 'Calling startDiscordBot()...')
       discordClient = await startDiscordBot()
-      console.log('Discord bot is ready and running.')
+      log('info', 'Discord bot is ready and running!', {
+        uptime: Math.round((Date.now() - startTime) / 1000),
+      })
 
       // Set up error handler for runtime errors
       discordClient.on('error', (error) => {
-        console.error('Discord client error:', error)
+        log('error', 'Discord client error', { error: String(error) })
       })
 
       // Handle disconnection
       discordClient.on('disconnect', () => {
-        console.error('Discord client disconnected')
+        log('error', 'Discord client disconnected')
       })
 
       // Bot is running, keep the process alive
+      // Note: heartbeat logging is handled by advisory-lock health checks
       return
     } catch (error) {
-      console.error('Failed to start Discord bot:', error)
+      log('error', 'Failed to start Discord bot', { error: String(error) })
 
       // Release the lock so another instance can try
+      log('info', 'Releasing lock after failed bot start...')
       await handle.release()
       lockHandle = null
       discordClient = null
 
       // Continue polling - maybe another instance will have better luck,
       // or maybe the issue is transient (Discord outage)
-      console.log(`Will retry in ${LOCK_RETRY_INTERVAL_MS / 1000} seconds...`)
+      log('info', `Will retry in ${LOCK_RETRY_INTERVAL_MS / 1000} seconds...`)
       await sleep(LOCK_RETRY_INTERVAL_MS)
     }
   }
 }
 
 main().catch(async (error) => {
-  console.error('Fatal error in Discord bot script:', error)
+  log('error', 'Fatal error in Discord bot script', { error: String(error), stack: (error as Error).stack })
   await shutdown(1)
 })
