diff --git a/jupyterlab_git/git.py b/jupyterlab_git/git.py index a4ae5e9e8..fc5b72c53 100644 --- a/jupyterlab_git/git.py +++ b/jupyterlab_git/git.py @@ -10,6 +10,7 @@ import shlex import shutil import subprocess +import time import traceback from enum import Enum, IntEnum from pathlib import Path @@ -55,6 +56,104 @@ execution_lock = tornado.locks.Lock() +async def call_subprocess_with_authentication( + cmdline: "List[str]", + username: "str", + password: "str", + cwd: "Optional[str]" = None, + env: "Optional[Dict[str, str]]" = None, + timeout: "float" = 20, +) -> "Tuple[int, str, str]": + """Call subprocess with authentication handling.""" + try: + p = pexpect.spawn( + cmdline[0], + cmdline[1:], + cwd=cwd, + env=env, + encoding="utf-8", + timeout=timeout, + ) + + # We expect a prompt from git + # In most of cases git will prompt for username and + # then for password + # In some cases (Bitbucket) username is included in + # remote URL, so git will not ask for username + i = await p.expect(["Username for .*: ", "Password for .*:"], async_=True) + if i == 0: # ask for username then password + p.sendline(username) + await p.expect("Password for .*:", async_=True) + p.sendline(password) + elif i == 1: # only ask for password + p.sendline(password) + + await p.expect(pexpect.EOF, async_=True) + response = p.before + + returncode = p.wait() + p.close() + return returncode, "", response + except pexpect.exceptions.EOF: # In case of pexpect failure + response = p.before + returncode = p.exitstatus + p.close() # close process + return returncode, "", response + except pexpect.exceptions.TIMEOUT: # Handle timeout + p.terminate(force=True) + p.close() + raise TimeoutError( + f"Git authentication timed out after {timeout} seconds: {' '.join(cmdline)}" + ) + except Exception as e: + # Ensure process is always closed on any exception + if p and p.isalive(): + p.terminate(force=True) + if p: + p.close() + raise e + + +def call_subprocess( + cmdline: "List[str]", + cwd: "Optional[str]" = None, + env: "Optional[Dict[str, str]]" = None, + timeout: "float" = 20, + is_binary=False, +) -> "Tuple[int, str, str]": + """Call subprocess with timeout and process cleanup.""" + process = subprocess.Popen( + cmdline, stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=cwd, env=env + ) + try: + output, error = process.communicate(timeout=timeout) + except subprocess.TimeoutExpired: + # Terminate the process gracefully + process.terminate() + try: + process.wait(timeout=5) + except subprocess.TimeoutExpired: + # Force kill if still alive after 5 seconds + process.kill() + process.wait() + get_logger().warning("Git command timed out: %s", cmdline) + raise TimeoutError( + f"Git command timed out after {timeout} seconds: {' '.join(cmdline)}" + ) + except OSError as e: + get_logger().warning("Failed to execute git command: %s", cmdline) + raise + + if is_binary: + return ( + process.returncode, + base64.encodebytes(output).decode("ascii"), + error.decode("utf-8"), + ) + else: + return (process.returncode, output.decode("utf-8"), error.decode("utf-8")) + + class State(IntEnum): """Git repository state.""" @@ -99,67 +198,6 @@ async def execute( (int, str, str): (return code, stdout, stderr) """ - async def call_subprocess_with_authentication( - cmdline: "List[str]", - username: "str", - password: "str", - cwd: "Optional[str]" = None, - env: "Optional[Dict[str, str]]" = None, - ) -> "Tuple[int, str, str]": - try: - p = pexpect.spawn( - cmdline[0], - cmdline[1:], - cwd=cwd, - env=env, - encoding="utf-8", - timeout=None, - ) - - # We expect a prompt from git - # In most of cases git will prompt for username and - # then for password - # In some cases (Bitbucket) username is included in - # remote URL, so git will not ask for username - i = await p.expect(["Username for .*: ", "Password for .*:"], async_=True) - if i == 0: # ask for username then password - p.sendline(username) - await p.expect("Password for .*:", async_=True) - p.sendline(password) - elif i == 1: # only ask for password - p.sendline(password) - - await p.expect(pexpect.EOF, async_=True) - response = p.before - - returncode = p.wait() - p.close() - return returncode, "", response - except pexpect.exceptions.EOF: # In case of pexpect failure - response = p.before - returncode = p.exitstatus - p.close() # close process - return returncode, "", response - - def call_subprocess( - cmdline: "List[str]", - cwd: "Optional[str]" = None, - env: "Optional[Dict[str, str]]" = None, - is_binary=is_binary, - ) -> "Tuple[int, str, str]": - process = subprocess.Popen( - cmdline, stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=cwd, env=env - ) - output, error = process.communicate() - if is_binary: - return ( - process.returncode, - base64.encodebytes(output).decode("ascii"), - error.decode("utf-8"), - ) - else: - return (process.returncode, output.decode("utf-8"), error.decode("utf-8")) - try: await execution_lock.acquire(timeout=datetime.timedelta(seconds=timeout)) except tornado.util.TimeoutError: @@ -183,11 +221,12 @@ def call_subprocess( password, cwd, env, + timeout, ) else: current_loop = tornado.ioloop.IOLoop.current() code, output, error = await current_loop.run_in_executor( - None, call_subprocess, cmdline, cwd, env + None, call_subprocess, cmdline, cwd, env, timeout, is_binary ) log_output = ( output[:MAX_LOG_OUTPUT] + "..." if len(output) > MAX_LOG_OUTPUT else output @@ -198,9 +237,13 @@ def call_subprocess( get_logger().debug( "Code: {}\nOutput: {}\nError: {}".format(code, log_output, log_error) ) + except TimeoutError as e: + # Handle our custom timeout errors + code, output, error = -1, "", str(e) + get_logger().warning("Git command timed out: %s - %s", cmdline, str(e)) except BaseException as e: code, output, error = -1, "", traceback.format_exc() - get_logger().warning("Fail to execute {!s}".format(cmdline), exc_info=True) + get_logger().warning("Failed to execute git command: %s", cmdline, exc_info=True) finally: execution_lock.release() @@ -228,8 +271,28 @@ def __init__(self, config=None): ) def __del__(self): + self._cleanup_processes() + + def _cleanup_processes(self): + """Clean up any running processes managed by this Git instance.""" if self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS: - self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.terminate() + try: + if self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.poll() is None: + self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.terminate() + try: + self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.wait(timeout=5) + except subprocess.TimeoutExpired: + self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.kill() + try: + self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.wait(timeout=1) + except subprocess.TimeoutExpired: + # If kill() doesn't work within 1 second, just give up + pass + get_logger().debug("Git credential cache daemon process (PID: %s) cleaned up successfully", self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS.pid) + except Exception as e: + get_logger().warning("Failed to cleanup credential cache daemon: %s", e) + finally: + self._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = None async def __execute( self, diff --git a/jupyterlab_git/tests/test_subprocess_timeout.py b/jupyterlab_git/tests/test_subprocess_timeout.py new file mode 100644 index 000000000..964642b81 --- /dev/null +++ b/jupyterlab_git/tests/test_subprocess_timeout.py @@ -0,0 +1,357 @@ +""" +Tests for subprocess timeout handling and process cleanup functionality. + +This module tests the improvements made to git.py for: +1. Subprocess timeout handling with graceful termination +2. Process cleanup with terminate → wait → kill pattern +3. Credential daemon cleanup with proper timeout handling +4. Logging behavior for timeout and error scenarios +""" + +import asyncio +import logging +import subprocess +from unittest.mock import AsyncMock, MagicMock, Mock, patch +from pathlib import Path + +import pexpect +import pytest + +from jupyterlab_git.git import Git, call_subprocess_with_authentication + + +class TestSubprocessTimeout: + """Test subprocess timeout handling in call_subprocess function.""" + + def test_subprocess_timeout_terminates_gracefully(self): + """Test that subprocess timeout follows terminate → wait → kill pattern.""" + with patch("subprocess.Popen") as mock_popen: + mock_process = MagicMock() + mock_process.communicate.side_effect = subprocess.TimeoutExpired( + cmd=["git", "status"], timeout=5 + ) + mock_process.wait.return_value = 0 # Graceful termination + mock_popen.return_value = mock_process + + # Import after patching to ensure we get the patched version + from jupyterlab_git.git import call_subprocess + + with pytest.raises( + TimeoutError, match="Git command timed out after 5 seconds" + ): + call_subprocess(["git", "status"], timeout=5) + + # Verify graceful termination sequence + mock_process.terminate.assert_called_once() + mock_process.wait.assert_called_once_with(timeout=5) + mock_process.kill.assert_not_called() + + def test_subprocess_timeout_force_kills_after_wait_timeout(self): + """Test that subprocess force kills if process doesn't terminate gracefully.""" + with patch("subprocess.Popen") as mock_popen: + mock_process = MagicMock() + mock_process.communicate.side_effect = subprocess.TimeoutExpired( + cmd=["git", "status"], timeout=5 + ) + # First wait() call (with timeout=5) should timeout + # Second wait() call (without timeout) should succeed + mock_process.wait.side_effect = [ + subprocess.TimeoutExpired(cmd=["git", "status"], timeout=5), + 0, # Second call succeeds + ] + mock_popen.return_value = mock_process + + from jupyterlab_git.git import call_subprocess + + with pytest.raises( + TimeoutError, match="Git command timed out after 5 seconds" + ): + call_subprocess(["git", "status"], timeout=5) + + # Verify force kill sequence + mock_process.terminate.assert_called_once() + assert mock_process.wait.call_count == 2 + mock_process.wait.assert_any_call(timeout=5) + mock_process.kill.assert_called_once() + + +class TestPexpectTimeout: + """Test pexpect timeout handling in call_subprocess_with_authentication.""" + + @pytest.mark.asyncio + async def test_pexpect_timeout_uses_proper_timeout_parameter(self): + """Test that pexpect.spawn uses the timeout parameter correctly.""" + with patch("pexpect.spawn") as mock_spawn: + mock_process = MagicMock() + mock_process.expect.side_effect = pexpect.exceptions.TIMEOUT("timeout") + mock_spawn.return_value = mock_process + + with pytest.raises( + TimeoutError, match="Git authentication timed out after 10 seconds" + ): + await call_subprocess_with_authentication( + ["git", "clone", "https://example.com/repo.git"], + username="user", + password="pass", + timeout=10, + ) + + # Verify pexpect.spawn was called with correct timeout + mock_spawn.assert_called_once() + call_args = mock_spawn.call_args + assert call_args[1]["timeout"] == 10 + + @pytest.mark.asyncio + async def test_pexpect_timeout_cleans_up_process(self): + """Test that pexpect timeout properly cleans up the process.""" + with patch("pexpect.spawn") as mock_spawn: + mock_process = MagicMock() + mock_process.expect.side_effect = pexpect.exceptions.TIMEOUT("timeout") + mock_spawn.return_value = mock_process + + with pytest.raises(TimeoutError): + await call_subprocess_with_authentication( + ["git", "clone", "https://example.com/repo.git"], + username="user", + password="pass", + timeout=10, + ) + + # Verify process cleanup + mock_process.terminate.assert_called_once_with(force=True) + mock_process.close.assert_called_once() + + @pytest.mark.asyncio + async def test_pexpect_exception_cleanup(self): + """Test that any exception in pexpect properly cleans up the process.""" + with patch("pexpect.spawn") as mock_spawn: + mock_process = MagicMock() + mock_process.isalive.return_value = True + mock_process.expect.side_effect = RuntimeError("Unexpected error") + mock_spawn.return_value = mock_process + + with pytest.raises(RuntimeError, match="Unexpected error"): + await call_subprocess_with_authentication( + ["git", "clone", "https://example.com/repo.git"], + username="user", + password="pass", + timeout=10, + ) + + # Verify process cleanup on exception + mock_process.terminate.assert_called_once_with(force=True) + mock_process.close.assert_called_once() + + +class TestGitCredentialDaemonCleanup: + """Test Git credential daemon cleanup functionality.""" + + def test_credential_daemon_cleanup_on_destruction(self): + """Test that credential daemon is cleaned up when Git instance is destroyed.""" + with patch("subprocess.Popen") as mock_popen: + mock_daemon = MagicMock() + mock_daemon.poll.return_value = None # Process is still running + mock_daemon.wait.return_value = 0 # Graceful termination + mock_daemon.pid = 12345 + + git = Git() + git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = mock_daemon + + # Trigger cleanup + git._cleanup_processes() + + # Verify graceful termination sequence + mock_daemon.terminate.assert_called_once() + mock_daemon.wait.assert_called_once_with(timeout=5) + mock_daemon.kill.assert_not_called() + + def test_credential_daemon_force_kill_after_timeout(self, caplog): + """Test that credential daemon is force killed if it doesn't terminate gracefully.""" + with patch("subprocess.Popen") as mock_popen: + mock_daemon = MagicMock() + mock_daemon.poll.return_value = None # Process is still running + # First wait() call (with timeout=5) should timeout + # Second wait() call (with timeout=1) should also timeout to test the fallback + mock_daemon.wait.side_effect = [ + subprocess.TimeoutExpired(cmd=["git-credential-cache"], timeout=5), + subprocess.TimeoutExpired(cmd=["git-credential-cache"], timeout=1), + ] + mock_daemon.pid = 12345 + + git = Git() + git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = mock_daemon + + git._cleanup_processes() + + # Verify force kill sequence + mock_daemon.terminate.assert_called_once() + assert mock_daemon.wait.call_count == 2 + mock_daemon.wait.assert_any_call(timeout=5) + mock_daemon.wait.assert_any_call(timeout=1) + mock_daemon.kill.assert_called_once() + + def test_credential_daemon_cleanup_logging(self, caplog): + """Test that credential daemon cleanup uses proper logging.""" + # Mock the logger to verify it's called + with patch("subprocess.Popen") as mock_popen, patch( + "jupyterlab_git.git.get_logger" + ) as mock_get_logger: + + mock_logger = MagicMock() + mock_get_logger.return_value = mock_logger + + mock_daemon = MagicMock() + mock_daemon.poll.return_value = None # Process is still running + mock_daemon.wait.return_value = 0 + mock_daemon.pid = 12345 + + git = Git() + git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = mock_daemon + + git._cleanup_processes() + + # Verify logging message includes PID and uses lazy evaluation + mock_logger.debug.assert_called_once_with( + "Git credential cache daemon process (PID: %s) cleaned up successfully", + 12345, + ) + + def test_credential_daemon_cleanup_exception_handling(self, caplog): + """Test that credential daemon cleanup handles exceptions gracefully.""" + # Mock the logger to verify it's called + with patch("subprocess.Popen") as mock_popen, patch( + "jupyterlab_git.git.get_logger" + ) as mock_get_logger: + + mock_logger = MagicMock() + mock_get_logger.return_value = mock_logger + + mock_daemon = MagicMock() + mock_daemon.poll.return_value = None + exception = OSError("Process not found") + mock_daemon.terminate.side_effect = exception + mock_daemon.pid = 12345 + + git = Git() + git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = mock_daemon + + git._cleanup_processes() + + # Verify exception is logged + mock_logger.warning.assert_called_once_with( + "Failed to cleanup credential cache daemon: %s", exception + ) + # Verify process is set to None even on exception + assert git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS is None + + def test_credential_daemon_cleanup_skips_if_already_terminated(self): + """Test that cleanup skips if daemon process is already terminated.""" + with patch("subprocess.Popen") as mock_popen: + mock_daemon = MagicMock() + mock_daemon.poll.return_value = 0 # Process already terminated + + git = Git() + git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = mock_daemon + + git._cleanup_processes() + + # Verify no termination calls since process is already done + mock_daemon.terminate.assert_not_called() + mock_daemon.wait.assert_not_called() + mock_daemon.kill.assert_not_called() + + +class TestLoggingBehavior: + """Test logging behavior improvements.""" + + def test_timeout_error_includes_command_details(self, caplog): + """Test that timeout errors include specific command details.""" + # Mock the logger to verify it's called + with patch("subprocess.Popen") as mock_popen, patch( + "jupyterlab_git.git.get_logger" + ) as mock_get_logger: + + mock_logger = MagicMock() + mock_get_logger.return_value = mock_logger + + mock_process = MagicMock() + mock_process.communicate.side_effect = subprocess.TimeoutExpired( + cmd=["git", "clone", "https://example.com/repo.git"], timeout=30 + ) + mock_process.wait.return_value = 0 + mock_popen.return_value = mock_process + + from jupyterlab_git.git import call_subprocess + + with pytest.raises(TimeoutError) as exc_info: + call_subprocess( + ["git", "clone", "https://example.com/repo.git"], timeout=30 + ) + + # Verify error message includes command and timeout details + assert "Git command timed out after 30 seconds" in str(exc_info.value) + assert "git clone https://example.com/repo.git" in str(exc_info.value) + mock_logger.warning.assert_called_once_with( + "Git command timed out: %s", + ["git", "clone", "https://example.com/repo.git"], + ) + + +class TestIntegrationScenarios: + """Test integration scenarios combining multiple improvements.""" + + @pytest.mark.asyncio + async def test_authentication_timeout_with_cleanup_and_logging(self, caplog): + """Test complete authentication timeout scenario with cleanup and logging.""" + with patch("pexpect.spawn") as mock_spawn: + mock_process = MagicMock() + mock_process.expect.side_effect = pexpect.exceptions.TIMEOUT("timeout") + mock_spawn.return_value = mock_process + + with caplog.at_level(logging.WARNING, logger="Application.jupyterlab_git"): + with pytest.raises(TimeoutError) as exc_info: + await call_subprocess_with_authentication( + ["git", "push", "origin", "main"], + username="user", + password="pass", + timeout=15, + ) + + # Verify proper timeout error message + assert "Git authentication timed out after 15 seconds" in str( + exc_info.value + ) + assert "git push origin main" in str(exc_info.value) + + # Verify process cleanup occurred + mock_process.terminate.assert_called_once_with(force=True) + mock_process.close.assert_called_once() + + def test_git_instance_full_lifecycle_with_cleanup(self, caplog): + """Test full Git instance lifecycle with proper cleanup.""" + # Mock the logger to verify it's called + with patch("subprocess.Popen") as mock_popen, patch( + "jupyterlab_git.git.get_logger" + ) as mock_get_logger: + + mock_logger = MagicMock() + mock_get_logger.return_value = mock_logger + + mock_daemon = MagicMock() + mock_daemon.poll.return_value = None + mock_daemon.wait.return_value = 0 + mock_daemon.pid = 54321 + + git = Git() + git._GIT_CREDENTIAL_CACHE_DAEMON_PROCESS = mock_daemon + + # Simulate destruction + git.__del__() + + # Verify cleanup was called and logged properly + mock_daemon.terminate.assert_called_once() + mock_daemon.wait.assert_called_once_with(timeout=5) + mock_logger.debug.assert_called_once_with( + "Git credential cache daemon process (PID: %s) cleaned up successfully", + 54321, + )