diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 969f1c6da..ea97a056b 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -131,6 +131,7 @@ jobs: - tests/mock_vws/test_model_target_retries.py - tests/mock_vws/vumark_generation_api - tests/mock_vws/test_vumark_generation_failure.py + - tests/mock_vws/test_real_vws_retries.py - tests/mock_vws/test_target_setup_retries.py - tests/mock_vws/test_target_validators.py - tests/mock_vws/requests_mock diff --git a/tests/mock_vws/fixtures/api_contract.py b/tests/mock_vws/fixtures/api_contract.py index 62dd56cd4..b9f32762b 100644 --- a/tests/mock_vws/fixtures/api_contract.py +++ b/tests/mock_vws/fixtures/api_contract.py @@ -19,7 +19,7 @@ from tests.mock_vws.utils import Endpoint, ModelTargetEndpoint from tests.mock_vws.utils.retries import ( RETRY_ON_TARGET_NOT_YET_VISIBLE, - RETRY_ON_TRANSIENT_VWS_FAILURE, + retry_transient_vws_failures, ) # The number of targets to add before giving up on getting one which @@ -84,7 +84,7 @@ def inactive_cloud_reco_client( @beartype -@RETRY_ON_TRANSIENT_VWS_FAILURE +@retry_transient_vws_failures def _add_target(*, vws_client: VWS, image: io.BytesIO) -> str: """Add a target, which is then in the processing state. @@ -107,7 +107,7 @@ def _add_target(*, vws_client: VWS, image: io.BytesIO) -> str: @beartype -@RETRY_ON_TRANSIENT_VWS_FAILURE +@retry_transient_vws_failures @RETRY_ON_TARGET_NOT_YET_VISIBLE def _get_processed_target( *, vws_client: VWS, target_id_: str diff --git a/tests/mock_vws/fixtures/real_vws_retries.py b/tests/mock_vws/fixtures/real_vws_retries.py new file mode 100644 index 000000000..22501cd37 --- /dev/null +++ b/tests/mock_vws/fixtures/real_vws_retries.py @@ -0,0 +1,106 @@ +"""Bounded retry scheduling for real Vuforia fixture operations. + +At most ten attempts are scheduled within 120 seconds of the first attempt. +A retry cannot interrupt an in-flight client request or its processing poll. +Valid Retry-After values are honored, even when that means giving up because +no retry fits the budget. Without one, full jitter spreads retries over an +exponentially increasing interval, starting at one second and capped at 30. +""" + +import datetime +import logging +from email.utils import parsedate_to_datetime +from http import HTTPStatus + +from beartype import beartype +from tenacity import RetryCallState, Retrying +from tenacity.retry import retry_if_exception_type +from tenacity.stop import stop_after_attempt, stop_before_delay +from tenacity.wait import wait_random_exponential +from vws.exceptions.vws_exceptions import TooManyRequestsError + +from tests.mock_vws.utils.retries import ( + TRANSIENT_VWS_EXCEPTIONS, + TRANSIENT_VWS_RETRY_ATTEMPTS, +) + +RETRY_BUDGET_SECONDS = 120 +_LOGGER = logging.getLogger(name=__name__) +_MAX_DELAY_DIGITS = 9 +_FALLBACK_WAIT = wait_random_exponential(multiplier=1, max=30) + + +@beartype +def _retry_after_seconds( + *, value: str, now: datetime.datetime +) -> float | None: + """Read HTTP delay-seconds or an HTTP-date, rejecting malformed values.""" + value = value.strip() + if value.isascii() and value.isdecimal(): + value = value.lstrip("0") + if value == "": + return 0.0 + # Longer values exceed any useful retry deadline. Avoid integer + # conversion limits and float overflow for external header values. + if len(value) > _MAX_DELAY_DIGITS: + return float("inf") + return float(value) + try: + retry_at = parsedate_to_datetime(data=value) + except ValueError, TypeError, OverflowError: + return None + if retry_at.tzinfo is None: + return None + return max(0.0, (retry_at - now).total_seconds()) + + +@beartype +def wait_for_real_vws(retry_state: RetryCallState) -> float: + """Wait for the server's delay, otherwise use capped full jitter.""" + assert retry_state.outcome is not None + error = retry_state.outcome.exception() + if isinstance(error, TooManyRequestsError): + for name, value in error.response.headers.items(): + if name.casefold() == "retry-after": + delay = _retry_after_seconds( + value=value, + now=datetime.datetime.now(tz=datetime.UTC), + ) + if delay is not None: + return delay + return _FALLBACK_WAIT(retry_state=retry_state) + + +@beartype +def _log_retry(retry_state: RetryCallState) -> None: + """Log timing and error type without request headers or + credentials. + """ + assert retry_state.outcome is not None + assert retry_state.next_action is not None + error = retry_state.outcome.exception() + status = ( + HTTPStatus.TOO_MANY_REQUESTS + if isinstance(error, TooManyRequestsError) + else None + ) + _LOGGER.warning( + "Retrying real Vuforia operation after attempt %d: " + "%s (status %s), delay %.3fs", + retry_state.attempt_number, + type(error).__name__, + status, + retry_state.next_action.sleep, + ) + + +REAL_VWS_RETRYING = Retrying( + retry=retry_if_exception_type(exception_types=TRANSIENT_VWS_EXCEPTIONS), + stop=( + stop_after_attempt(max_attempt_number=TRANSIENT_VWS_RETRY_ATTEMPTS) + | stop_before_delay(max_delay=RETRY_BUDGET_SECONDS) + ), + wait=wait_for_real_vws, + before_sleep=_log_retry, + reraise=True, +) diff --git a/tests/mock_vws/fixtures/vuforia_backends.py b/tests/mock_vws/fixtures/vuforia_backends.py index fae9bce5c..e5f6e67a0 100644 --- a/tests/mock_vws/fixtures/vuforia_backends.py +++ b/tests/mock_vws/fixtures/vuforia_backends.py @@ -42,6 +42,7 @@ get_real_inactive_vumark_database, get_real_vumark_database, ) +from tests.mock_vws.fixtures.real_vws_retries import REAL_VWS_RETRYING from tests.mock_vws.utils.backend_capabilities import BackendCapabilities from tests.mock_vws.utils.cloud_databases import AddCloudDatabase from tests.mock_vws.utils.model_target_response_policy import ( @@ -56,7 +57,8 @@ ) from tests.mock_vws.utils.retries import ( RETRY_ON_TARGET_STILL_PROCESSING, - RETRY_ON_TRANSIENT_VWS_FAILURE, + retry_transient_vws_failures, + retrying_vws_requests, ) from tests.mock_vws.utils.unrouted_requests import ( UnroutedRequests, @@ -99,7 +101,7 @@ def running_in_memory_mock() -> MockVWS: @beartype -@RETRY_ON_TRANSIENT_VWS_FAILURE +@retry_transient_vws_failures def _delete_all_targets( *, database_keys: CloudDatabase, base_vws_url: str ) -> None: @@ -194,10 +196,13 @@ def _enable_use_real_vuforia( assert bool(vumark_vuforia_database) assert bool(inactive_vumark_database) del base_vwq_url - _delete_all_targets( - database_keys=working_database, base_vws_url=base_vws_url - ) - with handling_request_timeouts(handler=_handle_real_request_timeout): + with ( + retrying_vws_requests(retrying=REAL_VWS_RETRYING), + handling_request_timeouts(handler=_handle_real_request_timeout), + ): + _delete_all_targets( + database_keys=working_database, base_vws_url=base_vws_url + ) yield diff --git a/tests/mock_vws/test_real_vws_retries.py b/tests/mock_vws/test_real_vws_retries.py new file mode 100644 index 000000000..f706d5df4 --- /dev/null +++ b/tests/mock_vws/test_real_vws_retries.py @@ -0,0 +1,320 @@ +"""Real-service retry timing and adapter-policy isolation.""" + +import datetime +import random +from unittest.mock import patch + +import pytest +from freezegun import freeze_time +from requests.exceptions import ReadTimeout +from tenacity import RetryCallState +from tenacity.stop import stop_after_attempt +from tenacity.wait import wait_none +from vws.exceptions.vws_exceptions import ( + TooManyRequestsError, + UnknownTargetError, +) +from vws.response import Response + +from mock_vws.database import CloudDatabase +from tests.mock_vws.fixtures.credentials import ( + InactiveVuMarkCloudDatabase, + VuMarkCloudDatabase, +) +from tests.mock_vws.fixtures.real_vws_retries import ( + REAL_VWS_RETRYING, + RETRY_BUDGET_SECONDS, + wait_for_real_vws, +) +from tests.mock_vws.fixtures.vuforia_backends import ( + _enable_use_real_vuforia, # pyright: ignore[reportPrivateUsage] +) +from tests.mock_vws.utils.retries import ( + TRANSIENT_VWS_RETRY_ATTEMPTS, + retry_transient_vws_failures, + retrying_vws_requests, +) + + +def _throttle(*, headers: dict[str, str]) -> TooManyRequestsError: + """Build a throttle carrying the original response details.""" + return TooManyRequestsError( + response=Response( + text="", + url="https://example.com/summary/target", + status_code=429, + headers={"x-envoy-ratelimited": "true", **headers}, + request_body=None, + tell_position=0, + content=b"", + ) + ) + + +def _state(*, error: Exception, attempt: int) -> RetryCallState: + """Build the failed attempt supplied to a Tenacity wait function.""" + state = RetryCallState( + retry_object=REAL_VWS_RETRYING, fn=None, args=(), kwargs={} + ) + state.attempt_number = attempt + state.set_exception(exc_info=(type(error), error, None)) + return state + + +@pytest.mark.parametrize( + argnames=("header", "expected"), + argvalues=[ + ("7", 7.0), + (" 7 ", 7.0), + ("0", 0.0), + ("00000000000000000000", 0.0), + ("Fri, 16 Oct 2026 12:00:07 GMT", 7.0), + ("Fri, 16 Oct 2026 11:00:00 GMT", 0.0), + ("99999999999999999999999999999", float("inf")), + ], +) +def test_retry_after(*, header: str, expected: float) -> None: + """Both header forms control the delay, including dates in the + past. + """ + state = _state(error=_throttle(headers={"rEtRy-AfTeR": header}), attempt=1) + with freeze_time(time_to_freeze="2026-10-16 12:00:00"): + assert wait_for_real_vws(retry_state=state) == expected + + +@pytest.mark.parametrize( + argnames="header", + argvalues=["", "invalid", "-1", "1.5", "NaN", "Fri, 16 Oct 2026 12:00:07"], +) +def test_malformed_header_uses_fallback(*, header: str) -> None: + """Malformed delay headers fall back to jitter.""" + expected_delay = 0.5 + state = _state(error=_throttle(headers={"Retry-After": header}), attempt=1) + with patch.object( + target=random, attribute="uniform", return_value=expected_delay + ): + assert wait_for_real_vws(retry_state=state) == expected_delay + + +@pytest.mark.parametrize( + argnames=("attempt", "upper"), + argvalues=[(1, 1), (2, 2), (5, 16), (6, 30), (10, 30)], +) +@pytest.mark.parametrize(argnames="throttle", argvalues=[True, False]) +def test_fallback_jitter_bounds( + *, attempt: int, upper: int, throttle: bool +) -> None: + """Missing delay headers and transport errors use exponential + jitter. + """ + error = _throttle(headers={}) if throttle else ReadTimeout("timeout") + expected_delay = 0.5 + state = _state(error=error, attempt=attempt) + with patch.object( + target=random, attribute="uniform", return_value=expected_delay + ) as uniform: + assert wait_for_real_vws(retry_state=state) == expected_delay + uniform.assert_called_once_with(0, upper) + + +def test_delay_larger_than_budget_surfaces_original_response() -> None: + """Do not truncate a server delay to squeeze in another attempt.""" + error = _throttle( + headers={"Retry-After": str(object=RETRY_BUDGET_SECONDS + 1)} + ) + with ( + patch.object(target=REAL_VWS_RETRYING, attribute="sleep") as sleep, + pytest.raises(expected_exception=TooManyRequestsError) as exc, + ): + _ = REAL_VWS_RETRYING(lambda: _raise(error=error)) + assert exc.value is error + assert exc.value.response is error.response + sleep.assert_not_called() + + +def _raise(*, error: Exception) -> None: + """Raise the supplied exception. + + Raises: + Exception: The exact supplied exception. + """ + raise error + + +def test_deadline_accounts_for_elapsed_time() -> None: + """No further attempt is scheduled when the delay no longer fits.""" + error = _throttle(headers={"Retry-After": "50"}) + sleeps: list[float] = [] + attempts = 0 + with freeze_time(time_to_freeze="2026-10-16 12:00:00") as frozen: + + def sleep(seconds: float) -> None: + """Advance the fake clock instead of actually sleeping.""" + sleeps.append(seconds) + _ = frozen.tick(delta=datetime.timedelta(seconds=seconds)) + + def send() -> None: + """Spend part of the deadline waiting for a server + response. + """ + nonlocal attempts + attempts += 1 + _ = frozen.tick(delta=datetime.timedelta(seconds=10)) + raise error + + with pytest.raises(expected_exception=TooManyRequestsError): + _ = REAL_VWS_RETRYING.copy(sleep=sleep)(send) + assert attempts == len(sleeps) + 1 + assert sleeps == [50.0] + + +def test_nested_operations_share_attempt_budget( + *, caplog: pytest.LogCaptureFixture +) -> None: + """Nested decorated helpers do not each start a ten-attempt loop.""" + attempts = 0 + error = _throttle(headers={"Authorization": "secret"}) + + @retry_transient_vws_failures + def inner() -> None: + """Always encounter a throttle.""" + nonlocal attempts + attempts += 1 + raise error + + @retry_transient_vws_failures + def outer() -> None: + """Call another decorated operation.""" + inner() + + with ( + retrying_vws_requests( + retrying=REAL_VWS_RETRYING.copy(wait=wait_none()) + ), + pytest.raises(expected_exception=TooManyRequestsError) as exc, + ): + outer() + assert exc.value is error + assert attempts == TRANSIENT_VWS_RETRY_ATTEMPTS + assert len(caplog.records) == TRANSIENT_VWS_RETRY_ATTEMPTS - 1 + assert "TooManyRequestsError" in caplog.text + assert "429" in caplog.text + assert "delay" in caplog.text + assert "secret" not in caplog.text + + +def test_scopes_restore_policy_after_exception() -> None: + """Nested scopes restore the preceding policy after a failure.""" + attempts = 0 + checkpoints: list[int] = [] + error = ReadTimeout("timeout") + + @retry_transient_vws_failures + def send() -> None: + """Count and fail each call.""" + nonlocal attempts + attempts += 1 + raise error + + with retrying_vws_requests( + retrying=REAL_VWS_RETRYING.copy( + wait=wait_none(), + stop=stop_after_attempt(max_attempt_number=2), + ) + ): + with ( + retrying_vws_requests( + retrying=REAL_VWS_RETRYING.copy( + wait=wait_none(), + stop=stop_after_attempt(max_attempt_number=1), + ) + ), + pytest.raises(expected_exception=ReadTimeout), + ): + send() + checkpoints.append(attempts) + with pytest.raises(expected_exception=ReadTimeout): + send() + checkpoints.append(attempts) + with pytest.raises(expected_exception=ReadTimeout): + send() + checkpoints.append(attempts) + assert checkpoints == [1, 3, 4] + + +def test_unknown_target_is_not_globally_transient() -> None: + """Only the known-target visibility helper may retry UnknownTarget.""" + error = UnknownTargetError(response=_throttle(headers={}).response) + with ( + patch.object(target=REAL_VWS_RETRYING, attribute="sleep") as sleep, + pytest.raises(expected_exception=UnknownTargetError), + ): + _ = REAL_VWS_RETRYING(lambda: _raise(error=error)) + sleep.assert_not_called() + + +def test_real_adapter_installs_policy_before_cleanup( + *, monkeypatch: pytest.MonkeyPatch +) -> None: + """The real adapter enables retries for setup and restores them on + exit. + """ + attempts = 0 + checkpoints: list[int] = [] + error = ReadTimeout("timeout") + + @retry_transient_vws_failures + def operation() -> None: + """Recover a single transient error under the installed policy.""" + nonlocal attempts + attempts += 1 + if attempts % 2 == 1: + raise error + + def cleanup(*, database_keys: CloudDatabase, base_vws_url: str) -> None: + """Check policy installation during the adapter's initial + cleanup. + """ + del database_keys, base_vws_url + operation() + + cloud = CloudDatabase() + vumark = VuMarkCloudDatabase( + target_manager_database_name="name", + server_access_key="key", + server_secret_key="secret", + target_id="target", + processing_target_id="processing", + ) + inactive = InactiveVuMarkCloudDatabase( + target_manager_database_name="inactive", + server_access_key="key", + server_secret_key="secret", + ) + with ( + patch( + target="tests.mock_vws.fixtures.vuforia_backends._delete_all_targets", + side_effect=cleanup, + ), + patch.object( + target=REAL_VWS_RETRYING, attribute="wait", new=wait_none() + ), + ): + setup = _enable_use_real_vuforia( + working_database=cloud, + inactive_cloud_database=cloud, + vumark_vuforia_database=vumark, + inactive_vumark_database=inactive, + monkeypatch=monkeypatch, + base_vws_url="https://example.com", + base_vwq_url="https://example.com", + ) + assert next(setup) is None + checkpoints.append(attempts) + operation() + checkpoints.append(attempts) + setup.close() + with pytest.raises(expected_exception=ReadTimeout): + operation() + checkpoints.append(attempts) + assert checkpoints == [2, 4, 5] diff --git a/tests/mock_vws/test_target_setup_retries.py b/tests/mock_vws/test_target_setup_retries.py index 2185dc34a..c0b1014fe 100644 --- a/tests/mock_vws/test_target_setup_retries.py +++ b/tests/mock_vws/test_target_setup_retries.py @@ -2,11 +2,13 @@ import io import time +from collections.abc import Generator from unittest.mock import call, patch import pytest from requests.exceptions import ReadTimeout from tenacity import RetryError +from tenacity.wait import wait_none from vws import VWS from vws.exceptions.vws_exceptions import ( TooManyRequestsError, @@ -18,7 +20,11 @@ from tests.mock_vws.fixtures.api_contract import ( _add_target_which_processed_successfully, # pyright: ignore[reportPrivateUsage] ) -from tests.mock_vws.utils.retries import TRANSIENT_VWS_RETRY_ATTEMPTS +from tests.mock_vws.fixtures.real_vws_retries import REAL_VWS_RETRYING +from tests.mock_vws.utils.retries import ( + TRANSIENT_VWS_RETRY_ATTEMPTS, + retrying_vws_requests, +) def _record(*, status: TargetStatuses) -> TargetStatusAndRecord: @@ -57,9 +63,18 @@ def _no_sleep(seconds: float) -> None: @pytest.fixture(autouse=True) -def fixture_no_sleep(*, monkeypatch: pytest.MonkeyPatch) -> None: - """Exercise the actual retry decorators without sleeping.""" +def fixture_no_sleep(*, monkeypatch: pytest.MonkeyPatch) -> Generator[None]: + """Exercise the real policy without sleeping, including visibility + waits. + + Yields: + ``None``, with real fixture retries enabled. + """ monkeypatch.setattr(target=time, name="sleep", value=_no_sleep) + with retrying_vws_requests( + retrying=REAL_VWS_RETRYING.copy(wait=wait_none()) + ): + yield @pytest.fixture(name="client") diff --git a/tests/mock_vws/utils/retries.py b/tests/mock_vws/utils/retries.py index c6e4826bd..2ebd3d5a7 100644 --- a/tests/mock_vws/utils/retries.py +++ b/tests/mock_vws/utils/retries.py @@ -1,10 +1,16 @@ """Helpers for retrying requests to VWS.""" +import contextlib +from collections.abc import Callable, Generator +from contextvars import ContextVar +from functools import wraps + +from beartype import beartype from requests.exceptions import ConnectionError as RequestsConnectionError from requests.exceptions import ConnectTimeout as RequestsConnectTimeout from requests.exceptions import ReadTimeout as RequestsReadTimeout from requests.exceptions import Timeout as RequestsTimeout -from tenacity import retry +from tenacity import Retrying, retry from tenacity.retry import retry_if_exception_type from tenacity.stop import stop_after_attempt from tenacity.wait import wait_fixed @@ -31,17 +37,50 @@ ) TRANSIENT_VWS_RETRY_ATTEMPTS = 10 -# We rely on pytest-retry for exceptions *during* tests. -# We use tenacity for exceptions *before* tests. -# See https://github.com/str0zzapreti/pytest-retry/issues/33. -RETRY_ON_TRANSIENT_VWS_FAILURE = retry( - retry=retry_if_exception_type(exception_types=TRANSIENT_VWS_EXCEPTIONS), - stop=stop_after_attempt(max_attempt_number=TRANSIENT_VWS_RETRY_ATTEMPTS), - wait=wait_fixed(wait=10), - reraise=True, +# Shared helpers send once unless an adapter supplies a retry policy. +# ContextVar requires a positional name at runtime. +_VWS_RETRYING: ContextVar[Retrying | None] = ContextVar( # type: ignore[call-arg] + "vws_retrying", + default=None, ) +@contextlib.contextmanager +@beartype +def retrying_vws_requests(*, retrying: Retrying) -> Generator[None]: + """Install an adapter's fixture retry policy for this scope. + + Yields: + ``None``, with the policy active and its predecessor restored on exit. + """ + token = _VWS_RETRYING.set(retrying) + try: + yield + finally: + _VWS_RETRYING.reset(token) + + +@beartype +def retry_transient_vws_failures[**P, T]( + operation: Callable[P, T], +) -> Callable[P, T]: + """Apply the adapter's policy without multiplying nested retry budgets.""" + + @wraps(wrapped=operation) + def wrapped(*args: P.args, **kwargs: P.kwargs) -> T: + """Run an operation under at most one transient retry loop.""" + retrying = _VWS_RETRYING.get() + if retrying is None: + return operation(*args, **kwargs) + token = _VWS_RETRYING.set(None) + try: + return retrying.copy()(operation, *args, **kwargs) + finally: + _VWS_RETRYING.reset(token) + + return wrapped + + # Real Vuforia sometimes reports a target which it has just created as # unknown, because the target is not yet visible to the read path. #