fix(data-imports): stop reporting wrapped poll timeouts as queue-db errors - #73649
Conversation
…rrors
The v3 batch consumer's poll loop wraps each fetch in asyncio.timeout() and has a dedicated handler for a clean TimeoutError that logs it as the designed recovery path with no error-tracking report. But psycopg's async wait loop can catch the CancelledError that asyncio.timeout() raises on expiry and re-raise it as a generic OperationalError ("consuming input failed: server closed the connection unexpectedly") instead of letting TimeoutError propagate. That routed it into the sibling branch meant for genuine queue-DB outages, which does call capture_exception.
Use Timeout.expired() to detect this case regardless of which exception surfaced, and route it through the same designed-timeout handling (log, back off, drop the connection) without reporting it as a defect.
Generated-By: PostHog Code
Task-Id: 98500f40-1b65-4393-884b-7b1d780cc42a
|
Hey @Gilbert09! 👋 It looks like your git author email on this PR isn't your
You can fix it for this repo with: git config user.email "you@posthog.com"Or set it globally with |
🤖 CI report
|
| File | Patch | Uncovered changed lines |
|---|---|---|
products/warehouse_sources/backend/temporal/data_imports/pipelines/pipeline_v3/postgres_queue/test_consumer.py |
95.5% | 730 |
🤖 Agents: add a test covering the lines above, or note why under "How did you test this code?". Machine-readable gap list: the patch-coverage artifact on this run (gh run download 30133231448 -n patch-coverage), or the coverage-data block at the end of this comment.
Per-product line coverage (touched products)
| Product | Coverage | Lines |
|---|---|---|
demo |
███████████░░░░░░░░░ 56.2% |
1,497 / 2,663 |
tasks |
██████████████░░░░░░ 69.8% |
30,626 / 43,893 |
signals |
████████████████░░░░ 80.1% |
22,223 / 27,736 |
cdp |
████████████████░░░░ 81.0% |
3,146 / 3,883 |
data_modeling |
█████████████████░░░ 82.7% |
5,556 / 6,722 |
notebooks |
█████████████████░░░ 85.6% |
7,478 / 8,736 |
agent_platform |
█████████████████░░░ 86.4% |
3,807 / 4,405 |
actions |
█████████████████░░░ 86.6% |
717 / 828 |
cohorts |
██████████████████░░ 87.8% |
4,488 / 5,114 |
product_tours |
██████████████████░░ 87.9% |
1,303 / 1,482 |
exports |
██████████████████░░ 88.4% |
6,951 / 7,863 |
data_warehouse |
██████████████████░░ 88.9% |
11,950 / 13,443 |
conversations |
██████████████████░░ 89.3% |
16,953 / 18,978 |
engineering_analytics |
██████████████████░░ 89.4% |
6,386 / 7,145 |
dashboards |
██████████████████░░ 89.4% |
5,983 / 6,693 |
error_tracking |
██████████████████░░ 89.7% |
10,174 / 11,343 |
alerts |
██████████████████░░ 90.0% |
4,056 / 4,508 |
streamlit_apps |
██████████████████░░ 90.4% |
2,501 / 2,767 |
slack_app |
██████████████████░░ 90.7% |
9,028 / 9,951 |
mcp_analytics |
██████████████████░░ 90.9% |
2,879 / 3,168 |
marketing_analytics |
██████████████████░░ 91.1% |
11,903 / 13,072 |
stamphog |
██████████████████░░ 91.1% |
4,056 / 4,450 |
early_access_features |
██████████████████░░ 91.5% |
1,215 / 1,328 |
product_analytics |
███████████████████░ 92.5% |
5,848 / 6,319 |
ai_observability |
███████████████████░ 92.8% |
15,178 / 16,359 |
surveys |
███████████████████░ 93.0% |
5,734 / 6,167 |
web_analytics |
███████████████████░ 93.2% |
14,671 / 15,744 |
posthog_ai |
███████████████████░ 93.2% |
1,326 / 1,422 |
approvals |
███████████████████░ 93.3% |
3,437 / 3,682 |
reminders |
███████████████████░ 93.4% |
468 / 501 |
workflows |
███████████████████░ 93.6% |
6,512 / 6,959 |
endpoints |
███████████████████░ 94.1% |
8,640 / 9,177 |
review_hog |
███████████████████░ 94.6% |
6,898 / 7,289 |
skills |
███████████████████░ 94.6% |
3,158 / 3,337 |
logs |
███████████████████░ 95.4% |
10,012 / 10,498 |
experiments |
███████████████████░ 95.8% |
25,324 / 26,444 |
annotations |
███████████████████░ 96.2% |
732 / 761 |
replay_vision |
███████████████████░ 96.2% |
15,465 / 16,069 |
revenue_analytics |
███████████████████░ 96.3% |
1,887 / 1,960 |
feature_flags |
███████████████████░ 96.4% |
17,254 / 17,906 |
user_interviews |
███████████████████░ 96.5% |
2,638 / 2,734 |
warehouse_sources |
███████████████████░ 97.2% |
340,250 / 350,099 |
customer_analytics |
███████████████████░ 97.2% |
9,757 / 10,038 |
data_catalog |
████████████████████ 97.6% |
2,469 / 2,530 |
pulse |
████████████████████ 98.4% |
2,017 / 2,049 |
Report-only. Patch coverage = changed backend lines covered vs origin/master. Sorted lowest first.
Known gaps: lines covered only by Temporal tests show as uncovered; core line numbers may drift if master changed the same file.
Problem
Error tracking flagged an
OperationalError("consuming input failed: server closed the connection unexpectedly") in the v3 warehouse-sources batch consumer's poll loop (issue).The poll loop wraps each fetch in
asyncio.timeout(poll_timeout_seconds)specifically so a slow/stuck claim query can't wedge the consumer forever. When the timeout fires, it cancels the in-flight query, and there's already a dedicatedexcept TimeoutErrorbranch for that: log it as the designed recovery path (no traceback, no error-tracking report) and back off.The problem is psycopg's async wait loop can catch that cancellation internally and re-raise it as a generic
psycopg.OperationalErrorinstead of letting a cleanTimeoutErrorpropagate. That routes it into the siblingexcept psycopg.OperationalErrorbranch instead - the one meant for genuine queue-DB outages, which does callcapture_exception. So a routine, already-handled timeout was being reported to error tracking as if the queue DB were unreachable.I confirmed via the exception chain in the captured event (
OperationalError<-TimeoutError<-CancelledErrorinsidepsycopg's wait loop) and by readingasyncio.timeout()'s implementation that this is exactly what happened - the stack trace's innermost frames are asyncio internals being cancelled, not a real connection failure.Changes
asyncio.timeout()returns aTimeoutcontext object whose.expired()method reports whether this context's own deadline fired, independent of which exception type ends up propagating. I kept a reference to it and check.expired()inside theOperationalErrorhandler: if true, treat it exactly like theTimeoutErrorcase (log, drop the connection, back off) instead of reporting it as a queue-DB outage._handle_poll_timeout()so both branches stay in sync.This is the same class of fix as #73565, which did the equivalent for the sink's periodic maintenance-query timeout - this one is the main poll loop instead.
How did you test this code?
Added
test_poll_timeout_wrapped_as_operational_error_is_not_reportedinpostgres_queue/test_consumer.py::TestQueueOperationTimeouts, alongside the existing hung-poll timeout test. It simulates a fetch that, once cancelled by the poll timeout, raisespsycopg.OperationalErrorinstead of lettingCancelledErrorpropagate (mirroring psycopg's real behavior), and assertscapture_exceptionis never called while the consumer still recovers and keeps polling.Ran:
uv run pytest products/warehouse_sources/backend/temporal/data_imports/pipelines/pipeline_v3/postgres_queue/test_consumer.py products/warehouse_sources/backend/temporal/data_imports/pipelines/pipeline_v3/duckgres/test_consumer.py -q- all pass (3 pre-existing errors in an unrelated test class need a live Postgres connection and aren't affected by this change)uv run ruff check/ruff format --checkon both changed files - cleanuv run mypy --cache-fine-grained .(repo-wide) - clean, 16918 filesDocs update
N/A - internal error-classification fix, no user-facing or documented behavior changes.
🤖 Agent context
Autonomy: Fully autonomous
I (Claude) triaged this from a PostHog error-tracking webhook alert with no human steering the investigation. I pulled the issue's stack trace and a representative event via the error-tracking MCP tools, read the batch consumer's poll loop and the psycopg call path, and traced the exception chain (
OperationalError<-TimeoutError<-CancelledError) back toasyncio.timeout()'s cancellation being re-wrapped by psycopg. I checked open PRs first and found #73565 fixed the analogous bug in the maintenance-query path, confirming this was a distinct instance in the main poll loop rather than a duplicate.No skills were invoked for this change (no migration, DRF, or frontend surface touched);
/writing-testswas consulted before adding the regression test.