diff --git a/.sampo/changesets/capture-retry-jitter.md b/.sampo/changesets/capture-retry-jitter.md new file mode 100644 index 00000000..08e170dd --- /dev/null +++ b/.sampo/changesets/capture-retry-jitter.md @@ -0,0 +1,5 @@ +--- +pypi/posthog: patch +--- + +Capture retry waits now vary randomly by up to 25%, so many clients do not retry at the same moment. diff --git a/docs/migration-7.x-to-8.0.md b/docs/migration-7.x-to-8.0.md index fdf51725..623d645d 100644 --- a/docs/migration-7.x-to-8.0.md +++ b/docs/migration-7.x-to-8.0.md @@ -99,7 +99,7 @@ When the whole request is over the billing limit, capture returns a `402` with n - In `sync_mode`, a failed `capture()` calls `on_error` and returns `None`. With `debug=True` it calls `on_error` and then re-raises the error. - If a capture inside `on_error` fails, the SDK logs the failure and does not call `on_error` again. - The SDK retries `408`, `500`, `502`, `503` and `504` responses and network errors. Other error statuses fail the batch at once, including `429` and the other 5xx codes. 7.x also retried `429` and every 5xx. Capture itself does not return `429`; a proxy in front of it can. -- Retries start at 100 ms and double each attempt, up to 30 seconds. A `Retry-After` header sets a minimum wait, up to 30 seconds. The `Consumer` default is 3 retries, down from 10. +- Retries start at 100 ms and double each attempt, up to 30 seconds. Each wait varies randomly by up to 25%, so many clients do not retry at the same moment. A `Retry-After` header sets a minimum wait, up to 30 seconds. The `Consumer` default is 3 retries, down from 10. - Logs never contain event content. The debug line for a queued event names the event and the lane, and the invalid timestamp warning no longer includes the value. To inspect events, use `before_send`. - A personal API key (`phx_...`) passed as the project API key disables the client and logs one error, as an empty key does. Capture rejects personal API keys, and the SDK no longer sends one with every request. diff --git a/posthog/capture_send.py b/posthog/capture_send.py index c9b24feb..6f0e487d 100644 --- a/posthog/capture_send.py +++ b/posthog/capture_send.py @@ -21,6 +21,7 @@ import json import logging +import random import time import zlib from dataclasses import dataclass @@ -88,6 +89,10 @@ # posthog-go. _BACKOFF_BASE_SECONDS = 0.1 +# Spread each backoff by up to a quarter, so clients refused together do not +# return together. +_BACKOFF_JITTER = 0.25 + @dataclass(frozen=True) class CaptureEventResult: @@ -413,18 +418,25 @@ def _parse_v1_response(res: "requests.Response") -> _V1ParsedResponse: return _V1ParsedResponse(status, False, retry_after, error_message=message) +def _draw_jitter() -> float: + return 1 - _BACKOFF_JITTER + random.random() * _BACKOFF_JITTER * 2 + + def _backoff(attempt_index: int, retry_after: Optional[float]) -> None: """Sleep before the next attempt. - Exponential backoff capped at :data:`_MAX_BACKOFF_SECONDS` is the base. When - the server sent a ``Retry-After`` it acts as a *minimum*, not a replacement: + Exponential backoff, spread by :data:`_BACKOFF_JITTER` and then capped at + :data:`_MAX_BACKOFF_SECONDS`, is the base. When the server sent a + ``Retry-After`` it acts as a *minimum*, not a replacement: the client waits the longer of the configured backoff and ``Retry-After``, so a small ``Retry-After`` never retries earlier than the normal schedule (matching posthog-go / posthog-rs). ``Retry-After`` is itself clamped to :data:`_MAX_BACKOFF_SECONDS`, so both sides share one ceiling and a hostile/buggy header can't park the consumer thread. """ - configured = min(_BACKOFF_BASE_SECONDS * 2**attempt_index, _MAX_BACKOFF_SECONDS) + configured = min( + _BACKOFF_BASE_SECONDS * 2**attempt_index * _draw_jitter(), _MAX_BACKOFF_SECONDS + ) clamped_retry_after = ( min(retry_after, _MAX_BACKOFF_SECONDS) if retry_after and retry_after > 0 else 0 ) diff --git a/posthog/test/test_capture_send.py b/posthog/test/test_capture_send.py index fc77a76b..e7072177 100644 --- a/posthog/test/test_capture_send.py +++ b/posthog/test/test_capture_send.py @@ -9,6 +9,7 @@ from parameterized import parameterized +from posthog import capture_send from posthog.capture_compression import CaptureCompression from posthog.capture_event import _build_v1_batch_body, _to_v1_event from posthog.capture_send import ( @@ -355,6 +356,7 @@ def setUp(self) -> None: sleep_patch = mock.patch("posthog.capture_send.time.sleep") self.sleep = sleep_patch.start() self.addCleanup(sleep_patch.stop) + _patch_no_jitter(self) def _run(self, batch, outcomes, **kwargs): stub = _PostV1Stub(outcomes) @@ -677,9 +679,19 @@ def test_message(self, _name, error, batch_size, expected) -> None: ) +def _patch_no_jitter(test: unittest.TestCase) -> None: + # 0.5 draws a jitter factor of exactly 1.0. + patch = mock.patch.object(capture_send.random, "random", return_value=0.5) + patch.start() + test.addCleanup(patch.stop) + + class TestBackoff(unittest.TestCase): """Directly exercises ``_backoff``'s Retry-After-as-minimum + cap policy.""" + def setUp(self) -> None: + _patch_no_jitter(self) + @parameterized.expand( [ # (attempt_index, retry_after, expected sleep seconds) @@ -700,3 +712,21 @@ def test_backoff(self, _name, attempt_index, retry_after, expected) -> None: _backoff(attempt_index, retry_after) sleep.assert_called_once() self.assertAlmostEqual(sleep.call_args.args[0], expected) + + @parameterized.expand( + [ + # (draw, attempt_index, retry_after, expected sleep seconds) + ("lowest_draw_shortens_by_a_quarter", 0.0, 1, None, 0.15), + ("highest_draw_lengthens_by_a_quarter", 1.0, 1, None, 0.25), + ("jittered_wait_still_capped", 1.0, 10, None, _MAX_BACKOFF_SECONDS), + ("jitter_never_shortens_retry_after", 0.0, 1, 0.2, 0.2), + ("jitter_can_lengthen_past_retry_after", 1.0, 1, 0.2, 0.25), + ] + ) + def test_jitter(self, _name, draw, attempt_index, retry_after, expected) -> None: + with ( + mock.patch.object(capture_send.random, "random", return_value=draw), + mock.patch("posthog.capture_send.time.sleep") as sleep, + ): + _backoff(attempt_index, retry_after) + self.assertAlmostEqual(sleep.call_args.args[0], expected)