Enhance Docker image pull logging with periodic progress updates (#11750)

Co-authored-by: openhands <openhands@all-hands.dev>

openhands/app_server/sandbox/docker_sandbox_service.py

@@ -192,7 +192,7 @@ class DockerSandboxService(SandboxService):
             except asyncio.CancelledError:
                 raise
             except Exception as exc:
-                _logger.info(f'Sandbox server not running: {exc}')
+                _logger.info(f'Sandbox server not running: {app_server_url} : {exc}')
                 sandbox_info.status = SandboxStatus.ERROR
                 sandbox_info.exposed_urls = None
                 sandbox_info.session_api_key = None

openhands/app_server/sandbox/docker_sandbox_spec_service.py

@@ -81,10 +81,49 @@ class DockerSandboxSpecServiceInjector(SandboxSpecServiceInjector):
             try:
                 docker_client.images.get(spec.id)
             except docker.errors.ImageNotFound:
-                _logger.info(f'⬇️ Pulling Docker Image: {spec.id}')
-                # Pull in a background thread to prevent locking up the main runloop
-                loop = asyncio.get_running_loop()
-                await loop.run_in_executor(None, docker_client.images.pull, spec.id)
-                _logger.info(f'⬇️ Finished Pulling Docker Image: {spec.id}')
+                _logger.info(f'⬇️  Pulling Docker Image: {spec.id}')
+                await self._pull_with_progress_logging(docker_client, spec.id)
+                _logger.info(f'⬇️  Finished Pulling Docker Image: {spec.id}')
         except docker.errors.APIError as exc:
             raise SandboxError(f'Error Getting Docker Image: {spec.id}') from exc
+
+    async def _pull_with_progress_logging(
+        self, docker_client: docker.DockerClient, image_id: str
+    ):
+        """Pull Docker image with periodic progress logging every 5 seconds."""
+        # Event to signal when pull is complete
+        pull_complete = asyncio.Event()
+
+        async def periodic_logger():
+            """Log progress message every 5 seconds until pull is complete."""
+            while not pull_complete.is_set():
+                try:
+                    await asyncio.wait_for(pull_complete.wait(), timeout=5.0)
+                    break  # Pull completed
+                except asyncio.TimeoutError:
+                    # 5 seconds elapsed, log progress message
+                    _logger.info(f'🔄 Downloading Docker Image: {image_id}...')
+
+        async def pull_image():
+            """Perform the actual Docker image pull."""
+            try:
+                loop = asyncio.get_running_loop()
+                await loop.run_in_executor(None, docker_client.images.pull, image_id)
+            finally:
+                pull_complete.set()
+
+        # Run both tasks concurrently
+        logger_task = asyncio.create_task(periodic_logger())
+        pull_task = asyncio.create_task(pull_image())
+
+        try:
+            # Wait for pull to complete
+            await pull_task
+        finally:
+            # Ensure logger task is cancelled if still running
+            if not logger_task.done():
+                logger_task.cancel()
+                try:
+                    await logger_task
+                except asyncio.CancelledError:
+                    pass

tests/unit/app_server/test_docker_sandbox_spec_service_injector.py

@@ -447,3 +447,85 @@ class TestDockerSandboxSpecServiceInjector:
         # Verify no Docker operations were performed
         mock_get_docker_client.assert_not_called()
         mock_docker_client.images.get.assert_not_called()
+
+    @patch('openhands.app_server.sandbox.docker_sandbox_spec_service.get_docker_client')
+    @patch('openhands.app_server.sandbox.docker_sandbox_spec_service._logger')
+    async def test_pull_with_progress_logging(
+        self, mock_logger, mock_get_docker_client, sample_spec
+    ):
+        """Test that periodic progress logging occurs during image pull."""
+        # Setup
+        mock_docker_client = MagicMock()
+        mock_get_docker_client.return_value = mock_docker_client
+        mock_docker_client.images.get.side_effect = ImageNotFound('Image not found')
+
+        # Create a future that will be resolved after some delay to simulate slow pull
+        pull_future = asyncio.Future()
+
+        async def delayed_pull_completion():
+            # Wait for multiple logging intervals to pass
+            await asyncio.sleep(12)  # 12 seconds = 2 logging intervals (5s each)
+            pull_future.set_result(MagicMock())
+
+        # Start the delayed completion task
+        asyncio.create_task(delayed_pull_completion())
+
+        # Mock the executor to return our delayed future
+        with patch('asyncio.get_running_loop') as mock_get_loop:
+            mock_loop = MagicMock()
+            mock_get_loop.return_value = mock_loop
+            mock_loop.run_in_executor.return_value = pull_future
+
+            injector = DockerSandboxSpecServiceInjector()
+
+            # Execute
+            await injector.pull_spec_if_missing(sample_spec)
+
+            # Verify that progress logging occurred
+            # Should have initial pull message, progress messages, and completion message
+            progress_calls = [
+                call
+                for call in mock_logger.info.call_args_list
+                if '🔄 Downloading Docker Image:' in str(call)
+            ]
+
+            # Should have at least 2 progress log messages (every 5 seconds for 12 seconds)
+            assert len(progress_calls) >= 2
+
+            # Verify the progress message format
+            for call in progress_calls:
+                assert '🔄 Downloading Docker Image: test-image:latest...' in str(call)
+
+    @patch('openhands.app_server.sandbox.docker_sandbox_spec_service.get_docker_client')
+    @patch('openhands.app_server.sandbox.docker_sandbox_spec_service._logger')
+    async def test_pull_with_progress_logging_fast_pull(
+        self, mock_logger, mock_get_docker_client, sample_spec
+    ):
+        """Test that no progress logging occurs for fast pulls (< 5 seconds)."""
+        # Setup
+        mock_docker_client = MagicMock()
+        mock_get_docker_client.return_value = mock_docker_client
+        mock_docker_client.images.get.side_effect = ImageNotFound('Image not found')
+
+        # Mock fast pull (completes immediately)
+        with patch('asyncio.get_running_loop') as mock_get_loop:
+            mock_loop = MagicMock()
+            mock_get_loop.return_value = mock_loop
+            fast_future = asyncio.Future()
+            fast_future.set_result(MagicMock())
+            mock_loop.run_in_executor.return_value = fast_future
+
+            injector = DockerSandboxSpecServiceInjector()
+
+            # Execute
+            await injector.pull_spec_if_missing(sample_spec)
+
+            # Verify that no progress logging occurred (only start/end messages)
+            progress_calls = [
+                call
+                for call in mock_logger.info.call_args_list
+                if '🔄 Downloading Docker Image:' in str(call)
+            ]
+
+            # Should have no progress log messages for fast pulls
+            assert len(progress_calls) == 0