Keep bisect log handlers isolated when instance IDs are reused (#439)

Summary:
Pull Request resolved: #439

Creating a BisectLogger with a reused timestamp and object ID can retrieve a previous instance's logger from Python's global logging registry. Its closed handlers then reopen an old log file, mixing output between sessions or raising FileNotFoundError after the old temporary directory has been removed. This caused three setUp errors in GitHub Actions Tests #927: https://github.com/meta-pytorch/tritonparse/actions/runs/35882624122/job/107254643368

Give each BisectLogger its own logging.Logger and detach and close test handlers before removing temporary directories. Add a deterministic regression that forces object ID reuse and covers both retained and deleted previous log directories.

___

Differential Revision: D121418371

fbshipit-source-id: 5f784470861c3cf86c1fb7b51e465364eb1ed500

Author: FindHao

tests/cpu/test_bisect_executor.py

@@ -65,13 +65,13 @@ class ShellExecutorTest(unittest.TestCase):
     def setUp(self):
         """Set up test fixtures."""
         self.temp_dir = tempfile.mkdtemp()
+        self.addCleanup(shutil.rmtree, self.temp_dir)
         self.logger = BisectLogger(self.temp_dir)
+        for handler in self.logger.logger.handlers:
+            self.addCleanup(handler.close)
+            self.addCleanup(self.logger.logger.removeHandler, handler)
         self.executor = ShellExecutor(self.logger)
 
-    def tearDown(self):
-        """Clean up test fixtures."""
-        shutil.rmtree(self.temp_dir)
-
     def test_run_command_success(self):
         """Test run_command executes command and returns result."""
         result = self.executor.run_command(["echo", "hello"])

tests/cpu/test_bisect_logger.py

@@ -5,6 +5,8 @@
 import shutil
 import tempfile
 import unittest
+from pathlib import Path
+from unittest.mock import patch
 
 from tritonparse.bisect import BisectLogger
 
@@ -15,40 +17,48 @@ class BisectLoggerTest(unittest.TestCase):
     def setUp(self):
         """Set up test fixtures."""
         self.temp_dir = tempfile.mkdtemp()
+        self.addCleanup(shutil.rmtree, self.temp_dir)
 
-    def tearDown(self):
-        """Clean up test fixtures."""
-        shutil.rmtree(self.temp_dir)
+    def _make_logger(self, log_dir=None, **kwargs):
+        logger = BisectLogger(str(log_dir or self.temp_dir), **kwargs)
+        self.addCleanup(self._close_logger, logger)
+        return logger
+
+    @staticmethod
+    def _close_logger(logger):
+        for handler in logger.logger.handlers[:]:
+            logger.logger.removeHandler(handler)
+            handler.close()
 
     def test_creates_log_directory_and_files(self):
         """Test that logger creates log directory and module log file."""
-        logger = BisectLogger(self.temp_dir)
+        logger = self._make_logger()
         self.assertTrue(logger.module_log_path.exists())
         self.assertTrue(logger.log_dir.exists())
 
     def test_auto_generates_session_name(self):
         """Test that session name is auto-generated if not provided."""
-        logger = BisectLogger(self.temp_dir)
+        logger = self._make_logger()
         self.assertIsNotNone(logger.session_name)
         self.assertIn(logger.session_name, str(logger.module_log_path))
 
     def test_uses_provided_session_name(self):
         """Test that provided session name is used."""
-        logger = BisectLogger(self.temp_dir, session_name="test_session")
+        logger = self._make_logger(session_name="test_session")
         self.assertEqual(logger.session_name, "test_session")
         self.assertIn("test_session", str(logger.module_log_path))
 
     def test_output_callback_receives_lines(self):
         """Test that output_callback receives each line of command output."""
         captured = []
-        logger = BisectLogger(self.temp_dir, output_callback=captured.append)
+        logger = self._make_logger(output_callback=captured.append)
         logger.log_command_output("test_cmd", "line1\nline2\nline3", 0)
         self.assertEqual(captured, ["line1", "line2", "line3"])
 
     def test_tui_callback_on_info(self):
         """Test that info() triggers TUI callback when configured."""
         tui_msgs = []
-        logger = BisectLogger(self.temp_dir)
+        logger = self._make_logger()
         logger.configure_for_tui(tui_msgs.append)
         logger.info("test message")
         self.assertEqual(len(tui_msgs), 1)
@@ -57,21 +67,49 @@ def test_tui_callback_on_info(self):
     def test_tui_callback_not_triggered_by_debug(self):
         """Test that debug() does NOT trigger TUI callback (too verbose)."""
         tui_msgs = []
-        logger = BisectLogger(self.temp_dir)
+        logger = self._make_logger()
         logger.configure_for_tui(tui_msgs.append)
         logger.debug("debug message")
         # TUI callback should not be called for debug messages
         self.assertEqual(len(tui_msgs), 0)
 
     def test_log_command_output_writes_to_file(self):
         """Test that log_command_output writes to command log file."""
-        logger = BisectLogger(self.temp_dir)
+        logger = self._make_logger()
         logger.log_command_output("echo hello", "hello world", 0)
         self.assertTrue(logger.command_log_path.exists())
         content = logger.command_log_path.read_text()
         self.assertIn("echo hello", content)
         self.assertIn("hello world", content)
 
+    def test_reused_instance_id_keeps_logs_isolated(self):
+        """A replacement logger must not reopen a previous instance's log file."""
+        for remove_previous_directory in (False, True):
+            with self.subTest(remove_previous_directory=remove_previous_directory):
+                previous_dir = Path(self.temp_dir) / f"old_{remove_previous_directory}"
+                current_dir = Path(self.temp_dir) / f"new_{remove_previous_directory}"
+                session_name = f"reused_id_{remove_previous_directory}"
+                # Force ID reuse without depending on allocator timing.
+                with patch("tritonparse.bisect.logger.id", return_value=1, create=True):
+                    previous = self._make_logger(
+                        previous_dir, session_name=session_name
+                    )
+                    # Reproduce the original cleanup: close without detaching.
+                    for handler in previous.logger.handlers:
+                        handler.close()
+                    if remove_previous_directory:
+                        shutil.rmtree(previous_dir)
+
+                    current = self._make_logger(current_dir, session_name=session_name)
+                    message = "message from the replacement logger"
+                    current.info(message)
+
+                self.assertIn(message, current.module_log_path.read_text())
+                if remove_previous_directory:
+                    self.assertFalse(previous_dir.exists())
+                else:
+                    self.assertNotIn(message, previous.module_log_path.read_text())
+
 
 if __name__ == "__main__":
     unittest.main()

tests/cpu/test_bisect_results.py

@@ -142,6 +142,7 @@ def setUp(self):
         self.logger = BisectLogger(str(self.root / "logs"))
         for handler in self.logger.logger.handlers:
             self.addCleanup(handler.close)
+            self.addCleanup(self.logger.logger.removeHandler, handler)
         self.executor = ShellExecutor(self.logger)
         self._git("init", "-q")
         self._git("config", "user.name", "Tritonparse test")

tritonparse/bisect/logger.py

@@ -88,11 +88,10 @@ def set_output_callback(self, callback: Optional[Callable[[str], None]]) -> None
 
     def _setup_module_logger(self) -> None:
         """Configure the Python logging system with file and stdout handlers."""
-        # Use unique logger name with instance id to avoid sharing handlers
-        # between different BisectLogger instances with the same session_name.
-        # This ensures each instance logs to its own file path.
+        # Own the logger instead of using the global getLogger() registry:
+        # object IDs can be reused while that registry retains old handlers.
         self._logger_name = f"bisect.{self.session_name}.{id(self)}"
-        self.logger = logging.getLogger(self._logger_name)
+        self.logger = logging.Logger(self._logger_name)
         self.logger.setLevel(logging.DEBUG)
 
         # Prevent propagation to root logger to avoid duplicate output