Add a container health check that tests the database, uploads and background jobs, and deploy on healthy (#509)

* Add a container health check that tests the database, uploads and background jobs, and deploy on healthy

* Reuse one health query while the database hangs, require search permission on uploads, and accept running jobs on an external e2e server

.github/workflows/deploy-demo.yml

@@ -163,17 +163,20 @@ jobs:
 
       - name: Health check
         run: |
-          echo "Waiting for demo container to be ready..."
-          for i in $(seq 1 12); do
-            STATUS=$(docker inspect --format='{{.State.Status}}' torqvoice-app-demo 2>/dev/null || echo "not found")
-            if [ "$STATUS" = "running" ]; then
+          echo "Waiting for the demo container to report healthy..."
+          # Healthy is the image's own HEALTHCHECK passing: database, uploads and
+          # background jobs (see the Dockerfile). An image from before it has no
+          # health status, and then running is all there is to wait for.
+          for i in $(seq 1 36); do
+            STATUS=$(docker inspect --format='{{if .State.Health}}{{.State.Health.Status}}{{else}}{{.State.Status}}{{end}}' torqvoice-app-demo 2>/dev/null || echo "not found")
+            if [ "$STATUS" = "healthy" ] || [ "$STATUS" = "running" ]; then
               echo "Container is running!"
               exit 0
             fi
             echo "Status: $STATUS, retrying in 5s..."
             sleep 5
           done
-          echo "::error::Container failed to start"
+          echo "::error::Container did not become healthy"
           docker logs torqvoice-app-demo --tail 50
           exit 1
 

.github/workflows/deploy-prod.yml

@@ -260,17 +260,20 @@ jobs:
 
       - name: Health check
         run: |
-          echo "Waiting for prod container to be ready..."
-          for i in $(seq 1 12); do
-            STATUS=$(docker inspect --format='{{.State.Status}}' torqvoice-app 2>/dev/null || echo "not found")
-            if [ "$STATUS" = "running" ]; then
+          echo "Waiting for the prod container to report healthy..."
+          # Healthy is the image's own HEALTHCHECK passing: database, uploads and
+          # background jobs (see the Dockerfile). An image from before it has no
+          # health status, and then running is all there is to wait for.
+          for i in $(seq 1 36); do
+            STATUS=$(docker inspect --format='{{if .State.Health}}{{.State.Health.Status}}{{else}}{{.State.Status}}{{end}}' torqvoice-app 2>/dev/null || echo "not found")
+            if [ "$STATUS" = "healthy" ] || [ "$STATUS" = "running" ]; then
               echo "Deployed ${{ steps.tag.outputs.value }}."
               exit 0
             fi
             echo "Status: $STATUS, retrying in 5s..."
             sleep 5
           done
-          echo "::error::Container failed to start"
+          echo "::error::Container did not become healthy"
           docker logs torqvoice-app --tail 50
           exit 1
 

.github/workflows/deploy-staging.yml

@@ -245,17 +245,20 @@ jobs:
 
       - name: Health check
         run: |
-          echo "Waiting for staging container to be ready..."
-          for i in $(seq 1 12); do
-            STATUS=$(docker inspect --format='{{.State.Status}}' torqvoice-app-staging 2>/dev/null || echo "not found")
-            if [ "$STATUS" = "running" ]; then
+          echo "Waiting for the staging container to report healthy..."
+          # Healthy is the image's own HEALTHCHECK passing: database, uploads and
+          # background jobs (see the Dockerfile). An image from before it has no
+          # health status, and then running is all there is to wait for.
+          for i in $(seq 1 36); do
+            STATUS=$(docker inspect --format='{{if .State.Health}}{{.State.Health.Status}}{{else}}{{.State.Status}}{{end}}' torqvoice-app-staging 2>/dev/null || echo "not found")
+            if [ "$STATUS" = "healthy" ] || [ "$STATUS" = "running" ]; then
               echo "Container is running!"
               exit 0
             fi
             echo "Status: $STATUS, retrying in 5s..."
             sleep 5
           done
-          echo "::error::Container failed to start"
+          echo "::error::Container did not become healthy"
           docker logs torqvoice-app-staging --tail 50
           exit 1
 

.github/workflows/rollback-cloud.yml

@@ -117,16 +117,19 @@ jobs:
 
       - name: Health check
         run: |
-          echo "Waiting for prod container to be ready..."
-          for i in $(seq 1 12); do
-            STATUS=$(docker inspect --format='{{.State.Status}}' torqvoice-app 2>/dev/null || echo "not found")
-            if [ "$STATUS" = "running" ]; then
+          echo "Waiting for the prod container to report healthy..."
+          # Healthy is the image's own HEALTHCHECK passing: database, uploads and
+          # background jobs (see the Dockerfile). An image from before it has no
+          # health status, and then running is all there is to wait for.
+          for i in $(seq 1 36); do
+            STATUS=$(docker inspect --format='{{if .State.Health}}{{.State.Health.Status}}{{else}}{{.State.Status}}{{end}}' torqvoice-app 2>/dev/null || echo "not found")
+            if [ "$STATUS" = "healthy" ] || [ "$STATUS" = "running" ]; then
               echo "Rolled back to ${{ inputs.tag }}."
               exit 0
             fi
             echo "Status: $STATUS, retrying in 5s..."
             sleep 5
           done
-          echo "::error::Container failed to start after rollback"
+          echo "::error::Container did not become healthy after rollback"
           docker logs torqvoice-app --tail 50
           exit 1

.github/workflows/rollback-staging.yml

@@ -110,16 +110,19 @@ jobs:
 
       - name: Health check
         run: |
-          echo "Waiting for staging container to be ready..."
-          for i in $(seq 1 12); do
-            STATUS=$(docker inspect --format='{{.State.Status}}' torqvoice-app-staging 2>/dev/null || echo "not found")
-            if [ "$STATUS" = "running" ]; then
+          echo "Waiting for the staging container to report healthy..."
+          # Healthy is the image's own HEALTHCHECK passing: database, uploads and
+          # background jobs (see the Dockerfile). An image from before it has no
+          # health status, and then running is all there is to wait for.
+          for i in $(seq 1 36); do
+            STATUS=$(docker inspect --format='{{if .State.Health}}{{.State.Health.Status}}{{else}}{{.State.Status}}{{end}}' torqvoice-app-staging 2>/dev/null || echo "not found")
+            if [ "$STATUS" = "healthy" ] || [ "$STATUS" = "running" ]; then
               echo "Rolled back to ${{ inputs.tag }}."
               exit 0
             fi
             echo "Status: $STATUS, retrying in 5s..."
             sleep 5
           done
-          echo "::error::Container failed to start after rollback"
+          echo "::error::Container did not become healthy after rollback"
           docker logs torqvoice-app-staging --tail 50
           exit 1

Dockerfile

@@ -147,5 +147,13 @@ EXPOSE 3000
 ENV PORT=3000
 ENV HOSTNAME="0.0.0.0"
 
+# Healthy means the server can do its job: the database answers within three
+# seconds, uploads can be written and the background jobs are still firing
+# (src/lib/health.ts). The deploy workflows wait for it. The start period
+# covers the migrations init-db.sh runs before the server is up. busybox wget
+# exits 1 on a 503, and -Y off keeps a proxy set for the app out of the probe.
+HEALTHCHECK --interval=15s --timeout=5s --start-period=60s --retries=3 \
+    CMD wget -q -Y off -T 4 -O /dev/null "http://127.0.0.1:${PORT:-3000}/api/v1/health" || exit 1
+
 ENTRYPOINT ["./init-db.sh"]
 CMD ["node", "server.js"]

e2e/specs/smoke/app.spec.ts

@@ -41,4 +41,20 @@ test.describe('smoke', () => {
     expect(body.data?.api).toBe('v1')
     expect(body.data?.minAppVersion).toMatch(/^\d+\.\d+\.\d+$/)
   })
+
+  test('the container health check answers healthy', async ({ request }) => {
+    // Docker and the deploy workflows decide on this answer. The server the
+    // suite starts runs with DISABLE_BACKGROUND_JOBS=1, so "disabled" there
+    // also proves the route sees what instrumentation recorded, which only a
+    // real build shows. A server it is pointed at with E2E_BASE_URL may be
+    // running its jobs, and then "ok" is the healthy answer too.
+    const jobs = process.env.E2E_BASE_URL ? ['ok', 'disabled'] : ['disabled']
+    const response = await request.get('/api/v1/health')
+    expect(response.status()).toBe(200)
+    const body = (await response.json()) as { status: string; checks: Record<string, string> }
+    expect(body.status).toBe('ok')
+    expect(body.checks.database).toBe('ok')
+    expect(body.checks.storage).toBe('ok')
+    expect(jobs).toContain(body.checks.jobs)
+  })
 })

