Postgres connection exhaustion on dev: authenticated requests fail with 'too many clients already' (500) or time out (504)

[saqibmanan]

Summary

Authenticated requests to the dev backend intermittently exceed nginx's 60s proxy timeout and return 504 Gateway Time-out, while unauthenticated endpoints answer in ~0.2s. Roughly half of calls to the token-exchange endpoint are affected.

Found while enabling the API smoke suite against dev (CivicDataSpace-test#19) — the tests had never actually run in CI, so this had no way of surfacing.

Measurements

All taken from a single session against https://dev.api.civicdataspace.in:

POST /api/auth/keycloak/login/ — four consecutive calls:

Attempt	Result
1	504 after 60.1s
2	200 in 6.9s
3	200 in 42.2s
4	504 after 60.1s

GET /api/activities/user/ (authenticated) — three consecutive calls:

Attempt	Result
1	200 in 8.3s
2	200 in 8.3s
3	200 in 50.3s

What this is not

Deliberately ruled out:

Endpoint	Latency
Keycloak OIDC discovery	0.13s
Keycloak JWKS (/certs)	0.12s
Keycloak userinfo	0.13s
Backend GET /health/	0.20s

Keycloak is fast and the backend's own health endpoint is fast. /health/ reports database, elasticsearch and redis all healthy. So this is not the auth.civicdatalab.in migration, not general network latency, and not a wholly-down service — it is specific to the authenticated request path inside the backend.

The bimodal distribution (fast, or 40-60s+, with little in between) looks more like waiting on a resource than like slow computation — a connection pool, a lock, or a blocking call in auth middleware would all produce this shape.

Impact

• Any client doing the Keycloak token exchange fails about half the time on dev.
• ParakhAI is affected: its DataSpaceAuthMiddleware forwards user tokens to this endpoint, so a timeout there degrades ParakhAI requests.
• It masked a test defect. A cross-application test asserted status != 401, which a 504 satisfies — so it passed while the endpoint was timing out entirely. Tightened in ParakhAI_test#10.

Current mitigation (tests only)

CivicDataSpace-test#19 retries gateway timeouts in the shared API client and skips authenticated tests when the exchange never answers, so an infrastructure problem stops presenting as an API contract failure. That keeps CI usable — it does not fix this, and the retries will keep hiding it until it is addressed.

Health checks there remain strict, so a genuine outage still fails.

Suggested next step

Compare timings on prod. If prod is clean this is dev-environment resourcing; if prod shows the same shape it is a code path worth profiling — starting with what the auth middleware does per request and whether it holds a DB connection while making an outbound call.

[saqibmanan]

Root cause: PostgreSQL connection exhaustion

Caught the underlying error by sampling the endpoint until it returned a 500 rather than a 504:

OperationalError at /api/auth/keycloak/login/

connection to server at "backend_db" (172.24.0.2), port 5432 failed:
FATAL:  sorry, too many clients already

Exception Location: /usr/local/lib/python3.10/site-packages/psycopg2/__init__.py, line 122, in connect

This explains both symptoms as one fault, which the original report treated as unexplained:

• 504 — the request waits for a free connection and nginx gives up at 60s.
• 500 — the connection attempt fails immediately with too many clients already.

Which one you get depends on whether you land in the queue or get refused outright, hence the bimodal timing (fast, or 40-60s+, nothing in between) and the roughly even split.

It also explains why /health/ stays fast at 0.2s while authenticated routes fail: whatever /health/ does to check the database either reuses a connection or fails fast, so it never contends for a new one. A green /health/ is therefore not evidence the database layer is healthy here.

Observed distribution

Sampled the exchange endpoint repeatedly during this investigation:

504, 500, 500, 500, 500, 504
504, 504, 504, 200
200, 200, 504

Where to look

max_connections on backend_db versus how many connections the app actually opens. Worth checking:

• CONN_MAX_AGE — if it is 0, every request opens and closes a connection; if it is large without a pooler, idle connections accumulate and are never reclaimed.
• Gunicorn/uvicorn worker count multiplied by threads, against Postgres max_connections.
• Whether anything holds a connection open across an outbound HTTP call (the token exchange does contact Keycloak), which would hold a slot for the duration of that call.
• SELECT count(*), state FROM pg_stat_activity GROUP BY state; during a slow period will show whether the slots are idle, idle-in-transaction, or genuinely active. idle in transaction would point at a different bug from simple over-allocation.

A connection pooler (pgbouncer) or a lower per-worker connection ceiling is the usual fix, but the pg_stat_activity breakdown should come first — it distinguishes "too many workers" from "connections leaked and never returned".

Note on severity

This is dev, but the same configuration shape likely exists on prod. Worth checking pg_stat_activity there before assuming it is dev-only resourcing.

[saqibmanan]

Escalation: this now blocks deploys, not just tests

The Deploy Backend to Dev EC2 run for the merge of #133 failed with the same error — this time from Django's own startup checks, before the app even served a request:

django.db.utils.OperationalError: connection to server at "backend_db" (172.24.0.2), port 5432 failed:
FATAL:  sorry, too many clients already

Run 33679992434 — Deploy to EC2 failed, so Smoke Tests, Finalize Deploy and Rollback were all skipped.

That reframes the severity. It is not only that authenticated requests fail intermittently; the deploy pipeline cannot complete, because manage.py cannot open a connection either. The previous deploy is still serving.

/health/ is actively misleading here

Taken just now, while the exchange endpoint was returning too many clients already:

GET /health/ -> 200 in 0.44s
{"status": "healthy", "services": {"database": {"status": "healthy",
 "message": "Successfully connected to database"}, ...}}

The health check reports the database healthy at the same moment new connections are being refused. It presumably reuses an already-open connection rather than opening one, so it never contends for a slot.

Anything relying on /health/ to gate a deploy or to page on database problems will stay green through this outage. Worth fixing alongside the connection issue — a health check that cannot fail when the database is unreachable to new work is not measuring the thing it claims to.

Suggested immediate step

Connections need reclaiming before the next deploy can succeed. During a bad period:

SELECT count(*), state FROM pg_stat_activity WHERE datname = current_database() GROUP BY state;
SHOW max_connections;

If most slots are idle or idle in transaction, that distinguishes leaked/over-retained connections from genuine over-allocation, and points at whether the fix is CONN_MAX_AGE, worker count, or a pooler.

[saqibmanan]

Resolved

Root cause was not connection leakage but row-lock contention, and the deploy failures had a second, independent cause. Both fixed and verified on dev.

What was actually happening

Every login called user.save() unconditionally inside @transaction.atomic, rewriting every column of the same row. Concurrent logins for one user queued on that row's lock, and each waiting request held a database connection while it waited — which walked the count to max_connections and produced sorry, too many clients already.

Captured from pg_stat_activity during a burst:

 36  active              | Lock   | tuple
 31  active              | Lock   | transactionid
 67  UPDATE "ds_user" SET "password" = ..., "last_login" = ...

Ruled out with measurements, not assumption: Keycloak did 20 concurrent introspects in 0.2s; ATOMIC_REQUESTS was unset; no User.post_save signals existed. An intermediate fix adding uvicorn workers (#135) did not improve concurrency — which is what pointed at the database rather than the application.

Measured, same test before and after

	Before	After
Single login	4.6s	0.5s
20 concurrent	17×200, 3×504, up to 60.1s	20×200, max 1.6s
Wall clock (20)	60.2s	1.6s
DB connections peak	26	7
Lock waiters peak	36 samples	0
Image size	14.1GB	3.56GB

Latencies before formed a clean arithmetic sequence (4.3, 8.1, 12.0 … 60.1s) — the signature of serialization. They now cluster at 0.9–1.6s, which is genuine concurrency.

API smoke suite: 20 passed, 1 skipped.

Fixes

• fix: stop rewriting the user row on every login (the actual cause of connection exhaustion) #136 — save only when a field actually changed, with update_fields. A repeat login of an unchanged user now performs no write, so there is no lock to contend on. Also dropped a gratuitous user.save() on the Django-JWT path.
• fix: install CPU-only torch so the image can actually be deployed #137 — CPU-only torch. The image was 14.1GB, of which 6.6GB was CUDA runtime on a 2-CPU box with no GPU. docker pull had begun exceeding the deploy step's 40 minute timeout, so fix: stop rewriting the user row on every login (the actual cause of connection exhaustion) #136 merged green and then could not be deployed at all.
• fix: stop Postgres connection exhaustion (serialized sync views, duplicate Keycloak calls, blind health check) #135 — two uvicorn workers, three Keycloak round-trips per login reduced to one, and a health check that opens a fresh connection.

On the health check

/health/ returned {"database": "healthy"} in 0.44s while Postgres was refusing new connections and the deploy pipeline was failing on exactly that. It probed the request's own already-open connection, so it could not fail for the condition taking the service down. It now also opens and closes a fresh connection.

That matters beyond observability: ci-deploy.sh gates on /health/ with curl -f, and the view returns 503 when a required service is unhealthy — so with the check able to detect exhaustion, the deploy gate now catches this class of fault and rolls back automatically.

Follow-up

#138 adds a build-time image size ceiling (8GB against the current 3.56GB). Builds stayed green through all of this while the cost landed only on the deploy host an hour later; that PR moves the feedback to the PR that causes it.