fix: kill hung queries at 25 seconds and stop tile requests hanging forever on database errors - #113
Conversation
- Set statement_timeout (default 30s, override with STATEMENT_TIMEOUT env) on every pooled connection, so a hung query is killed by our own client instead of waiting for the database server's 600 second limit. Each failed query then holds a shared pgpool slot for at most 30 seconds. - Move the async work out of the Promise executor in buildMapInstance. A rejection inside an async executor never rejects the outer promise, so database errors left the HTTP request hanging forever with no response. Errors now reach the route handler and return HTTP 500. This completes the error path started in Greenstand#111: database error in, clean HTTP error out. All four tile routes go through this function. For Greenstand/treetracker-infrastructure#315 (Fix 1 plus the error propagation gap found in the July 2 investigation).
|
Evidence update (July 6): these queries do not only leak memory. They crash tile server pods. I saw it happen three times. On Monday July 6 I ran an automated watch from 03:03 to 17:46 UTC. It took a sample every 2 minutes. It recorded every query that ran longer than 60 seconds, together with its SQL and the memory of both tile server pods. I also compared the results with the replica's CPU graphs for the same hours. Three findings are important for this review. All of them make the case for this PR stronger. First, a definition. Below I use the word "giant" for one specific query type. A query is giant when its result is built from the complete dataset. This happens for the global map at low zoom (zoom 0 to 6): that map has no filter, so the query groups all of the roughly 8 million trees into cluster bubbles and returns all of that as one result. A query for one organization's map or one wallet's map is never giant, because it returns only that organization's or that wallet's trees, which is a small result. Note that giant describes the size of the result, not the runtime. An organization map query can also run for hours (see finding 2), but its result stays small. 1. When several giant queries finish at the same moment, the pods die. Evidence item 5 in the PR description says: when giant results arrived, the pods kept 360 to 430 MB of extra memory forever. Monday showed a worse outcome. Three times, a group of giant queries finished within the same 2 minute sample, and tile server pods died at that exact moment:
In total: four pods deleted and two container restarts in 3.3 hours. This PR would have stopped every one of these queries at 30 seconds. The jump from 540 MB to 2,349 MB is the memory problem of issue mapnik#315, recorded as it happened: the giant result arrives all at once, no user is waiting for it anymore (the load balancer already closed the client connection at 60 seconds), and the pod does not have enough memory to hold it. One detail supports this reading: a third group of giant queries finished on the same day, but spread out over 16 minutes instead of together, and the pods survived with no visible memory change. The kill needs both things: giant results, and several of them arriving at the same time. The 30 second limit removes the giant class completely, so the arrival pattern stops mattering. 2. Long runtime alone is not the danger. The result size is. On the same morning, one organization map ran queries of 1h56m and 2h00m. Another organization map ran two queries for 5 hours. All of these finished with no change in pod memory, exactly as the definition above predicts: their results were small. But note that these queries are still a serious problem. Giant or not, every slow query holds a shared database connection and replica CPU for its whole runtime. Only the giant type additionally crashes pods when the result comes back. The 30 second limit stops both types at the source. 3. A second proof that these queries cause the replica CPU load. Item 3 of the description: on July 5 I manually cancelled the runaway queries, and replica CPU fell from 100 to 11 percent in 4 minutes. Monday gave the same proof without any manual action: the 5 hour query pair finished by itself at 17:50 UTC, and replica CPU fell from about 50 percent to 12 percent in a few minutes. It then stayed low. Both times, the CPU dropped exactly when these queries stopped. Nothing else changed at those moments. More numbers from the watch: 99 slow queries in less than 15 hours of normal traffic. One page view of one public map started 20 queries at the same time; they ran 21 to 46 minutes each. The replica was at full CPU from 07:00 to 08:07 (page views of one organization map, seven queries at the same time) and again from 12:55 to 13:15 (the 20 query wave). For most of the rest of the day it ran at 32 to 72 percent. The 5 hour pair alone used about 2 CPU cores for the whole afternoon. The longest finished query I have seen through pgpool is now 5h01m. The 41 hour pair in the description is still the worst case. Nothing here changes the code in this PR. It changes how much damage the PR prevents: with the 30 second limit, none of the queries above lives long enough to saturate the replica, to block the shared connection pool, or to deliver the giant result that kills a pod. @dadiorchen the PR is ready for review whenever you have time. I am happy to explain any of the measurements. |
…udFront edge timeout The production tile hosts (tiles and tiles1-4.treetracker.org) sit behind a CloudFront distribution whose origin response timeout is 30 seconds, with up to 3 attempts. With the default equal to 30s the two deadlines race: if CloudFront gives up first it retries the same multi-hour query. A 25s default guarantees the database returns its error before the edge deadline, so CloudFront delivers the error instead of retrying. Still overridable via STATEMENT_TIMEOUT.
|
To make it concrete what this 30 second limit actually stops, I posted the exact database queries behind the slow and missing tiles here, captured live from production: Greenstand/treetracker-infrastructure#315 (comment) Two are full statements (a whole-dataset cluster query and an organization map query), taken from the pod logs and matched to the live queries on the replica. Both scan a 27 GB materialized view with no bounding box and run for minutes to hours. This PR is what stops them at the source. One decision point for this PR while I have your attention. Production tile traffic goes through AWS CloudFront, and I checked its settings: it waits 30 seconds for a tile, then gives up and retries, up to 3 attempts. The limit proposed here is also 30 seconds, so the two deadlines are level and it becomes a race: if CloudFront times out a moment before the query does, it retries and starts the same multi hour query again, up to two more times. I set the default to 25 seconds rather than 30 (latest commit on this branch). That keeps the limit just below the edge deadline, so the error reaches CloudFront before it retries, and CloudFront delivers the error rather than starting the query again. It costs nothing for real traffic, because no legitimate tile takes anywhere near 25 seconds. The value stays configurable through the STATEMENT_TIMEOUT environment variable, so this only changes the default. |
| //kill any query that runs longer than statementTimeout on our side, | ||
| //instead of waiting for the database server's 600s limit | ||
| pool.on('connect', (client) => { | ||
| client.query(`SET statement_timeout = ${statementTimeout}`).catch(e => { |
There was a problem hiding this comment.
If we set timeout on the db side, then it could make the situation worse, because sql failed and no pg pool cache for this and next, we still try to request and failed again, it could make this failing infinitely
Airflow has been down since 2026-06-13 (#321): the embedded Redis pod cannot pull public.ecr.aws/bitnami/redis:5.0.14-debian-10-r32 because Bitnami delisted its free public images. Without Redis (the Celery broker) the scheduler and workers crash loop and no DAG runs. This pins the Redis image explicitly to docker.io/bitnamilegacy/redis, Bitnami's read-only archive of the same images. The archive does not carry the old suffixed tag; it carries the bare 5.0.14 version alias (verified against the Docker Hub API on 2026-07-03), which points at the final rebuild of the exact Redis version that ran in production before the outage. The playbook previously set no image override, so the deployed release inherited a default that no longer exists anywhere pullable. Deploy note: do not roll this out before Greenstand/node-mapnik-1#113 is merged and deployed. Restoring Airflow resumes the map pre-warm DAGs, and the tile server needs its query timeout in place first (see issue #315 for the sequencing rationale).
Fixes two of the remaining problems from Greenstand/treetracker-infrastructure#315. Follow-up to #111.
Background: the life of one bad request today
To understand what this PR changes, follow one request for a map tile whose database query is too heavy to ever finish (for example the expensive cluster queries described in issue #315):
buildMapInstance, the error falls into broken promise wiring and vanishes. No response is ever sent.So one bad query costs: 10 minutes of a shared database slot, plus a hung connection, plus a blind retry that repeats the damage.
Evidence update (2026-07-05 and 06): I measured what actually happens in production
Everything in this section I measured on the live production system. It replaces the cautious assumptions above with hard numbers, and every number says the problem is worse than first described.
1. The 600-second kill no longer exists. The real worst case is 41 hours.
I ran a deliberate test query,
SELECT pg_sleep(700), and it completed untouched (701 seconds, no error) both through pgpool and directly against the database replica. Nothing at any layer kills a long query today. The same day, I found the replica running two tile queries that had been executing for 41 hours, for a client machine that had been destroyed in a node rotation a day earlier, plus six more at 4.7 hours that all came from a single organization map page view. Step 4 of the story above should now read "the query runs until someone notices and cancels it by hand", not "about 600 seconds".2. A week of replica host graphs shows the cost: the database replica ran at 100 percent CPU for 2 to 24 hours EVERY day of the last week.
From the DigitalOcean host metrics for the replica (June 29 to July 6, UTC):
That includes one block of 45 hours of continuous 100 percent CPU (July 2 21:20 to July 4 18:19 UTC), and replica memory peaked at 99.5 percent on July 3 (within half a percent of out-of-memory).
3. These specific queries are the cause, proven by intervention. On July 5 at 05:32 UTC I manually cancelled the 8 runaway tile queries then on the replica. CPU collapsed from 100 percent to 11 percent within 4 minutes, and stayed at baseline until the next wave of map traffic hours later. Nothing else changed at that moment.
4. Cancelling by hand is not a fix. Within 2 hours of that cancel, ordinary map visits regenerated the same workload: 14 queries over 10 minutes (8 running at the same time at the peak), 6 over an hour, 2 at about 2 hours, in one Sunday morning. The same evening, an 8 hour automated watch captured 42 distinct runaway queries from at least 9 different maps (several organization maps, a wallet map, and named public maps), including single page views that each launched 6 to 8 simultaneous queries running 4 to 40 minutes. This is ordinary browsing across the whole map catalog, not one problem map. Every one of these queries runs on exactly the connection pool this PR covers.
5. Nobody receives the results of these queries. The production gateway timeout for the tile route is disabled, and the load balancer in front cuts an idle connection at about 60 seconds (its default; nothing configures it otherwise). So every query that passes the one minute mark is computing a result for a client that hung up long ago. Killing at 30 seconds therefore loses nothing a user would ever see. It also helps the memory half of issue mapnik#315: when two orphaned 2-hour queries finally returned their giant results, both tile server pods rendered them into dead connections and permanently retained 360 to 430 MB each, measured at that exact minute. (Follow-up measurement sharpened this: the 42 shorter runaway completions watched the same evening retained nothing, so the permanent memory growth is specific to the giant multi-hour results, exactly the class the 30 second cap eliminates.)
6. I proved the exact mechanism of Change 1 against production infrastructure. Through the real production pgpool path,
SET statement_timeout = '2s'cancelled a testpg_sleep(5)after exactly 2 seconds with the expected PostgreSQL error. Afterwards, 10 freshly pooled sessions all showed the timeout back at 0, confirming the setting does not leak into the pooled connections other services reuse.7. I also found the root cause of the slow queries themselves (broken query planner statistics on the main map table; written up in issue mapnik#315). Fixing that will make tile queries faster, but no statistics fix can remove the need for a timeout: this PR is the permanent safety layer, the statistics work is the performance repair.
Change 1: tell the database "no query may run longer than 30 seconds"
Every time the connection pool opens a database connection, it now runs
SET statement_timeout = 30000. That is a standard PostgreSQL setting meaning "kill any query on this connection that runs longer than 30 seconds."Scope: this timeout applies ONLY to the connections the tile server itself opens to pgpool (the Node.js
pgpool created inapp.js, which carries the tile SQL queries). It is set per connection, not globally, so nothing else changes behavior:statement_timeout = 0for everyone else).Step 2 above changes from 600 seconds (in reality: unbounded, up to the observed 41 hours) to 30 seconds. A bad query now holds a shared pgpool slot for at most 30 seconds.
Why 30 seconds is safe: worker logs show normal, successful tile renders finish in 30 to 37 seconds end to end, which means the database part finishes well under 30. And per evidence item 5 above, any query still running at 30 seconds is computing for a client that the load balancer will cut (or has already cut) at about 60 seconds; killing it loses nothing.
The value can be tuned without a code change through the
STATEMENT_TIMEOUTenvironment variable (in milliseconds).Update (verified 2026-07-03): there is currently NO query timeout in effect anywhere in the database. I checked the live production settings by querying
pg_settingsthrough the tile server's own database connection. The result: PostgreSQL 17.10 withstatement_timeout = 0,transaction_timeout = 0, andlock_timeout = 0(all defaults). PostgreSQL will never kill a runaway query on its own. This means the setting added by this PR is not an extra safety layer on top of an existing one; it is the only query-level timeout the system will have. It also confirms the 600 second kills observed in past incidents were not a database setting, so they cannot be counted on as a backstop (and per the evidence update above, they no longer happen at all).Change 2: database errors now produce an answer instead of silence
buildMapInstancedid its work inside a promise wrapper written in a way where errors thrown midway have nowhere to go (the technical name is the "async promise executor" anti-pattern: an error inside it does not reject the outer promise, it just leaves it stuck as pending forever). That is why step 5 above swallowed the error and the request hung.This PR moves the work out of the wrapper so errors flow normally to the error handler that already exists in every route. Step 5 changes from "the error vanishes and the connection hangs" to "the caller immediately gets an HTTP 500 error response."
This also completes what #111 started. #111 fixed the database layer so errors are reported instead of swallowed, but this wiring bug swallowed them again one layer up, so from the outside nothing had improved on the error path. After this PR: database error in, clean HTTP error out. A browser can show "tile unavailable" instead of spinning forever, and the Airflow pre-warm job fails in seconds with a real error message in its logs instead of burning its full timeout on silence.
All four tile routes (
.png,.grid.json, and both/newvariants) go through this one function, so one change covers them all.Change 3 (small): keep the process alive if an idle connection drops
Added
pool.on('error'). The database client library requires this: if a connection sitting idle in the pool gets dropped (a network blip, or pgpool recycling connections) and nobody is listening for the error, the whole tile server process crashes. Now it just logs the error instead.After this PR
The same bad request costs: the query is killed by the database at second 30 (Change 1), the error travels cleanly up through the layers (#111), and the caller receives an HTTP 500 at second 30 instead of silence (Change 2). Total damage: 30 seconds of one pool slot and one log line. Compare that to what the evidence update measured: hours-long queries, a saturated replica for most of every day, and 40 shared slots slowly filling with doomed work.
Why this needs to merge before the Redis fix
Issue Greenstand/treetracker-infrastructure#321 (Airflow's Redis is down) is currently keeping the pre-warm job offline, which is the only reason things look calm. The moment Redis is repaired, that job resumes sending 182 tile requests every 5 minutes. If this PR is deployed first, the returning traffic hits a server that fails fast and cleanly. If not, the old behavior gets uncorked onto a database replica that the host graphs show is already saturated for hours every day, and the original incident likely restarts.
How it was validated
I built a test harness that loads the real app.js, config.js, Map.js and PGPool.js code with the outside libraries replaced by stand-ins, including a fake database that rejects every query, which is exactly what a killed query looks like to this code. Against current master: the tile route never responds (hangs), confirming the bug. With this PR: the route returns HTTP 500 with the error message immediately, the 30 second timeout is set on every connection, the environment override works, and the two failure paths (the SET failing, an idle connection dropping) are absorbed without crashing. 9 of 9 checks pass.
In addition, I verified the timeout mechanism itself against production infrastructure on 2026-07-05 (evidence item 6 above): through the real pgpool path, a 2 second statement_timeout cancelled a test query on schedule, and no timeout setting leaked into other pooled sessions.
Not yet tested against a real database from this branch: per the team process, this PR is reviewed first, then deployed to the dev environment for verification (a normal tile renders; with
STATEMENT_TIMEOUT=100a heavy query returns HTTP 500 in seconds instead of hanging), and promoted to production a few days later if dev shows no issues. The Redis repair (issue #321) waits for the production deploy, not just the merge.What this PR does not do
It does not fix the memory growth to 2 GB (that is a separate investigation in issue #315, although evidence item 5 above shows this PR removes one measured source of permanent memory growth), it does not change the Airflow job settings (Fix 3 in the issue, which lives in the treetracker-airflow-dags repo), and it does not cover the few database connections that the Mapnik map renderer opens on its own for high zoom tiles, which bypass this connection pool.
It also does not set a default timeout on the PostgreSQL server itself. The database configuration is not touched by this PR: the server keeps
statement_timeout = 0, and every other client keeps its current behavior. The change is entirely application side, applied by the tile server on each of its own connections at connect time, and it disappears if the app is rolled back. Giving the database a server-wide or per-role default timeout (for exampleALTER ROLE ... SET statement_timeout) is a possible future hardening step, but it would affect every service that shares the database, so it deserves its own discussion and is deliberately out of scope here.Finally, it does not fix WHY the tile queries are slow in the first place. That work targets the database and is tracked in issue #315 (evidence item 7 above), in rough order:
ANALYZEon the main map table (active_tree_region) on the production primary. Its query planner statistics are broken (the planner estimates 1 row for map areas that contain millions of trees, and picks catastrophic query plans as a result), and because the table is a materialized view, PostgreSQL never refreshes those statistics on its own. This is a one-command repair at a quiet hour; I have drafted the proposal on Vector tiles renderer ignores zoom level mapnik/node-mapnik#315 and it is awaiting go-ahead.ANALYZEafter every rebuild of the materialized view, so the statistics can never go permanently stale again (a small PR in the treetracker-airflow-dags repo).Those changes attack the root cause and should shrink most tile queries from hours to seconds. None of them replaces this PR: whatever makes queries fast tomorrow, the timeout is what guarantees that no single map visit can ever again hold the shared database pool hostage for hours.