src/__tests__/api/health.test.ts

@@ -0,0 +1,177 @@
+/**
+ * @vitest-environment node
+ *
+ * The health route the container's HEALTHCHECK and uptime monitors call. A
+ * 200 has to mean the app can do its job: the database answers in time,
+ * uploads can be written and the background jobs are still firing. Anything
+ * else is a 503 that names what failed.
+ */
+import { chmod, mkdir, mkdtemp, rm } from 'node:fs/promises'
+import { tmpdir } from 'node:os'
+import path from 'node:path'
+import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
+
+const state = vi.hoisted(() => ({ uploads: '', queryRaw: vi.fn() }))
+
+vi.mock('@/lib/db', () => ({
+  db: { $queryRaw: (...args: unknown[]) => state.queryRaw(...args) },
+}))
+vi.mock('@/lib/upload-root', () => ({ uploadsRoot: () => state.uploads }))
+
+import { markBackgroundJobsDisabled, recordBackgroundJobsBeat } from '@/lib/background-jobs'
+import { startHeartbeat } from '@/lib/cron/heartbeat'
+import { DATABASE_TIMEOUT_MS, JOBS_STALE_MS } from '@/lib/health'
+
+type Body = { status: string; checks: Record<string, string> }
+
+/** A fresh copy of the route each test, as a newly started server has. */
+async function probe() {
+  const { GET } = await import('@/app/api/v1/health/route')
+  const response = await GET()
+  return {
+    status: response.status,
+    headers: response.headers,
+    body: (await response.json()) as Body,
+  }
+}
+
+let tmp = ''
+
+beforeEach(async () => {
+  vi.resetModules()
+  // What instrumentation leaves behind lives on globalThis; a test starts with none.
+  delete (globalThis as { __torqvoiceBackgroundJobs?: unknown }).__torqvoiceBackgroundJobs
+  state.queryRaw.mockReset().mockResolvedValue([{ ok: 1 }])
+  tmp = await mkdtemp(path.join(tmpdir(), 'tv-health-'))
+  state.uploads = path.join(tmp, 'uploads')
+  await mkdir(state.uploads)
+  recordBackgroundJobsBeat()
+  vi.spyOn(console, 'error').mockImplementation(() => undefined)
+  vi.spyOn(console, 'warn').mockImplementation(() => undefined)
+})
+
+afterEach(async () => {
+  vi.useRealTimers()
+  vi.restoreAllMocks()
+  await chmod(state.uploads, 0o700).catch(() => undefined)
+  await rm(tmp, { recursive: true, force: true })
+})
+
+describe('GET /api/v1/health', () => {
+  it('answers 200 when everything works, and is never cached', async () => {
+    const { status, headers, body } = await probe()
+    expect(status).toBe(200)
+    expect(body).toEqual({ status: 'ok', checks: { database: 'ok', storage: 'ok', jobs: 'ok' } })
+    expect(headers.get('cache-control')).toBe('no-store')
+  })
+
+  it('answers 503 when the database refuses the connection', async () => {
+    state.queryRaw.mockRejectedValue(new Error('ECONNREFUSED'))
+    const { status, body } = await probe()
+    expect(status).toBe(503)
+    expect(body.status).toBe('error')
+    expect(body.checks.database).toBe('unreachable')
+  })
+
+  it('answers 503 within the time limit when the database hangs', async () => {
+    vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] })
+    state.queryRaw.mockReturnValue(new Promise(() => undefined))
+    const pending = probe()
+    await vi.advanceTimersByTimeAsync(DATABASE_TIMEOUT_MS)
+    const { status, body } = await pending
+    expect(status).toBe(503)
+    expect(body.checks.database).toBe('timeout')
+  })
+
+  it('asks a hung database once however many probes come in, and recovers when it answers', async () => {
+    // Each query that never comes back holds one of the app's ten pooled
+    // connections, so a probe every fifteen seconds must not open a new one.
+    vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] })
+    let answer: (value: unknown) => void = () => undefined
+    state.queryRaw.mockReturnValue(new Promise((resolve) => (answer = resolve)))
+
+    for (let i = 0; i < 3; i++) {
+      const pending = probe()
+      await vi.advanceTimersByTimeAsync(DATABASE_TIMEOUT_MS)
+      expect((await pending).body.checks.database).toBe('timeout')
+    }
+    expect(state.queryRaw).toHaveBeenCalledTimes(1)
+
+    answer([{ ok: 1 }])
+    state.queryRaw.mockResolvedValue([{ ok: 1 }])
+    const { status, body } = await probe()
+    expect(status).toBe(200)
+    expect(body.checks.database).toBe('ok')
+  })
+
+  it('is healthy before the first upload has made the uploads folder', async () => {
+    state.uploads = path.join(tmp, 'data', 'uploads')
+    const { status, body } = await probe()
+    expect(status).toBe(200)
+    expect(body.checks.storage).toBe('ok')
+  })
+
+  it.skipIf(process.getuid?.() === 0)('answers 503 when uploads cannot be written', async () => {
+    await chmod(state.uploads, 0o500)
+    const { status, body } = await probe()
+    expect(status).toBe(503)
+    expect(body.checks.storage).toBe('not_writable')
+  })
+
+  it.skipIf(process.getuid?.() === 0)(
+    'answers 503 when the uploads folder is writable but cannot be entered',
+    async () => {
+      // Write without search (execute) permission: making a workshop's folder
+      // inside it fails with EACCES, so uploads are broken.
+      await chmod(state.uploads, 0o600)
+      const { status, body } = await probe()
+      expect(status).toBe(503)
+      expect(body.checks.storage).toBe('not_writable')
+    }
+  )
+
+  it('answers 503 when the background jobs never started', async () => {
+    delete (globalThis as { __torqvoiceBackgroundJobs?: unknown }).__torqvoiceBackgroundJobs
+    const { status, body } = await probe()
+    expect(status).toBe(503)
+    expect(body.checks.jobs).toBe('not_started')
+  })
+
+  it('answers 503 when the background jobs have stopped beating', async () => {
+    recordBackgroundJobsBeat(Date.now() - JOBS_STALE_MS - 1000)
+    const { status, body } = await probe()
+    expect(status).toBe(503)
+    expect(body.checks.jobs).toBe('stalled')
+  })
+
+  it('stays healthy with the background jobs switched off on purpose', async () => {
+    markBackgroundJobsDisabled()
+    const { status, body } = await probe()
+    expect(status).toBe(200)
+    expect(body.checks.jobs).toBe('disabled')
+  })
+
+  it('keeps reporting healthy while the heartbeat runs, long past the stale limit', async () => {
+    vi.useFakeTimers()
+    const job = startHeartbeat()
+    await vi.advanceTimersByTimeAsync(JOBS_STALE_MS * 2)
+    const { status, body } = await probe()
+    job.stop()
+    expect(status).toBe(200)
+    expect(body.checks.jobs).toBe('ok')
+  })
+
+  it('logs one line when it starts failing and one when it recovers', async () => {
+    state.queryRaw.mockRejectedValue(new Error('ECONNREFUSED'))
+    await probe()
+    await probe()
+    state.queryRaw.mockResolvedValue([{ ok: 1 }])
+    await probe()
+    await probe()
+
+    expect(console.error).toHaveBeenCalledTimes(1)
+    expect(console.error).toHaveBeenCalledWith('[health] failing: database=unreachable')
+    expect(console.warn).toHaveBeenCalledTimes(1)
+    expect(console.warn).toHaveBeenCalledWith('[health] passing again')
+  })
+})

