Fix Python control thread hang (#7143)

Address #7142 by dropping the control thread if it doesn't exit after 5 seconds.

### QA Notes

Hopefully this reduces flakiness in CI, else we can take another look
with the new logs.

e2e: @:sessions @:console

Author: seeM

extensions/positron-python/python_files/posit/positron/positron_ipkernel.py

@@ -38,11 +38,12 @@
 from .plots import PlotsService
 from .session_mode import SessionMode
 from .ui import UiService
-from .utils import BackgroundJobQueue, JsonRecord, get_qualname
+from .utils import BackgroundJobQueue, JsonRecord, get_qualname, with_logging
 from .variables import VariablesService
 
 if TYPE_CHECKING:
     from ipykernel.comm.manager import CommManager
+    from ipykernel.control import ControlThread
 
 
 class _CommTarget(str, enum.Enum):
@@ -562,6 +563,7 @@ def _showwarning(self, message, category, filename, lineno, file=None, line=None
 
 
 class PositronIPKernelApp(IPKernelApp):
+    control_thread: ControlThread | None
     kernel: PositronIPyKernel
 
     # Use the PositronIPyKernel class.
@@ -570,6 +572,20 @@ class PositronIPKernelApp(IPKernelApp):
     # Positron-specific attributes:
     session_mode: SessionMode = SessionMode.trait()  # type: ignore
 
+    def init_control(self, context):
+        result = super().init_control(context)
+        # Should be defined in init_control().
+        assert self.control_thread is not None
+        # Add a bunch of debug logging to control thread methods.
+        # See: https://github.com/posit-dev/positron/issues/7142.
+        self.control_thread.io_loop.start = with_logging(self.control_thread.io_loop.start)
+        self.control_thread.io_loop.stop = with_logging(self.control_thread.io_loop.stop)
+        self.control_thread.io_loop.close = with_logging(self.control_thread.io_loop.close)
+        self.control_thread.run = with_logging(self.control_thread.run)
+        self.control_thread.stop = with_logging(self.control_thread.stop)
+        self.control_thread.join = with_logging(self.control_thread.join)
+        return result
+
     def init_gui_pylab(self):
         # Enable the Positron matplotlib backend if we're not in a notebook.
         # If we're in a notebook, use IPython's default backend via the super() call below.
@@ -580,6 +596,23 @@ def init_gui_pylab(self):
 
         return super().init_gui_pylab()
 
+    def close(self):
+        # Stop the control thread if it's still alive. This is also attempted in super().close(),
+        # but that doesn't timeout on join() so can hang forever if the control thread is stuck.
+        # See https://github.com/posit-dev/positron/issues/7142.
+        if self.control_thread and self.control_thread.is_alive():
+            self.log.debug("Closing control thread")
+            self.control_thread.stop()
+            self.control_thread.join(timeout=5)
+            # If the thread is still alive after 5 seconds, log a warning and drop the reference.
+            # This leaves the thread dangling, but since it's a daemon thread it won't stop the
+            # process from exiting.
+            if self.control_thread.is_alive() and self.control_thread.daemon:
+                self.log.warning("Control thread did not exit after 5 seconds, dropping it")
+                self.control_thread = None
+
+        super().close()
+
 
 #
 # OSC8 functionality

extensions/positron-python/python_files/posit/positron/utils.py

@@ -7,6 +7,7 @@
 import concurrent.futures
 import functools
 import inspect
+import logging
 import numbers
 import pprint
 import sys
@@ -31,6 +32,8 @@
 )
 from urllib.parse import unquote, urlparse
 
+logger = logging.getLogger(__name__)
+
 JsonData = Union[Dict[str, "JsonData"], List["JsonData"], str, int, float, bool, None]
 JsonRecord = Dict[str, JsonData]
 
@@ -497,3 +500,17 @@ def run() -> None:
         return debounced
 
     return wrapper
+
+
+def with_logging(func: Callable):
+    """Decorator to log the execution of a function."""
+    name = get_qualname(func)
+
+    @functools.wraps(func)
+    def wrapper(*args, **kwargs):
+        logger.debug(f"Calling {name} with args: {args}, kwargs: {kwargs}")
+        result = func(*args, **kwargs)
+        logger.debug(f"{name} returned: {result}")
+        return result
+
+    return wrapper