From 482ffc2ad479faed7e743812ec511ee6b928dd6d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dean=20Qui=C3=B1anola?= Date: Thu, 12 Feb 2026 14:39:00 -0800 Subject: [PATCH] feat(logging): improve worker log formatting and retry UX - Configure uvicorn loggers to use same format as custom logs - Change retry attempts to 1-indexed (1 of 3, not 0/3) - Log retry failures as WARNING (not ERROR with traceback) for non-final attempts - Add visual section separators (=== 60 chars) around key startup phases - Add section header around mothership app import in lb_handler.py - Update tests to match new logging behavior --- src/lb_handler.py | 4 +++ src/logger.py | 12 +++++++++ src/unpack_volume.py | 42 +++++++++++++++++++++++++------- tests/unit/test_unpack_volume.py | 21 +++++++++++----- 4 files changed, 64 insertions(+), 15 deletions(-) diff --git a/src/lb_handler.py b/src/lb_handler.py index 69686e9..4967166 100644 --- a/src/lb_handler.py +++ b/src/lb_handler.py @@ -47,6 +47,9 @@ if is_mothership: # Mothership mode: Import user's FastAPI application + logger.info("=" * 60) + logger.info("IMPORTING APPLICATION") + logger.info("=" * 60) try: main_file = os.getenv("FLASH_MAIN_FILE", "main.py") app_variable = os.getenv("FLASH_APP_VARIABLE", "app") @@ -73,6 +76,7 @@ ) logger.info(f"Successfully imported FastAPI app '{app_variable}' from {main_file}") + logger.info("=" * 60) # Add /ping endpoint if not already present # Check if /ping route already exists to avoid adding a duplicate health check endpoint diff --git a/src/logger.py b/src/logger.py index 9f97000..417498e 100644 --- a/src/logger.py +++ b/src/logger.py @@ -57,6 +57,18 @@ def setup_logging( handler.setFormatter(logging.Formatter(fmt)) root_logger.addHandler(handler) + # Configure uvicorn loggers to use same format + formatter = logging.Formatter(fmt) + for logger_name in ["uvicorn", "uvicorn.error", "uvicorn.access"]: + uvicorn_logger = logging.getLogger(logger_name) + uvicorn_logger.setLevel(level) + # Suppress access logs unless DEBUG + if logger_name == "uvicorn.access" and level != logging.DEBUG: + uvicorn_logger.setLevel(logging.WARNING) + # Ensure handlers use our formatter + for uvicorn_handler in uvicorn_logger.handlers: + uvicorn_handler.setFormatter(formatter) + # When DEBUG is requested, silence the noisy module if level == logging.DEBUG: logging.getLogger("filelock").setLevel(logging.INFO) diff --git a/src/unpack_volume.py b/src/unpack_volume.py index 14d8706..78313a5 100644 --- a/src/unpack_volume.py +++ b/src/unpack_volume.py @@ -128,24 +128,48 @@ def maybe_unpack(): _UNPACKED = True logger.info("unpacking app from volume") + logger.info("=" * 60) last_error: Exception | None = None for attempt in range(DEFAULT_TARBALL_UNPACK_ATTEMPTS): + attempt_num = attempt + 1 # 1-indexed for display try: + logger.info( + "attempting to extract tarball (attempt %s of %s)...", + attempt_num, + DEFAULT_TARBALL_UNPACK_ATTEMPTS, + ) unpack_app_from_volume() + logger.info("=" * 60) _UNPACKED = True return except (FileNotFoundError, RuntimeError) as e: last_error = e - logger.error( - "failed to unpack app from volume (attempt %s/%s): %s", - attempt, - DEFAULT_TARBALL_UNPACK_ATTEMPTS, - e, - exc_info=True, - ) - if attempt < DEFAULT_TARBALL_UNPACK_ATTEMPTS: + is_final_attempt = attempt == DEFAULT_TARBALL_UNPACK_ATTEMPTS - 1 + + if is_final_attempt: + # Final attempt failed - log as ERROR with traceback + logger.error( + "failed to unpack app from volume (final attempt %s of %s): %s", + attempt_num, + DEFAULT_TARBALL_UNPACK_ATTEMPTS, + e, + exc_info=True, + ) + else: + # Expected retry - log as WARNING without traceback + logger.warning( + "unpack failed (attempt %s of %s): %s", + attempt_num, + DEFAULT_TARBALL_UNPACK_ATTEMPTS, + e, + ) + logger.info( + "waiting %s seconds before retry...", DEFAULT_TARBALL_UNPACK_INTERVAL + ) sleep(DEFAULT_TARBALL_UNPACK_INTERVAL) + + logger.info("=" * 60) raise RuntimeError( - f"failed to unpack app from volume after retries: {last_error}" + f"failed to unpack app from volume after {DEFAULT_TARBALL_UNPACK_ATTEMPTS} attempts: {last_error}" ) from last_error diff --git a/tests/unit/test_unpack_volume.py b/tests/unit/test_unpack_volume.py index b33943b..d79ae1e 100644 --- a/tests/unit/test_unpack_volume.py +++ b/tests/unit/test_unpack_volume.py @@ -417,7 +417,14 @@ def test_maybe_unpack_logs_info_on_start(self, mock_logger, mock_unpack, mock_sh maybe_unpack() - mock_logger.info.assert_called_once_with("unpacking app from volume") + # Verify the unpacking start message is logged + info_calls = [call[0][0] for call in mock_logger.info.call_args_list] + assert "unpacking app from volume" in info_calls + # Verify section separators and attempt message are present + assert "=" * 60 in info_calls + assert any( + "attempting to extract tarball" in str(call) for call in mock_logger.info.call_args_list + ) @patch("unpack_volume.sleep") @patch("unpack_volume._should_unpack_from_volume") @@ -434,8 +441,10 @@ 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] + # First 2 attempts should be logged as WARNING (not ERROR) + assert mock_logger.warning.call_count == 2 + # Final attempt should be logged as ERROR with traceback + assert mock_logger.error.call_count == 1 + # Verify error call includes expected message + assert "failed to unpack app from volume" in mock_logger.error.call_args[0][0] + assert "final attempt" in mock_logger.error.call_args[0][0]