src/app/api/v1/health/route.ts

@@ -1,11 +1,18 @@
 import { NextResponse } from 'next/server'
-import { db } from '@/lib/db'
+import { checkHealth } from '@/lib/health'
 
+export const dynamic = 'force-dynamic'
+
+/**
+ * The container's health check and any uptime monitor: 200 when the
+ * database answers, uploads can be written and the background jobs are
+ * running, 503 otherwise. Public, so it names the check that failed and
+ * nothing more.
+ */
 export async function GET() {
-  try {
-    await db.$queryRaw`SELECT 1`
-    return NextResponse.json({ status: 'ok' })
-  } catch {
-    return NextResponse.json({ status: 'error' }, { status: 503 })
-  }
+  const { healthy, checks } = await checkHealth()
+  return NextResponse.json(
+    { status: healthy ? 'ok' : 'error', checks },
+    { status: healthy ? 200 : 503, headers: { 'Cache-Control': 'no-store' } }
+  )
 }

src/cronTasks.ts

@@ -12,3 +12,4 @@ export { checkDueReminders } from './lib/cron/reminder-alerts'
 export { processScheduledMessages } from './lib/cron/scheduled-messages'
 export { processIntegrationJobs, cleanupIntegrationLogs } from './lib/cron/integration-jobs'
 export { processBackupRuns } from './lib/cron/backup-runs'
