feat(logging): improve worker log formatting and retry UX

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

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)

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

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]