Bilko Demo Event-Loop Freeze — Root Cause, Fix & Hardening (2026-06-08, MC #103134)
Bilko Demo Event-Loop Freeze — Root Cause, Fix & Hardening (2026-06-08, MC #103134)
1. Incident Summary
Date: 2026-06-08
Service: bilko-api-demo (Cloud Run, europe-north1, tribal-sign-487920-k0)
Live revision at incident: bilko-api-demo-00139-b26 (git sha c8dfb6c)
MC: #103134 (child of #103132)
Detected by: CEO (Alem Basic) — no automated alerts existed
Symptom: POST /api/v1/auth/login and GET /api/v1/health intermittently returned HTTP 504 with server-side latency of exactly 59.999 s (Cloud Run hard timeout). Observed failure rate: 17–25% of requests. Both endpoints froze simultaneously on both Cloud Run instances. A manual container restart did not fix the issue.
Why restart did not help: The blocking code paths are baked into the deployed image (c8dfb6c). The freeze re-triggers the moment any user navigates to Reports or Billing/Usage, which re-executes the same bare JDBC calls on the Netty event-loop thread.
2. Root Cause — Causal Chain
Source: 5-agent synthesis (petter-synthesis.md) + source-verified app-layer audit (dev-applayer.md) + data/storage audit (devops2-data.md).
2.1 Ktor Netty Thread Pool Exhaustion (Primary)
Ktor runs on Netty. On a 1-vCPU Cloud Run container with no callGroupSize set (main branch pre-fix), Netty defaults to approximately 2 call-handling threads. With containerConcurrency=8, Cloud Run routes up to 8 simultaneous requests into the container, all competing for those 2 threads.
Any route that executes a bare orgTransaction() call — not wrapped in dbQuery{} — runs its JDBC work directly on the Netty call thread, blocking it for the duration of the DB round-trip (10–100 ms typical, up to 30 s if HikariCP must wait for a pool slot). With only 2 call threads and 8 concurrent slots, two simultaneous requests to a bare-orgTransaction route exhaust both call threads. The event loop is frozen.
Confirmed bare orgTransaction sites on main at incident time:
| File | Line(s) | Route |
|---|---|---|
| ReportRoutes.kt | 26 | GET /reports (country lookup) |
| ReportRoutes.kt | 240 | GET /reports/kpo (country pre-check) |
| ReportRoutes.kt | 264 | GET /reports/kpo/export/pdf (country pre-check) |
| ReportRoutes.kt | 285 | GET /reports/kpo/export/xlsx (country pre-check) |
| BillingRoutes.kt | 214 | GET /billing/usage (plan tier + invoice count) |
| MarketRoutes.kt | 2 sites | resolveMarketPlugin call sites |
| ResourceAccessFilter.kt | multiple | Per-request security filter |
| Authentication.kt | impersonation path | Per impersonation request |
2.2 PermissionService.loadFromDb — New RBAC Blocking Call (Critical, Entra cutover)
The Entra External ID cutover (MC #103140) introduced RBAC via requirePermission(), which is called on every authenticated request across all 17 route files. On first call per role (4 roles: owner/admin/accountant/viewer), resolve() calls loadFromDb():
// BEFORE fix — blocking on Netty event-loop thread
private fun loadFromDb(role: String): Set<String> {
return transaction { // bare JDBC on Netty thread
RolePermissionsTable.selectAll()...
}
}This fires on every cold-start / scale-out event for every authenticated route. Without the fix, the Entra cutover would have immediately re-introduced a freeze worse than the original: 4 role cache-misses per instance restart, each running blocking JDBC on the event loop. Source: /tmp/evidence-103134/rebase-on-entra.md.
2.3 HikariCP connectionTimeout=30,000 ms (Secondary Amplifier)
When the Dispatchers.IO pool workers (correctly dispatched DB calls) hit HikariCP pool pressure — 10 connections shared across 8 concurrent slots — a pool-borrow wait can last up to 30 s per request. Two stacked pool-borrow waits = 60 s = Cloud Run hard kill. This amplifier remains even after the bare-orgTransaction calls are fixed; it is addressed separately by reducing connectionTimeout to 5 s (P0.3).
2.4 Why /health Freezes (Not a DB Problem)
HealthRoutes.kt lines 10–21 are confirmed DB-independent (zero blocking calls, pure in-memory response). The health freeze is not because health touches the DB — it is because both Netty call threads are occupied by blocked orgTransaction callers. Health cannot be scheduled. The TCP startup probe continues to pass because the JVM still has port 4001 bound; only HTTP scheduling is stalled.
2.5 Why Login Freezes (Login Is the Victim, Not the Cause)
AuthRoutes.kt line 150 correctly wraps login in dbQuery{}. Login itself is not a blocking caller. Login freezes because it cannot obtain a call thread to execute — both threads are consumed by the bare-orgTransaction routes.
2.6 Tertiary — Absent Server-Side DB Timeouts
No statement_timeout, idle_in_transaction_session_timeout, or lock_timeout on Cloud SQL (confirmed: databaseFlags null). A single slow query (vacuum contention on db-f1-micro, missing index on a growing table) holds a pool connection indefinitely, compounding pool pressure.
2.7 gcsfuse Is Not a Cause of Auth/Health Freezes
gcsfuse GC timestamps do not align with freeze onsets (GC at 06:35:04 UTC, freeze at 06:34:52 and 06:35:43). Login does no file I/O. gcsfuse FUSE blocking I/O affects receipt endpoints only; it is a separate hygiene issue and was also offloaded to Dispatchers.IO in the fix.
3. Fix Applied (MC #103134)
Branch: fix/demo-freeze-on-entra-103134, commit 5252182, rebased on origin/main @ b21b366 (Entra cutover). Merged as PR #279 → main 839ee7f. Source: /tmp/evidence-103134/rebase-on-entra.md.
Code Fixes
| File | Change |
|---|---|
| routes/ReportRoutes.kt (4 sites) | Bare orgTransaction → wrapped in dbQuery{} |
| routes/BillingRoutes.kt (line 214) | Bare orgTransaction in /billing/usage → dbQuery{} |
| routes/MarketRoutes.kt (2 sites) | resolveMarketPlugin call sites → dbQuery{} |
| plugins/ResourceAccessFilter.kt | fetchResourceOwner + logSecurityViolation → suspend + withContext(IO); Thread.sleep → delay |
| plugins/Authentication.kt | Impersonation transaction → withContext(Dispatchers.IO) |
| services/PermissionService.kt (new finding) | loadFromDb() → runBlocking { withContext(Dispatchers.IO) { ... } } — RBAC per-request DB call offloaded |
| services/ReceiptService.kt | readLocalDocument + persistLocalIfEnabled → suspend + withContext(IO) |
| routes/ExpenseRoutes.kt | readLocalDocument moved out of dbQuery{} (now suspend-safe) |
| plugins/Database.kt | connectionTimeout 30,000 → 5,000 ms |
| routes/HealthRoutes.kt | Added GET /api/v1/health/deep — DB-touching endpoint with withTimeout 3 s + Dispatchers.IO + SELECT 1 |
Infrastructure Fixes (cloudbuild-stage.yaml + cloudbuild.yaml)
| Change | Value |
|---|---|
| Memory | 512 Mi → 1 Gi |
| Liveness probe | httpGet /api/v1/health/deep, port 4001, initialDelaySeconds 30, periodSeconds 30, failureThreshold 2, timeoutSeconds 8 |
| Startup probe | httpGet /api/v1/health (was TCP), port 4001, periodSeconds 10, failureThreshold 3, timeoutSeconds 5 |
| containerConcurrency | 80 → 8 (in cloudbuild-demo-api.yaml; applied to stage + demo templates) |
Build and Test Results
./gradlew build -x detekt → BUILD SUCCESSFUL in 12s
Tests: 2561 passed, 1 skipped (EntraLiveCiamTokenWp5Test — stale token, assumeTrue guard), 0 failuresPermissionService Cache Note
The 4-role cache (one entry per role after first load) bounds future DB hits. Pre-warming the cache at JVM startup is recommended as a follow-on polish task (task #7), but is not a blocker for the freeze fix: the IO offload alone prevents the event-loop block on cold misses.
4. Industry-Standard Scorecard
Condensed from petter-synthesis.md §2. Full details in audit reports.
Application Layer
| Component | Assessment | Finding |
|---|---|---|
| Ktor/Netty callGroupSize | DEVIATES (pre-fix) | No callGroupSize set on main. Defaults to ~2 call threads on 1 vCPU. Fix branch sets callGroupSize=32; must be confirmed active in Cloud Run (env var KTOR_CALL_GROUP_SIZE=32 or production application.yaml profile). |
| dbQuery{} discipline | DEVIATES → FIXED | 5 confirmed bare orgTransaction sites + PermissionService.loadFromDb all wrapped in this fix. 97 raw transaction{} calls in repo; remaining ones are safely nested inside outer dbQuery{} or on non-hot paths. |
| Login path (AuthRoutes.kt:150) | STANDARD | Correctly wraps in dbQuery{}. Login was the victim of thread starvation, not a cause. |
| BCrypt dispatcher | DEVIATES (minor) | BCrypt (CPU-bound, 250–400 ms) runs on Dispatchers.IO (I/O-bound). Not the freeze cause but degrades throughput. Move to Dispatchers.Default is a follow-on (P1.3). |
| HikariCP connectionTimeout | DEVIATES → FIXED | 30,000 ms → 5,000 ms. Pool-borrow wait now fails fast with 503 in 5 s. |
| Login 3-transaction pool pressure | DEVIATES | AuthService.login() makes 3 separate orgTransaction{} calls (3 pool borrows per login). Follow-on: consolidate to 1 (P1.1). |
| Server-side RequestTimeout | DEVIATES | No Ktor RequestTimeout plugin. Stuck handlers are killed by Cloud Run at 60 s, not the app at 10 s. Follow-on: P1.5. |
| /health endpoint | STANDARD | DB-independent, correct. Preserved as-is for startup probe. |
| /health/deep endpoint | ADDED | New DB-touching endpoint (SELECT 1 via HikariCP, 3 s internal timeout). Returns 200 {db:up} or 503 {db:down}. |
| gcsfuse (ReceiptService) | DEVIATES → FIXED (hygiene) | Blocking POSIX I/O on FUSE mount offloaded to withContext(IO). Not the auth/health freeze cause, but blocks safe concurrency > 1–8 without this fix. |
Infrastructure Layer
| Component | Assessment | Finding |
|---|---|---|
| containerConcurrency | DEVIATES | 8 with blocking event-loop paths present. Correct value is 1 until all blocking paths are confirmed on Dispatchers.IO. Prior safe state (v0.2.33) was concurrency=1. Fix branch applies concurrency=8 in cloudbuild templates (improvement from 80 default; full concurrency=1 revert deferred pending gcsfuse→SDK swap per P1.2). |
| minScale/maxScale | DEVIATES | min=2, max=2. Pinned — no relief valve. With maxScale=2 and both instances holding frozen slots, no new instance can absorb traffic. Follow-on: maxScale=5 paired with pool=2 (P2.2). |
| HikariCP pool math | FRAGILE | pool=10, maxScale=2 = 20 connections vs ~22 usable on db-f1-micro. Within bounds by 2 connections only. Any scale-up to 3 instances without reducing pool causes exhaustion. |
| Cloud SQL databaseFlags | DEVIATES | Zero flags. No statement_timeout, no idle_in_transaction_session_timeout, no lock_timeout. Follow-on: MC #103133 (blocked on GCP-write channel MC #103149). |
| Cloud SQL tier | DEVIATES | db-f1-micro: max_connections=25, shared CPU, VACUUM contention risk. Follow-on recommendation: db-g1-small minimum for customer-facing demo. |
| Liveness probe | ABSENT → ADDED | HTTP liveness on /health/deep added. Without it, frozen containers ran for the full incident duration with no auto-recovery. |
| Startup probe | DEVIATES → FIXED | Was TCP period=240s failureThreshold=1 timeout=240s. Now HTTP GET /health period=10s failureThreshold=3 timeout=5s. |
| Cloud Monitoring alerts | DEVIATES (critical) | 0 policies (confirmed: gcloud monitoring policies list = 0 items). Incident was CEO-detected. Follow-on: P2.1 (5 alert policies). |
| Memory | DEVIATES → FIXED | 512 Mi → 1 Gi. JVM + HikariCP + gcsfuse daemon on 512 Mi was tight; GC pressure is a secondary freeze vector. |
| Cloud SQL public IP | DEVIATES | ipv4Enabled=true. No unauthorized networks found (mitigated), but public attack surface exists. Follow-on: private IP + VPC (P2 hardening). |
| CPU throttling / startup-cpu-boost / gen2 | STANDARD | All correct. No change needed. |
5. Deploy Path and Cross-Session Coordination
Source: /tmp/alai/p2p-pairing-evidence/john-7fedd67f-freeze-fix-coordination-20260608.md
This fix was developed in session 7fedd67f and rebased on top of the Entra External ID cutover branch (b21b366). The coordination agreement between the freeze-fix session and the Entra/RBAC workstream (MC #103080, Phase 4) is:
- Step 1 (complete): PR #279 merged fix/demo-freeze-on-entra-103134 → main (839ee7f). Stage auto-deploy triggered (bilko-stage-auto-deploy: push to ^main$ → cloudbuild-stage.yaml). Stage revision bilko-api-stage-00531-cub deployed.
- Step 2 (pending): Demo and production semver tag is owned by the Entra/RBAC workstream (MC #103080). That single semver tag vX.Y.Z ships Entra + RBAC + freeze fix together, via bilko-main-deploy trigger (^v.*$ → cloudbuild.yaml, 8 gates + approval). Neither session tags unilaterally.
Deploy pipeline mechanics (verified):
bilko-stage-auto-deploy: triggered by push to branch matching ^main$, runs cloudbuild-stage.yamlbilko-main-deploy: triggered by semver tag matching ^v.*$, runs cloudbuild.yaml (demo, 8 gates + approval required)cloudbuild-demo-api.yaml: DEAD CODE — orphaned trigger deleted 2026-05-21. Do not reference or invoke.
6. Proveo Stage Validation — PASS
Source: /tmp/evidence-103134/proveo-stage-verdict.json + /tmp/evidence-103134/proveo-stage-validation.md
Timestamp: 2026-06-08T09:54:10Z
Revision: bilko-api-stage-00531-cub (git sha 839ee7f)
| Check | Result | Detail |
|---|---|---|
| #1 /health x30 sequential | PASS | 0/30 failures, max latency 170 ms |
| #1b /health x20 concurrent | PASS | 0/20 failures, max latency 279 ms |
| #2 /health/deep x15 (DB-touching) | PASS | Endpoint present, db:up, all under 200 ms |
| #3 Concurrency starvation test (6 waves x20 = 120 requests) | PASS | 0 non-200, 0x 504@60s. Wave 1 had 2/20 requests at ~10.8 s (HTTP 200, pool warm-up artifact, not freeze). Waves 2–6: zero over 2 s. Original [email protected] pattern NOT observed. |
| #4 Auth path | PASS | POST /auth/login → 410 (legacy retired); POST /auth/entra/session (invalid) → 400; GET /invoices (no auth) → 401; GET /contacts (no auth) → 401. Entra + RBAC enforced. |
| #5 Probe config | PASS | livenessProbe httpGet /health/deep present; startupProbe httpGet /health present; memory 1Gi; git sha 839ee7f confirmed. |
Overall verdict: PASS. The event-loop freeze fix is confirmed on stage. The original [email protected] symptom is not reproduced under sustained concurrent load.
Caveat: Wave 1 had 2 requests at ~10.8 s (HTTP 200, not 504) — confirmed as connection pool warm-up artifact on first concurrent burst. Not a freeze regression. Waves 2–6 (100 requests) were all under 2 s.
7. Follow-Up Tasks
| MC | Item | Status |
|---|---|---|
| #103133 | Cloud SQL statement_timeout + idle_in_transaction_session_timeout + lock_timeout (gcloud sql instances patch) | Blocked on GCP-write channel MC #103149 |
| #103148 | Gate wc bug (claim-gate stale-transcript count issue) | Open |
| #103173 | Claim-gate stale-transcript loop | Open |
| #103138 | This documentation page (WS-D) | Complete (this page) |
| Task #7 | PermissionService pre-warm cache at JVM startup (recommended polish) | Deferred |
| P1.1 | Consolidate AuthService.login() 3 transactions into 1 (reduce pool borrows per login from 3 to 1) | Deferred — daytime review |
| P1.2 | Replace gcsfuse with GCS Storage SDK in ReceiptService (unlock safe concurrency > 8) | Deferred |
| P1.5 | Install Ktor RequestTimeout plugin (force-kill stuck handlers at 10 s, return 503) | Deferred |
| P2.1 | Create 5 Cloud Monitoring alert policies (5xx rate, p99 latency, instance ceiling, Cloud SQL connections, /health/deep uptime) | Deferred — no blocking dependency |
| P2.2 | Scaling fix: containerConcurrency=1, maxScale=5, pool=2 (requires P1.2 gcsfuse→SDK first) | Deferred |
| P2.6 | Add k6 event-loop-freeze regression gate to CI (tests/k6/event-loop-freeze.js) | Deferred — spec in test-observability.md §4 B5 |
8. Evidence References
- /tmp/alai/bilko-infra-team/petter-synthesis.md — 5-agent root-cause synthesis
- /tmp/alai/bilko-infra-team/devops1-cloudrun.md — Cloud Run compute/scaling audit
- /tmp/alai/bilko-infra-team/devops2-data.md — Cloud SQL / HikariCP / gcsfuse / networking audit
- /tmp/alai/bilko-infra-team/dev-applayer.md — Application layer audit (CodeCraft)
- /tmp/alai/bilko-infra-team/test-observability.md — Observability gaps + Proveo validation plan
- /tmp/evidence-103134/rebase-on-entra.md — Fix branch rebase on Entra main, PermissionService finding, build/test results
- /tmp/evidence-103134/proveo-stage-verdict.json — Stage validation machine-readable verdict
- /tmp/evidence-103134/proveo-stage-validation.md — Stage validation human-readable report
- /tmp/alai/p2p-pairing-evidence/john-7fedd67f-freeze-fix-coordination-20260608.md — Cross-session coordination with Entra workstream
No comments to display
No comments to display