+export { startHeartbeat } from './lib/cron/heartbeat'

src/instrumentation.ts

@@ -13,6 +13,8 @@ export async function register() {
     if (process.env.DISABLE_BACKGROUND_JOBS === '1') {
       const { warnAboutAppUrl } = await import('./lib/auth-origin-hint')
       warnAboutAppUrl()
+      const { markBackgroundJobsDisabled } = await import('./lib/background-jobs')
+      markBackgroundJobsDisabled()
       console.warn('[cron] DISABLE_BACKGROUND_JOBS=1, no scheduled work started')
       return
     }
@@ -33,6 +35,7 @@ export async function register() {
       processIntegrationJobs,
       cleanupIntegrationLogs,
       processBackupRuns,
+      startHeartbeat,
     } = await import('./cronTasks')
     const { warnAboutAppUrl } = await import('./lib/auth-origin-hint')
     warnAboutAppUrl()
@@ -52,5 +55,7 @@ export async function register() {
     processIntegrationJobs()
     cleanupIntegrationLogs()
     processBackupRuns()
+    // Last, so the health check only sees beats once everything above started.
+    startHeartbeat()
   }
 }

src/lib/background-jobs.ts

@@ -0,0 +1,24 @@
+/**
+ * Whether the scheduled work instrumentation.ts starts is still running, for
+ * the health check. Kept on globalThis because instrumentation and the route
+ * handlers are bundled apart and can each load their own copy of this module;
+ * the process is the one thing they share.
+ */
+type BackgroundJobsState = { disabled: true } | { disabled: false; lastBeatAt: number }
+
+const store = globalThis as unknown as { __torqvoiceBackgroundJobs?: BackgroundJobsState }
+
+/** `DISABLE_BACKGROUND_JOBS=1`: nothing was meant to start. */
+export function markBackgroundJobsDisabled() {
+  store.__torqvoiceBackgroundJobs = { disabled: true }
+}
+
+/** The scheduler fired. Called once at start and then every minute. */
+export function recordBackgroundJobsBeat(now = Date.now()) {
+  store.__torqvoiceBackgroundJobs = { disabled: false, lastBeatAt: now }
+}
+
+/** Undefined until instrumentation has run to the end. */
+export function backgroundJobsState(): BackgroundJobsState | undefined {
+  return store.__torqvoiceBackgroundJobs
+}

