From cdd8311a7b2d0eea7e46a7c034e76a759daa2077 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dean=20Qui=C3=B1anola?= Date: Sun, 18 Oct 2026 22:27:43 -0700 Subject: [PATCH] perf(unpack): poll for the build artifact under a deadline When the artifact was not on the volume at container start, maybe_unpack slept a fixed 30s before retrying, even if the artifact landed a moment later. On a measured RTX 4090 cold start this was ~32s of a ~38s in-container start. - Retry every 0.5s until a 60s deadline (same worst case as 3 x 30s) - Retry extraction errors too; a partially written tarball fails to extract - Log the wait once and the failure once, instead of an error per attempt Linear: SLS-812 --- src/constants.py | 8 ++-- src/unpack_volume.py | 70 ++++++++++++++++++++++---------- tests/unit/test_unpack_volume.py | 68 ++++++++++++++++++++++++++----- 3 files changed, 111 insertions(+), 35 deletions(-) diff --git a/src/constants.py b/src/constants.py index d8dc2a6..6d05888 100644 --- a/src/constants.py +++ b/src/constants.py @@ -46,10 +46,10 @@ DEFAULT_ENDPOINT_TIMEOUT = 300 """Default timeout in seconds for cross-endpoint HTTP requests.""" -DEFAULT_TARBALL_UNPACK_ATTEMPTS = 3 -"""Number of times the Flash-deployed endpoint will attempt to unpack the worker-flash tarball from mounted volume.""" -DEFAULT_TARBALL_UNPACK_INTERVAL = 30 -"""Time in seconds the Flash-deployed endpoint will wait between tarball unpack attempts.""" +DEFAULT_TARBALL_UNPACK_TIMEOUT = 60 +"""Time in seconds the Flash-deployed endpoint will keep retrying the tarball unpack before giving up.""" +DEFAULT_TARBALL_UNPACK_POLL_INTERVAL = 0.5 +"""Time in seconds between tarball unpack attempts. Kept short because the artifact can land just after container start.""" # Dependency Recovery Configuration MAX_IMPORT_RECOVERY_ATTEMPTS = 3 diff --git a/src/unpack_volume.py b/src/unpack_volume.py index 139d08e..06a0ff9 100644 --- a/src/unpack_volume.py +++ b/src/unpack_volume.py @@ -6,13 +6,13 @@ import tarfile import threading from pathlib import Path -from time import sleep +from time import monotonic, sleep from constants import ( DEFAULT_APP_DIR, DEFAULT_ARTIFACT_PATH, - DEFAULT_TARBALL_UNPACK_ATTEMPTS, - DEFAULT_TARBALL_UNPACK_INTERVAL, + DEFAULT_TARBALL_UNPACK_POLL_INTERVAL, + DEFAULT_TARBALL_UNPACK_TIMEOUT, ) from manifest_reconciliation import is_flash_deployment @@ -127,24 +127,52 @@ def maybe_unpack(): return logger.info("unpacking app from volume") + _unpack_before_deadline() + _UNPACKED = True - last_error: Exception | None = None - for attempt in range(DEFAULT_TARBALL_UNPACK_ATTEMPTS): - try: - unpack_app_from_volume() - _UNPACKED = True - return - except (FileNotFoundError, RuntimeError) as e: - last_error = e - logger.error( - "failed to unpack app from volume (attempt %s/%s): %s", - attempt + 1, - DEFAULT_TARBALL_UNPACK_ATTEMPTS, + +def _unpack_before_deadline() -> None: + """Retry the unpack at a short interval until it succeeds or the deadline passes. + + The artifact can land on the volume just after the container starts, so a + short poll picks it up within a fraction of a second instead of after a + long fixed sleep. Extraction errors are retried too, since a partially + written tarball fails to extract. + + Raises: + RuntimeError: the unpack did not succeed before the deadline; the last + error is chained. + """ + started = monotonic() + deadline = started + DEFAULT_TARBALL_UNPACK_TIMEOUT + last_error: Exception | None = None + while True: + try: + unpack_app_from_volume() + except (FileNotFoundError, RuntimeError) as e: + if last_error is None: + logger.warning( + "artifact not ready, retrying every %ss for up to %ss: %s", + DEFAULT_TARBALL_UNPACK_POLL_INTERVAL, + DEFAULT_TARBALL_UNPACK_TIMEOUT, e, - exc_info=True, ) - if attempt < DEFAULT_TARBALL_UNPACK_ATTEMPTS - 1: - sleep(DEFAULT_TARBALL_UNPACK_INTERVAL) - raise RuntimeError( - f"failed to unpack app from volume after retries: {last_error}" - ) from last_error + last_error = e + else: + if last_error is not None: + logger.info("artifact unpacked after %.1fs of retries", monotonic() - started) + return + + if monotonic() >= deadline: + break + sleep(DEFAULT_TARBALL_UNPACK_POLL_INTERVAL) + + logger.error( + "failed to unpack app from volume after %ss: %s", + DEFAULT_TARBALL_UNPACK_TIMEOUT, + last_error, + exc_info=last_error, + ) + raise RuntimeError( + f"failed to unpack app from volume after retries: {last_error}" + ) from last_error diff --git a/tests/unit/test_unpack_volume.py b/tests/unit/test_unpack_volume.py index f37c7aa..ada6cb6 100644 --- a/tests/unit/test_unpack_volume.py +++ b/tests/unit/test_unpack_volume.py @@ -349,6 +349,30 @@ def test_should_not_unpack_when_disabled_with_mixed_case(self): assert _should_unpack_from_volume() is False +class FakeClock: + """Monotonic clock that only advances when sleep() is called.""" + + def __init__(self) -> None: + self.now = 0.0 + + def monotonic(self) -> float: + return self.now + + def sleep(self, seconds: float) -> None: + self.now += seconds + + +@pytest.fixture +def fake_clock(): + """Run maybe_unpack's retry loop against a fake clock instead of real time.""" + clock = FakeClock() + with ( + patch("unpack_volume.monotonic", clock.monotonic), + patch("unpack_volume.sleep", clock.sleep), + ): + yield clock + + class TestMaybeUnpack: """Test idempotency and error handling of maybe_unpack.""" @@ -396,10 +420,9 @@ def test_maybe_unpack_skips_when_should_not_unpack(self, mock_unpack, mock_shoul mock_should_unpack.assert_called_once() mock_unpack.assert_not_called() - @patch("unpack_volume.sleep") @patch("unpack_volume._should_unpack_from_volume") @patch("unpack_volume.unpack_app_from_volume") - def test_maybe_unpack_propagates_exceptions(self, mock_unpack, mock_should_unpack, mock_sleep): + def test_maybe_unpack_propagates_exceptions(self, mock_unpack, mock_should_unpack, fake_clock): """Test that exceptions during unpacking are propagated.""" mock_should_unpack.return_value = True mock_unpack.side_effect = FileNotFoundError("Artifact not found") @@ -407,6 +430,33 @@ def test_maybe_unpack_propagates_exceptions(self, mock_unpack, mock_should_unpac with pytest.raises(RuntimeError, match="failed to unpack app from volume"): maybe_unpack() + @patch("unpack_volume._should_unpack_from_volume") + @patch("unpack_volume.unpack_app_from_volume") + def test_maybe_unpack_gives_up_at_deadline(self, mock_unpack, mock_should_unpack, fake_clock): + """A missing artifact is retried until the deadline, then the last error is chained.""" + mock_should_unpack.return_value = True + mock_unpack.side_effect = FileNotFoundError("artifact not found") + + with pytest.raises(RuntimeError) as exc_info: + maybe_unpack() + + assert isinstance(exc_info.value.__cause__, FileNotFoundError) + assert 60 <= fake_clock.now <= 61 + + @patch("unpack_volume._should_unpack_from_volume") + @patch("unpack_volume.unpack_app_from_volume") + def test_maybe_unpack_picks_up_late_artifact_promptly(self, mock_unpack, mock_should_unpack): + """An artifact that lands just after container start is unpacked without a long wait.""" + mock_should_unpack.return_value = True + mock_unpack.side_effect = [FileNotFoundError("artifact not found"), True] + waited: list[float] = [] + + with patch("unpack_volume.sleep", side_effect=waited.append): + maybe_unpack() + + assert mock_unpack.call_count == 2 + assert sum(waited) <= 1.0 + @patch("unpack_volume._should_unpack_from_volume") @patch("unpack_volume.unpack_app_from_volume") @patch("unpack_volume.logger") @@ -419,14 +469,13 @@ def test_maybe_unpack_logs_info_on_start(self, mock_logger, mock_unpack, mock_sh mock_logger.info.assert_called_once_with("unpacking app from volume") - @patch("unpack_volume.sleep") @patch("unpack_volume._should_unpack_from_volume") @patch("unpack_volume.unpack_app_from_volume") @patch("unpack_volume.logger") def test_maybe_unpack_logs_error_on_failure( - self, mock_logger, mock_unpack, mock_should_unpack, mock_sleep + self, mock_logger, mock_unpack, mock_should_unpack, fake_clock ): - """Test that errors are logged when unpacking fails.""" + """The wait is logged once when it starts, and the failure once at the deadline.""" mock_should_unpack.return_value = True error_msg = "Extraction failed" mock_unpack.side_effect = RuntimeError(error_msg) @@ -434,8 +483,7 @@ def test_maybe_unpack_logs_error_on_failure( with pytest.raises(RuntimeError, match="failed to unpack app from volume"): maybe_unpack() - # Error should be logged once per retry attempt (3 total) - assert mock_logger.error.call_count == 3 - # Verify all error calls include the expected message - for call in mock_logger.error.call_args_list: - assert "failed to unpack app from volume" in call[0][0] + assert mock_unpack.call_count > 3 + assert mock_logger.warning.call_count == 1 + assert mock_logger.error.call_count == 1 + assert "failed to unpack app from volume" in mock_logger.error.call_args[0][0]