From 184dc78db55927fbb6ce930beaa84a26bdb47c5f Mon Sep 17 00:00:00 2001 From: Ned Batchelder Date: Mon, 20 Nov 2023 05:03:03 -0500 Subject: [PATCH] debug(fix): process logging now alerts us to forked processes --- coverage/debug.py | 62 ++++++++++++++++++++++++++++--------------- tests/test_debug.py | 4 +++ tests/test_process.py | 61 ++++++++++++++++++++++++++---------------- 3 files changed, 83 insertions(+), 44 deletions(-) diff --git a/coverage/debug.py b/coverage/debug.py index 523bb4812..d78043989 100644 --- a/coverage/debug.py +++ b/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, diff --git a/tests/test_debug.py b/tests/test_debug.py index f5fbe11e5..4619c37cc 100644 --- a/tests/test_debug.py +++ b/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)" diff --git a/tests/test_process.py b/tests/test_process.py index 6b5acf6e2..90487328e 100644 --- a/tests/test_process.py +++ b/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