-
Notifications
You must be signed in to change notification settings - Fork 3.3k
fix(cohorts): guard cohort recalculation Redis calls #91350
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||
|---|---|---|---|---|---|---|
|
|
@@ -4,9 +4,10 @@ | |||||
| from unittest.mock import MagicMock, patch | ||||||
|
|
||||||
| from django.db import DEFAULT_DB_ALIAS, OperationalError | ||||||
| from django.test import SimpleTestCase | ||||||
| from django.test import SimpleTestCase, override_settings | ||||||
|
|
||||||
| from clickhouse_driver.errors import SocketTimeoutError | ||||||
| from kombu.exceptions import OperationalError as BrokerOperationalError | ||||||
| from parameterized import parameterized | ||||||
| from pydantic import ( | ||||||
| BaseModel, | ||||||
|
|
@@ -38,6 +39,7 @@ | |||||
| insert_cohort_query_actors_into_ch, | ||||||
| parse_error_code, | ||||||
| print_cohort_hogql_query, | ||||||
| run_cohort_query, | ||||||
| simplified_cohort_filter_properties, | ||||||
| sort_cohorts_topologically, | ||||||
| validate_actors_query_for_cohort, | ||||||
|
|
@@ -1360,10 +1362,17 @@ def test_original_error_surfaces_when_recovery_history_save_fails(self): | |||||
| assert mock_history.save.call_count == 2 | ||||||
| mock_connections[DEFAULT_DB_ALIAS].close.assert_called_once() | ||||||
|
|
||||||
| def test_original_error_surfaces_when_reset_calculating_save_fails(self): | ||||||
| # calculate_people_ch's finally block resets is_calculating on the same connection the recovery | ||||||
| # bookkeeping save uses. If that reset write hits the dropped connection it must not raise out of | ||||||
| # finally and mask the real calculation error - it runs through the same reconnect-and-retry. | ||||||
| @parameterized.expand( | ||||||
| [ | ||||||
| # A dropped Postgres connection, and a Redis error escaping the save's post_save signals. | ||||||
| ("connection_error", OperationalError("the connection is closed")), | ||||||
| ("redis_error", Exception("redis unavailable")), | ||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
The signal-firing call site is different: the bookkeeping
Suggested change
Fix the comment at test_util.py:1367 the same way. |
||||||
| ] | ||||||
| ) | ||||||
| def test_original_error_surfaces_when_reset_calculating_save_fails(self, _name, bookkeeping_error): | ||||||
| # calculate_people_ch's finally block resets is_calculating through the recovery bookkeeping. | ||||||
| # If that reset write fails - a dropped connection, or a Redis error from the save's signals - | ||||||
| # it must not raise out of finally and mask the real calculation error. | ||||||
| cohort = _create_cohort( | ||||||
| team=self.team, | ||||||
| name="c", | ||||||
|
|
@@ -1376,11 +1385,11 @@ def test_original_error_surfaces_when_reset_calculating_save_fails(self): | |||||
| "products.cohorts.backend.models.util.recalculate_cohortpeople", | ||||||
| side_effect=real_error, | ||||||
| ), | ||||||
| # The is_calculating reset write fails on the dropped connection, initial attempt and retry. | ||||||
| # The is_calculating reset write fails, initial attempt and retry. | ||||||
| patch.object( | ||||||
| Cohort, | ||||||
| "_safe_reset_calculating_state", | ||||||
| side_effect=OperationalError("the connection is closed"), | ||||||
| side_effect=bookkeeping_error, | ||||||
| ) as mock_reset, | ||||||
| # Patch connections so the reconnect doesn't close the real test transaction's connection. | ||||||
| patch("products.cohorts.backend.models.util.connections") as mock_connections, | ||||||
|
|
@@ -1391,3 +1400,25 @@ def test_original_error_surfaces_when_reset_calculating_save_fails(self): | |||||
| self.assertIs(ctx.exception, real_error) | ||||||
| assert mock_reset.call_count == 2 | ||||||
| mock_connections[DEFAULT_DB_ALIAS].close.assert_called_once() | ||||||
|
|
||||||
|
|
||||||
| class TestRunCohortQueryScheduling(SimpleTestCase): | ||||||
| @override_settings(TEST=False, IN_EVAL_TESTING=False) | ||||||
| def test_survives_broker_error_scheduling_initial_stats_task(self): | ||||||
| # The initial stats task is scheduled before the query runs. A broker blip there must not | ||||||
| # abort the recalculation before any ClickHouse work happens - run_cohort_query has to swallow | ||||||
| # it and still return fn's result, the same way the reschedule call after fn is guarded. | ||||||
| history = MagicMock() | ||||||
| with patch( | ||||||
| "posthog.tasks.calculate_cohort.collect_cohort_query_stats.apply_async", | ||||||
| side_effect=BrokerOperationalError("broker unavailable"), | ||||||
| ) as mock_apply: | ||||||
| result, _end_time = run_cohort_query( | ||||||
| lambda: "calc-result", | ||||||
| cohort_id=123, | ||||||
| history=history, | ||||||
| query="SELECT 1", | ||||||
| ) | ||||||
|
|
||||||
| assert result == "calc-result" | ||||||
| mock_apply.assert_called_once() | ||||||
| Original file line number | Diff line number | Diff line change | ||||||||
|---|---|---|---|---|---|---|---|---|---|---|
|
|
@@ -8,7 +8,7 @@ | |||||||||
| from typing import TYPE_CHECKING, Any, Optional, Union, cast | ||||||||||
|
|
||||||||||
| from django.conf import settings | ||||||||||
| from django.db import DEFAULT_DB_ALIAS, InterfaceError, OperationalError, connections | ||||||||||
| from django.db import DEFAULT_DB_ALIAS, connections | ||||||||||
| from django.utils import timezone | ||||||||||
|
|
||||||||||
| import structlog | ||||||||||
|
|
@@ -156,15 +156,16 @@ def save_recovery_bookkeeping(save_fn: Callable[[], None], *, cohort_id: int, te | |||||||||
| """Persist post-calculation bookkeeping, surviving a Postgres connection dropped mid-recalculation. | ||||||||||
|
|
||||||||||
| A long recalculation can outlive its connection (the server closes it unexpectedly); the first | ||||||||||
| write afterwards then raises a connection error. Left unguarded on the error/finally recovery | ||||||||||
| path, that cascades into "the connection is closed" - burying the real root-cause error and | ||||||||||
| leaving the cohort stuck with is_calculating=True. Reconnect and retry once so the bookkeeping | ||||||||||
| still lands and the original error is what propagates; if the retry fails too, swallow it (a | ||||||||||
| recovery write must never mask the failure it is recording). | ||||||||||
| write afterwards then raises a connection error. The save also fires post_save signal handlers | ||||||||||
| that touch Redis, so a Redis blip can escape here too. Left unguarded on the error/finally | ||||||||||
| recovery path, either failure buries the real root-cause error and leaves the cohort stuck with | ||||||||||
| is_calculating=True. Reconnect and retry once so the bookkeeping still lands and the original | ||||||||||
| error is what propagates; if the retry fails too, swallow it (a recovery write must never mask | ||||||||||
| the failure it is recording). | ||||||||||
| """ | ||||||||||
| try: | ||||||||||
|
posthog[bot] marked this conversation as resolved.
|
||||||||||
| save_fn() | ||||||||||
| except (InterfaceError, OperationalError): | ||||||||||
| except Exception: | ||||||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
The blast radius is small today, which is why this is a suggestion. This isn't the approach you already declined. Every exception still gets swallowed and captured, so error tracking doesn't become less visible. The reconnect-and-retry logic narrows specifically to when it makes sense: failures that a reconnect can fix. It requires try:
- save_fn()
- except Exception:
- connections[DEFAULT_DB_ALIAS].close() # next query opens a fresh connection
- try:
+ try:
save_fn()
- except Exception as retry_error:
- # A swallowed retry means the cohort is stuck with is_calculating=True and no bookkeeping
- # recorded. Surface it to error tracking, matching how other swallowed cohort-calculation
- # errors are captured, so it alerts rather than only living in structured logs.
- logger.warning("cohort_recalc_recovery_save_failed", cohort_id=cohort_id, team_id=team_id, exc_info=True)
- capture_exception(retry_error, additional_properties={"cohort_id": cohort_id, "team_id": team_id})
+ except (InterfaceError, OperationalError):
+ connections[DEFAULT_DB_ALIAS].close() # next query opens a fresh connection
+ save_fn()
+ except Exception as error:
+ # A swallowed failure means the cohort is stuck with is_calculating=True and no bookkeeping
+ # recorded. Surface it to error tracking, matching how other swallowed cohort-calculation
+ # errors are captured, so it alerts rather than only living in structured logs.
+ logger.warning("cohort_recalc_recovery_save_failed", cohort_id=cohort_id, team_id=team_id, exc_info=True)
+ capture_exception(error, additional_properties={"cohort_id": cohort_id, "team_id": team_id})Update the non-connection error case in test_util.py:1398: the reconnect no longer runs, so the assertions become |
||||||||||
| connections[DEFAULT_DB_ALIAS].close() # next query opens a fresh connection | ||||||||||
| try: | ||||||||||
| save_fn() | ||||||||||
|
|
@@ -212,10 +213,16 @@ def run_cohort_query( | |||||||||
| # Schedule delayed task to collect stats after query_log_archive is synced | ||||||||||
| # Only if we have a history record to update and not in test mode | ||||||||||
| if history and query and not (settings.TEST or settings.IN_EVAL_TESTING): | ||||||||||
| delayed_task = collect_cohort_query_stats.apply_async( | ||||||||||
| args=[cohort_tag, cohort_id, start_time.isoformat(), history.id, query], | ||||||||||
| countdown=COHORT_QUERY_TIMEOUT_SECONDS + COHORT_STATS_COLLECTION_DELAY_SECONDS, | ||||||||||
| ) | ||||||||||
| # Best-effort stats telemetry scheduled before the query runs, so a broker blip here must | ||||||||||
| # not abort the recalculation before any ClickHouse work happens. Log and continue with no | ||||||||||
| # delayed task, matching the guard on the reschedule below. | ||||||||||
| try: | ||||||||||
| delayed_task = collect_cohort_query_stats.apply_async( | ||||||||||
| args=[cohort_tag, cohort_id, start_time.isoformat(), history.id, query], | ||||||||||
| countdown=COHORT_QUERY_TIMEOUT_SECONDS + COHORT_STATS_COLLECTION_DELAY_SECONDS, | ||||||||||
| ) | ||||||||||
| except Exception as error: | ||||||||||
| logger.warning("cohort_stats_collection_scheduling_failed", cohort_id=cohort_id, error=str(error)) | ||||||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Neither passes
Suggested change
For the one at util.py:247, rename the event to |
||||||||||
|
|
||||||||||
| try: | ||||||||||
| result = fn(*args, **kwargs) | ||||||||||
|
|
@@ -224,14 +231,20 @@ def run_cohort_query( | |||||||||
| # If calculation succeeded and we scheduled a delayed task, cancel it and run immediately | ||||||||||
| # This avoids waiting the full timeout when the query completed quickly | ||||||||||
| if delayed_task and history and query and not settings.TEST: | ||||||||||
| if delayed_task.state in ["PENDING", "RECEIVED"]: | ||||||||||
| delayed_task.revoke() # Cancel the delayed task | ||||||||||
| # The recalculation result is already computed. This rescheduling is best-effort stats | ||||||||||
| # bookkeeping that talks to the Celery result backend and broker, so a Redis blip must | ||||||||||
| # not discard the result. The delayed task still runs after its original countdown. | ||||||||||
| try: | ||||||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
No test covers this block. Publishing before revoking makes the comment true in every ordering. A publish failure leaves the countdown task alone, and a revoke failure just means both tasks run, which try:
- if delayed_task.state in ["PENDING", "RECEIVED"]:
- delayed_task.revoke() # Cancel the delayed task
-
- # Run immediately since the query already completed
collect_cohort_query_stats.apply_async(
args=[cohort_tag, cohort_id, start_time.isoformat(), history.id, query],
countdown=COHORT_STATS_COLLECTION_DELAY_SECONDS,
)
+
+ # Publish before revoking so a failure here leaves the countdown task in place.
+ if delayed_task.state in ["PENDING", "RECEIVED"]:
+ delayed_task.revoke()
except Exception as error:Add a test case where the first |
||||||||||
| if delayed_task.state in ["PENDING", "RECEIVED"]: | ||||||||||
| delayed_task.revoke() # Cancel the delayed task | ||||||||||
|
|
||||||||||
| # Run immediately since the query already completed | ||||||||||
| collect_cohort_query_stats.apply_async( | ||||||||||
| args=[cohort_tag, cohort_id, start_time.isoformat(), history.id, query], | ||||||||||
| countdown=COHORT_STATS_COLLECTION_DELAY_SECONDS, | ||||||||||
| ) | ||||||||||
| # Run immediately since the query already completed | ||||||||||
| collect_cohort_query_stats.apply_async( | ||||||||||
| args=[cohort_tag, cohort_id, start_time.isoformat(), history.id, query], | ||||||||||
| countdown=COHORT_STATS_COLLECTION_DELAY_SECONDS, | ||||||||||
| ) | ||||||||||
| except Exception as error: | ||||||||||
| logger.warning("cohort_stats_collection_scheduling_failed", cohort_id=cohort_id, error=str(error)) | ||||||||||
|
posthog[bot] marked this conversation as resolved.
|
||||||||||
|
|
||||||||||
| return result, end_time | ||||||||||
|
|
||||||||||
|
|
||||||||||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
suggestion: The name reads as an event handler that runs after something else invalidated the behavioral cache, but this function is the thing doing the invalidating. The_on_prefix indicates a reaction to an event, like_on_cohort_changedwhich runs when a cohort changes. Someone tracing where the behavioral cache gets cleared will scroll past this one._safe_save_cohort_state(cohort.py:1255) is the nearby name for this exact shape, a wrapper that calls the real thing, logs, and swallows. Nothing outside this file references the new name, so the rename touches the definition and the twotransaction.on_commitregistrations at dependencies.py:473 and dependencies.py:591.