diff --git a/openhands/app_server/sandbox/docker_sandbox_service.py b/openhands/app_server/sandbox/docker_sandbox_service.py index 0f6ea51916..1e2505a85e 100644 --- a/openhands/app_server/sandbox/docker_sandbox_service.py +++ b/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 diff --git a/openhands/app_server/sandbox/docker_sandbox_spec_service.py b/openhands/app_server/sandbox/docker_sandbox_spec_service.py index cd42cbfe70..7504cec537 100644 --- a/openhands/app_server/sandbox/docker_sandbox_spec_service.py +++ b/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 diff --git a/tests/unit/app_server/test_docker_sandbox_spec_service_injector.py b/tests/unit/app_server/test_docker_sandbox_spec_service_injector.py index 1df987c56f..059cc27e8a 100644 --- a/tests/unit/app_server/test_docker_sandbox_spec_service_injector.py +++ b/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