debug(fix): process logging now alerts us to forked processes

coverage/debug.py

@@ -53,14 +53,17 @@ def __init__(
         self.suppress_callers = False
 
         filters = []
+        if self.should("process"):
+            filters.append(CwdTracker().filter)
+            filters.append(ProcessTracker().filter)
         if self.should("pytest"):
             filters.append(PytestTracker().filter)
         if self.should("pid"):
             filters.append(add_pid_and_tid)
+
         self.output = DebugOutputFile.get_one(
             output,
             file_name=file_name,
-            show_process=self.should("process"),
             filters=filters,
         )
         self.raw_output = self.output.outfile
@@ -227,8 +230,8 @@ def short_stack(
         import_local_file : /Users/ned/coverage/trunk/coverage/backward.py:159
         ...
 
-    `skip` is the number of frames to skip, so that debugging functions can
-    call this and not be included in the result.
+    `skip` is the number of closest immediate frames to skip, so that debugging
+    functions can call this and not be included in the result.
 
     If `full` is true, then include all frames.  Otherwise, initial "boring"
     frames (ones in site-packages and earlier) are omitted.
@@ -331,7 +334,8 @@ def filter_text(text: str, filters: Iterable[Callable[[str], str]]) -> str:
     """Run `text` through a series of filters.
 
     `filters` is a list of functions. Each takes a string and returns a
-    string.  Each is run in turn.
+    string.  Each is run in turn. After each filter, the text is split into
+    lines, and each line is passed through the next filter.
 
     Returns: the final string that results after all of the filters have
     run.
@@ -340,10 +344,10 @@ def filter_text(text: str, filters: Iterable[Callable[[str], str]]) -> str:
     clean_text = text.rstrip()
     ending = text[len(clean_text):]
     text = clean_text
-    for fn in filters:
+    for filter_fn in filters:
         lines = []
         for line in text.splitlines():
-            lines.extend(fn(line).splitlines())
+            lines.extend(filter_fn(line).splitlines())
         text = "\n".join(lines)
     return text + ending
 
@@ -362,6 +366,31 @@ def filter(self, text: str) -> str:
         return text
 
 
+class ProcessTracker:
+    """Track process creation for debug logging."""
+    def __init__(self) -> None:
+        self.pid: int = 0
+
+    def filter(self, text: str) -> str:
+        """Add a message about how new processes came to be."""
+        pid = os.getpid()
+        if pid != self.pid:
+            if self.pid == 0:
+                argv = getattr(sys, "argv", None)
+                premsg = (
+                    f"New process: {pid=}, executable: {sys.executable!r}\n"
+                    + f"New process: cmd: {argv!r}\n"
+                )
+                if hasattr(os, "getppid"):
+                    premsg += f"New process parent pid: {os.getppid()!r}\n"
+            else:
+                premsg = f"New process: forked {self.pid} -> {pid}\n"
+            self.pid = pid
+            return premsg + text
+        else:
+            return text
+
+
 class PytestTracker:
     """Track the current pytest test name to add to debug messages."""
     def __init__(self) -> None:
@@ -381,26 +410,17 @@ class DebugOutputFile:
     def __init__(
         self,
         outfile: Optional[IO[str]],
-        show_process: bool,
         filters: Iterable[Callable[[str], str]],
     ):
         self.outfile = outfile
-        self.show_process = show_process
         self.filters = list(filters)
-
-        if self.show_process:
-            self.filters.insert(0, CwdTracker().filter)
-            self.write(f"New process: executable: {sys.executable!r}\n")
-            self.write("New process: cmd: {!r}\n".format(getattr(sys, "argv", None)))
-            if hasattr(os, "getppid"):
-                self.write(f"New process: pid: {os.getpid()!r}, parent pid: {os.getppid()!r}\n")
+        self.pid = os.getpid()
 
     @classmethod
     def get_one(
         cls,
         fileobj: Optional[IO[str]] = None,
         file_name: Optional[str] = None,
-        show_process: bool = True,
         filters: Iterable[Callable[[str], str]] = (),
         interim: bool = False,
     ) -> DebugOutputFile:
@@ -412,9 +432,6 @@ def get_one(
         provided, or COVERAGE_DEBUG_FILE, or stderr), and a process-wide
         singleton DebugOutputFile is made.
 
-        `show_process` controls whether the debug file adds process-level
-        information, and filters is a list of other message filters to apply.
-
         `filters` are the text filters to apply to the stream to annotate with
         pids, etc.
 
@@ -423,7 +440,7 @@ def get_one(
         """
         if fileobj is not None:
             # Make DebugOutputFile around the fileobj passed.
-            return cls(fileobj, show_process, filters)
+            return cls(fileobj, filters)
 
         the_one, is_interim = cls._get_singleton_data()
         if the_one is None or is_interim:
@@ -437,8 +454,11 @@ def get_one(
                     fileobj = open(file_name, "a", encoding="utf-8")
                 else:
                     fileobj = sys.stderr
-            the_one = cls(fileobj, show_process, filters)
+            the_one = cls(fileobj, filters)
             cls._set_singleton_data(the_one, interim)
+
+        if not(the_one.filters):
+            the_one.filters = list(filters)
         return the_one
 
     # Because of the way igor.py deletes and re-imports modules,

tests/test_debug.py

@@ -210,6 +210,10 @@ def test_debug_pybehave(self) -> None:
         vtuple = ast.literal_eval(pyversion.partition(":")[-1].strip())
         assert vtuple[:5] == sys.version_info
 
+    def test_debug_process(self) -> None:
+        out_text = self.f1_debug_output(["trace", "process"])
+        assert f"New process: pid={os.getpid()}, executable:" in out_text
+
     def test_debug_pytest(self) -> None:
         out_text = self.f1_debug_output(["trace", "pytest"])
         ctx = "tests/test_debug.py::DebugTraceTest::test_debug_pytest (call)"

tests/test_process.py

@@ -24,7 +24,7 @@
 from coverage.files import abs_file, python_reported_file
 
 from tests.coveragetest import CoverageTest, TESTS_DIR
-from tests.helpers import re_lines_text
+from tests.helpers import re_lines, re_lines_text
 
 
 class ProcessTest(CoverageTest):
@@ -364,44 +364,59 @@ def test_fork(self) -> None:
         self.make_file("fork.py", """\
             import os
 
-            def child():
-                print('Child!')
+            print(f"parent={os.getpid()}", flush=True)
+            ret = os.fork()
 
-            def main():
-                ret = os.fork()
-
-                if ret == 0:
-                    child()
-                else:
-                    os.waitpid(ret, 0)
-
-            main()
+            if ret == 0:
+                print(f"child={os.getpid()}", flush=True)
+            else:
+                os.waitpid(ret, 0)
             """)
+        total_lines = 6
 
-        out = self.run_command("coverage run -p fork.py")
-        assert out == 'Child!\n'
+        self.set_environ("COVERAGE_DEBUG_FILE", "debug.out")
+        out = self.run_command("coverage run --debug=pid,process,trace -p fork.py")
+        pids = {key:int(pid) for line in out.splitlines() for key, pid in [line.split("=")]}
+        assert set(pids) == {"parent", "child"}
         self.assert_doesnt_exist(".coverage")
 
         # After running the forking program, there should be two
-        # .coverage.machine.123 files.
+        # .coverage.machine.pid.randomword files.  The pids should match our
+        # processes, and the files should have different random words at the
+        # end of the file name.
         self.assert_file_count(".coverage.*", 2)
-
-        # The two data files should have different random words at the end of
-        # the file name.
         data_files = glob.glob(".coverage.*")
-        suffixes = {name.rpartition(".")[-1] for name in data_files}
+        filepids = {int(name.split(".")[-2]) for name in data_files}
+        assert filepids == set(pids.values())
+        suffixes = {name.split(".")[-1] for name in data_files}
         assert len(suffixes) == 2, f"Same random suffix: {data_files}"
 
-        # Combine the parallel coverage data files into .coverage .
-        self.run_command("coverage combine")
-        self.assert_exists(".coverage")
+        # Each data file should have a subset of the lines.
+        for data_file in data_files:
+            data = coverage.CoverageData(data_file)
+            data.read()
+            assert line_counts(data)["fork.py"] < total_lines
 
+        # Combine the parallel coverage data files into a .coverage file.
         # After combining, there should be only the .coverage file.
+        self.run_command("coverage combine")
+        self.assert_exists(".coverage")
         self.assert_file_count(".coverage.*", 0)
 
         data = coverage.CoverageData()
         data.read()
-        assert line_counts(data)['fork.py'] == 9
+        assert line_counts(data)["fork.py"] == total_lines
+
+        debug_text = open("debug.out").read()
+        ppid = pids["parent"]
+        cpid = pids["child"]
+        assert ppid != cpid
+        plines = re_lines(fr"{ppid}\.[0-9a-f]+: New process: pid={ppid}, executable", debug_text)
+        assert len(plines) == 1
+        clines = re_lines(fr"{cpid}\.[0-9a-f]+: New process: forked {ppid} -> {cpid}", debug_text)
+        assert len(clines) == 1
+        reported_pids = {line.split(".")[0] for line in debug_text.splitlines()}
+        assert len(reported_pids) == 2
 
     def test_warnings_during_reporting(self) -> None:
         # While fixing issue #224, the warnings were being printed far too