src/lib/cron/heartbeat.ts

@@ -0,0 +1,14 @@
+import { CronJob } from 'cron'
+import { recordBackgroundJobsBeat } from '@/lib/background-jobs'
+
+/**
+ * A beat every minute on the same scheduler as the real jobs, so the health
+ * check can tell they are still firing. Started after every other job, so a
+ * start that failed part way never beats at all.
+ */
+export function startHeartbeat() {
+  recordBackgroundJobsBeat()
+  const job = new CronJob('* * * * *', () => recordBackgroundJobsBeat())
+  job.start()
+  return job
+}

src/lib/health.ts

@@ -0,0 +1,109 @@
+import { constants } from 'node:fs'
+import { access } from 'node:fs/promises'
+import path from 'node:path'
+import { backgroundJobsState } from '@/lib/background-jobs'
+import { db } from '@/lib/db'
+import { uploadsRoot } from '@/lib/upload-root'
+
+/**
+ * What the container's health check asks (HEALTHCHECK in the Dockerfile):
+ * can this server do its job, not only answer. Each check names what failed,
+ * so `docker logs` and an uptime monitor say why, not just that.
+ */
+
+/** Under Docker's own 5 s timeout, so a slow database is reported as such. */
+export const DATABASE_TIMEOUT_MS = 3000
+/** Three missed beats of the every-minute heartbeat. */
+export const JOBS_STALE_MS = 3 * 60 * 1000
+
+export type HealthChecks = {
+  database: 'ok' | 'timeout' | 'unreachable'
+  storage: 'ok' | 'not_writable'
+  jobs: 'ok' | 'disabled' | 'not_started' | 'stalled'
+}
+
+export type HealthReport = { healthy: boolean; checks: HealthChecks }
+
+/**
+ * The query a probe started and nobody has heard back from. A probe that gives
+ * up after three seconds cannot cancel it, and it keeps one of the app's ten
+ * pooled connections until the database answers. The next probe waits on that
+ * same query instead of taking another connection, so a database that stops
+ * answering costs the health check one connection however long it lasts.
+ */
+let pendingQuery: Promise<unknown> | undefined
+
+async function checkDatabase(): Promise<HealthChecks['database']> {
+  if (!pendingQuery) {
+    const query: Promise<unknown> = db.$queryRaw`SELECT 1`.finally(() => {
+      if (pendingQuery === query) pendingQuery = undefined
+    })
+    pendingQuery = query
+  }
+  const query = pendingQuery
+  let timer: ReturnType<typeof setTimeout> | undefined
+  const timeout = new Promise<'timeout'>((resolve) => {
+    timer = setTimeout(() => resolve('timeout'), DATABASE_TIMEOUT_MS)
+  })
+  try {
+    return await Promise.race([query.then(() => 'ok' as const), timeout])
+  } catch {
+    return 'unreachable'
+  } finally {
+    clearTimeout(timer)
+  }
+}
+
+/**
+ * The uploads folder is made on the first upload, so until it exists the
+ * nearest folder above it has to take it. Making a folder in a folder takes
+ * both write and search (execute) permission on it. A volume owned by the
+ * wrong user is the usual reason this fails: the app starts and every photo is
+ * refused.
+ */
+async function checkStorage(): Promise<HealthChecks['storage']> {
+  let dir = uploadsRoot()
+  for (;;) {
+    try {
+      await access(dir, constants.W_OK | constants.X_OK)
+      return 'ok'
+    } catch (error) {
+      const parent = path.dirname(dir)
+      if ((error as NodeJS.ErrnoException).code !== 'ENOENT' || parent === dir) {
+        return 'not_writable'
+      }
+      dir = parent
+    }
+  }
+}
+
+/** Reminders, scheduled messages and backups all run on these timers. */
+function checkJobs(now: number): HealthChecks['jobs'] {
+  const state = backgroundJobsState()
+  if (!state) return 'not_started'
+  if (state.disabled) return 'disabled'
+  return now - state.lastBeatAt <= JOBS_STALE_MS ? 'ok' : 'stalled'
+}
+
+let lastHealthy: boolean | undefined
+
+export async function checkHealth(now = Date.now()): Promise<HealthReport> {
+  const [database, storage] = await Promise.all([checkDatabase(), checkStorage()])
+  const jobs = checkJobs(now)
+  const checks: HealthChecks = { database, storage, jobs }
+  const healthy = database === 'ok' && storage === 'ok' && (jobs === 'ok' || jobs === 'disabled')
+
+  // One line when the answer changes, not one per probe, so an outage leaves
+  // its start and end in the log without filling it.
+  if (healthy !== lastHealthy) {
+    const failing = Object.entries(checks)
+      .filter(([, value]) => value !== 'ok' && value !== 'disabled')
+      .map(([name, value]) => `${name}=${value}`)
+      .join(' ')
+    if (!healthy) console.error(`[health] failing: ${failing}`)
+    else if (lastHealthy === false) console.warn('[health] passing again')
+    lastHealthy = healthy
+  }
+
+  return { healthy, checks }
+}