Big refactor of debug logging

6 files changed, 160 insertions, 83 deletions

diff --git a/coverage/control.py b/coverage/control.py
index 4cc7645..30923b9 100644
--- a/coverage/control.py
+++ b/coverage/control.py
@@ -17,7 +17,7 @@ from coverage.backward import string_class, iitems
 from coverage.collector import Collector
 from coverage.config import read_coverage_config
 from coverage.data import CoverageData, CoverageDataFiles
-from coverage.debug import DebugControl
+from coverage.debug import DebugControl, write_formatted_info
 from coverage.files import TreeMatcher, FnmatchMatcher
 from coverage.files import PathAliases, find_python_files, prep_patterns
 from coverage.files import ModuleMatcher, abs_file
@@ -144,7 +144,9 @@ class Coverage(object):
             concurrency=concurrency,
             )
 
+        # This is injectable by tests.
         self._debug_file = None
+
         self._auto_load = self._auto_save = auto_data
         self._data_suffix = data_suffix
 
@@ -354,19 +356,19 @@ class Coverage(object):
         with self.debug.without_callers():
             if self.debug.should('config'):
                 config_info = sorted(self.config.__dict__.items())
-                self.debug.write_formatted_info("config", config_info)
+                write_formatted_info(self.debug, "config", config_info)
                 wrote_any = True
 
             if self.debug.should('sys'):
-                self.debug.write_formatted_info("sys", self.sys_info())
+                write_formatted_info(self.debug, "sys", self.sys_info())
                 for plugin in self.plugins:
                     header = "sys: " + plugin._coverage_plugin_name
                     info = plugin.sys_info()
-                    self.debug.write_formatted_info(header, info)
+                    write_formatted_info(self.debug, header, info)
                 wrote_any = True
 
         if wrote_any:
-            self.debug.write_formatted_info("end", ())
+            write_formatted_info(self.debug, "end", ())
 
     def _canonical_path(self, morf, directory=False):
         """Return the canonical path of the module or file `morf`.
@@ -686,6 +688,8 @@ class Coverage(object):
 
     def _atexit(self):
         """Clean up on process shutdown."""
+        if self.debug.should("process"):
+            self.debug.write("atexit: {0!r}".format(self))
         if self._started:
             self.stop()
         if self._auto_save:
diff --git a/coverage/debug.py b/coverage/debug.py
index 5ffed39..4cec390 100644
--- a/coverage/debug.py
+++ b/coverage/debug.py
@@ -13,6 +13,7 @@ try:
 except ImportError:
     import thread as _thread
 
+from coverage.backward import StringIO
 from coverage.misc import isolate_module
 
 os = isolate_module(os)
@@ -32,18 +33,27 @@ class DebugControl(object):
 
     def __init__(self, options, output):
         """Configure the options and output file for debugging."""
-        self.options = options
-        self.output = output
+        self.options = list(options) + FORCED_DEBUG
+        self.raw_output = output
         self.suppress_callers = False
 
+        filters = []
+        if self.should('pid'):
+            filters.append(add_pid_and_tid)
+        self.output = DebugOutputFile.the_one(
+            self.raw_output,
+            show_process=self.should('process'),
+            filters=filters,
+        )
+
     def __repr__(self):
-        return "<DebugControl options=%r output=%r>" % (self.options, self.output)
+        return "<DebugControl options=%r raw_output=%r>" % (self.options, self.raw_output)
 
     def should(self, option):
         """Decide whether to output debug information in category `option`."""
         if option == "callers" and self.suppress_callers:
             return False
-        return (option in self.options or option in FORCED_DEBUG)
+        return (option in self.options)
 
     @contextlib.contextmanager
     def without_callers(self):
@@ -61,18 +71,20 @@ class DebugControl(object):
         `msg` is the line to write. A newline will be appended.
 
         """
-        if self.should('pid'):
-            msg = "pid %5d: %s" % (os.getpid(), msg)
         self.output.write(msg+"\n")
         if self.should('callers'):
             dump_stack_frames(out=self.output, skip=1)
         self.output.flush()
 
-    def write_formatted_info(self, header, info):
-        """Write a sequence of (label,data) pairs nicely."""
-        self.write(info_header(header))
-        for line in info_formatter(info):
-            self.write(" %s" % line)
+
+class DebugControlString(DebugControl):
+    """A `DebugControl` that writes to a StringIO, for testing."""
+    def __init__(self, options):
+        super(DebugControlString, self).__init__(options, StringIO())
+
+    def get_output(self):
+        """Get the output text from the `DebugControl`."""
+        return self.raw_output.getvalue()
 
 
 def info_header(label):
@@ -103,6 +115,13 @@ def info_formatter(info):
             yield "%*s: %s" % (label_len, label, data)
 
 
+def write_formatted_info(writer, header, info):
+    """Write a sequence of (label,data) pairs nicely."""
+    writer.write(info_header(header))
+    for line in info_formatter(info):
+        writer.write(" %s" % line)
+
+
 def short_stack(limit=None, skip=0):
     """Return a string summarizing the call stack.
 
@@ -126,7 +145,7 @@ def short_stack(limit=None, skip=0):
 
 
 def dump_stack_frames(limit=None, out=None, skip=0):
-    """Print a summary of the stack to stdout, or some place else."""
+    """Print a summary of the stack to stdout, or someplace else."""
     out = out or sys.stdout
     out.write(short_stack(limit=limit, skip=skip+1))
     out.write("\n")
@@ -140,60 +159,108 @@ def short_id(id64):
     return id16 & 0xFFFF
 
 
+def add_pid_and_tid(text):
+    """A filter to add pid and tid to debug messages."""
+    # Thread ids are useful, but too long. Make a shorter one.
+    tid = "{0:04x}".format(short_id(_thread.get_ident()))
+    text = "{0:5d}.{1}: {2}".format(os.getpid(), tid, text)
+    return text
+
+
+def filter_text(text, filters):
+    """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.
+
+    Returns: the final string that results after all of the filters have
+    run.
+
+    """
+    clean_text = text.rstrip()
+    ending = text[len(clean_text):]
+    text = clean_text
+    for fn in filters:
+        lines = []
+        for line in text.splitlines():
+            lines.extend(fn(line).splitlines())
+        text = "\n".join(lines)
+    return text + ending
+
+
+class CwdTracker(object):                                   # pragma: debugging
+    """A class to add cwd info to debug messages."""
+    def __init__(self):
+        self.cwd = None
+
+    def filter(self, text):
+        """Add a cwd message for each new cwd."""
+        cwd = os.getcwd()
+        if cwd != self.cwd:
+            text = "cwd is now {0!r}\n".format(cwd) + text
+            self.cwd = cwd
+        return text
+
+
 class DebugOutputFile(object):                              # pragma: debugging
     """A file-like object that includes pid and cwd information."""
-    def __init__(self, outfile):
+    def __init__(self, outfile, show_process, filters):
         self.outfile = outfile
-        self.cwd = None
+        self.show_process = show_process
+        self.filters = list(filters)
+
+        if self.show_process:
+            self.filters.append(CwdTracker().filter)
+            cmd = " ".join(getattr(sys, 'argv', ['???']))
+            self.write("New process: executable: %s\n" % (sys.executable,))
+            self.write("New process: cmd: %s\n" % (cmd,))
+            if hasattr(os, 'getppid'):
+                self.write("New process: parent pid: %s\n" % (os.getppid(),))
 
     SYS_MOD_NAME = '$coverage.debug.DebugOutputFile.the_one'
 
     @classmethod
-    def the_one(cls):
-        """Get the process-wide singleton DebugOutputFile."""
+    def the_one(cls, fileobj=None, show_process=True, filters=()):
+        """Get the process-wide singleton DebugOutputFile.
+
+        If it doesn't exist yet, then create it as a wrapper around the file
+        object `fileobj`. `show_process` controls whether the debug file adds
+        process-level information.
+
+        """
         # Because of the way igor.py deletes and re-imports modules,
         # this class can be defined more than once. But we really want
         # a process-wide singleton. So stash it in sys.modules instead of
         # on a class attribute. Yes, this is aggressively gross.
         the_one = sys.modules.get(cls.SYS_MOD_NAME)
         if the_one is None:
-            filename = os.environ.get("COVERAGE_LOG", "/tmp/covlog.txt")
-            sys.modules[cls.SYS_MOD_NAME] = the_one = cls(open(filename, "a"))
-
-            cmd = " ".join(getattr(sys, 'argv', ['???']))
-            the_one._write("New process: executable: %s\n" % (sys.executable,))
-            the_one._write("New process: cmd: %s\n" % (cmd,))
-            if hasattr(os, 'getppid'):
-                the_one._write("New process: parent pid: %s\n" % (os.getppid(),))
-
+            assert fileobj is not None
+            sys.modules[cls.SYS_MOD_NAME] = the_one = cls(fileobj, show_process, filters)
         return the_one
 
-    def write(self, text, stack=False):
-        """Just like file.write"""
-        cwd = os.getcwd()
-        if cwd != self.cwd:
-            self._write("cwd is now {0!r}\n".format(cwd))
-            self.cwd = cwd
-        self._write(text, stack=stack)
-
-    def _write(self, text, stack=False):
-        """The raw text-writer, so that we can use it ourselves."""
-        # Thread ids are useful, but too long. Make a shorter one.
-        tid = "{0:04x}".format(short_id(_thread.get_ident()))
-
-        # Aspectlib prints stack traces, but includes its own frames.  Scrub those out:
-        # <<< aspectlib/__init__.py:257:function_wrapper < igor.py:143:run_tests < ...
-        text = re.sub(r"(?<= )aspectlib/[^.]+\.py:\d+:\w+ < ", "", text)
+    def write(self, text):
+        """Just like file.write, but filter through all our filters."""
+        self.outfile.write(filter_text(text, self.filters))
+        self.outfile.flush()
 
-        self.outfile.write("{0:5d}.{1}: {2}".format(os.getpid(), tid, text))
+    def flush(self):
+        """Flush our file."""
         self.outfile.flush()
-        if stack:
-            dump_stack_frames(out=self.outfile, skip=1)
 
 
 def log(msg, stack=False):                                  # pragma: debugging
     """Write a log message as forcefully as possible."""
-    DebugOutputFile.the_one().write(msg+"\n", stack=stack)
+    out = DebugOutputFile.the_one()
+    out.write(msg+"\n")
+    if stack:
+        dump_stack_frames(out=out, skip=1)
+
+
+def filter_aspectlib_frames(text):                          # pragma: debugging
+    """Aspectlib prints stack traces, but includes its own frames.  Scrub those out."""
+    # <<< aspectlib/__init__.py:257:function_wrapper < igor.py:143:run_tests < ...
+    text = re.sub(r"(?<= )aspectlib/[^.]+\.py:\d+:\w+ < ", "", text)
+    return text
 
 
 def enable_aspectlib_maybe():                               # pragma: debugging
@@ -217,7 +284,9 @@ def enable_aspectlib_maybe():                               # pragma: debugging
     import aspectlib                            # pylint: disable=import-error
     import aspectlib.debug                      # pylint: disable=import-error
 
-    aspects_file = DebugOutputFile.the_one()
+    filename = os.environ.get("COVERAGE_LOG", "/tmp/covlog.txt")
+    filters = [add_pid_and_tid, filter_aspectlib_frames]
+    aspects_file = DebugOutputFile.the_one(open(filename, "a"), show_process=True, filters=filters)
     aspect_log = aspectlib.debug.log(
         print_to=aspects_file, attributes=['id'], stacktrace=30, use_logging=False
     )
diff --git a/doc/cmd.rst b/doc/cmd.rst
index a5e0005..acc56d5 100644
--- a/doc/cmd.rst
+++ b/doc/cmd.rst
@@ -457,6 +457,9 @@ to log:
 
 * ``plugin``: print information about plugin operations.
 
+* ``process``: show process creation information, and changes in the current
+  directory.
+
 * ``sys``: before starting, dump all the system and environment information,
   as with :ref:`coverage debug sys <cmd_debug>`.
 
diff --git a/tests/coveragetest.py b/tests/coveragetest.py
index f349196..37e0937 100644
--- a/tests/coveragetest.py
+++ b/tests/coveragetest.py
@@ -22,7 +22,7 @@ from coverage import env
 from coverage.backunittest import TestCase, unittest
 from coverage.backward import StringIO, import_local_file, string_class, shlex_quote
 from coverage.cmdline import CoverageScript
-from coverage.debug import _TEST_NAME_FILE, DebugControl
+from coverage.debug import _TEST_NAME_FILE
 from coverage.misc import StopEverything
 
 from tests.helpers import run_command, SuperModuleCleaner
@@ -476,16 +476,6 @@ class CoverageTest(
         return self.squeezed_lines(report)[-1]
 
 
-class DebugControlString(DebugControl):
-    """A `DebugControl` that writes to a StringIO, for testing."""
-    def __init__(self, options):
-        super(DebugControlString, self).__init__(options, StringIO())
-
-    def get_output(self):
-        """Get the output text from the `DebugControl`."""
-        return self.output.getvalue()
-
-
 def command_line(args, **kwargs):
     """Run `args` through the CoverageScript command line.
 
diff --git a/tests/test_data.py b/tests/test_data.py
index 52702e9..46999f6 100644
--- a/tests/test_data.py
+++ b/tests/test_data.py
@@ -13,10 +13,11 @@ import mock
 
 from coverage.backward import StringIO
 from coverage.data import CoverageData, CoverageDataFiles, debug_main, canonicalize_json_data
+from coverage.debug import DebugControlString
 from coverage.files import PathAliases, canonical_filename
 from coverage.misc import CoverageException
 
-from tests.coveragetest import CoverageTest, DebugControlString
+from tests.coveragetest import CoverageTest
 
 
 LINES_1 = {
diff --git a/tests/test_debug.py b/tests/test_debug.py
index b019915..6a33479 100644
--- a/tests/test_debug.py
+++ b/tests/test_debug.py
@@ -4,15 +4,15 @@
 """Tests of coverage/debug.py"""
 
 import os
-import re
 
 import pytest
 
 import coverage
 from coverage.backward import StringIO
-from coverage.debug import info_formatter, info_header, short_id, short_stack
+from coverage.debug import filter_text, info_formatter, info_header, short_id, short_stack
 
 from tests.coveragetest import CoverageTest
+from tests.helpers import re_lines
 
 
 class InfoFormatterTest(CoverageTest):
@@ -60,6 +60,17 @@ def test_short_id(id64, id16):
     assert short_id(id64) == id16
 
 
+@pytest.mark.parametrize("text, filters, result", [
+    ("hello", [], "hello"),
+    ("hello\n", [], "hello\n"),
+    ("hello\nhello\n", [], "hello\nhello\n"),
+    ("hello\nbye\n", [lambda x: "="+x], "=hello\n=bye\n"),
+    ("hello\nbye\n", [lambda x: "="+x, lambda x: x+"\ndone\n"], "=hello\ndone\n=bye\ndone\n"),
+])
+def test_filter_text(text, filters, result):
+    assert filter_text(text, filters) == result
+
+
 class DebugTraceTest(CoverageTest):
     """Tests of debug output."""
 
@@ -80,7 +91,7 @@ class DebugTraceTest(CoverageTest):
         self.start_import_stop(cov, "f1")
         cov.save()
 
-        out_lines = debug_out.getvalue().splitlines()
+        out_lines = debug_out.getvalue()
         return out_lines
 
     def test_debug_no_trace(self):
@@ -96,7 +107,7 @@ class DebugTraceTest(CoverageTest):
         self.assertIn("Tracing 'f1.py'", out_lines)
 
         # We should have lines like "Not tracing 'collector.py'..."
-        coverage_lines = lines_matching(
+        coverage_lines = re_lines(
             out_lines,
             r"^Not tracing .*: is part of coverage.py$"
             )
@@ -106,28 +117,29 @@ class DebugTraceTest(CoverageTest):
         out_lines = self.f1_debug_output(["trace", "pid"])
 
         # Now our lines are always prefixed with the process id.
-        pid_prefix = "^pid %5d: " % os.getpid()
-        pid_lines = lines_matching(out_lines, pid_prefix)
+        pid_prefix = r"^%5d\.[0-9a-f]{4}: " % os.getpid()
+        pid_lines = re_lines(out_lines, pid_prefix)
         self.assertEqual(pid_lines, out_lines)
 
         # We still have some tracing, and some not tracing.
-        self.assertTrue(lines_matching(out_lines, pid_prefix + "Tracing "))
-        self.assertTrue(lines_matching(out_lines, pid_prefix + "Not tracing "))
+        self.assertTrue(re_lines(out_lines, pid_prefix + "Tracing "))
+        self.assertTrue(re_lines(out_lines, pid_prefix + "Not tracing "))
 
     def test_debug_callers(self):
         out_lines = self.f1_debug_output(["pid", "dataop", "dataio", "callers"])
-        print("\n".join(out_lines))
+        print(out_lines)
         # For every real message, there should be a stack
         # trace with a line like "f1_debug_output : /Users/ned/coverage/tests/test_debug.py @71"
-        real_messages = lines_matching(out_lines, r"^pid\s+\d+: ")
+        real_messages = re_lines(out_lines, r" @\d+", match=False).splitlines()
         frame_pattern = r"\s+f1_debug_output : .*tests[/\\]test_debug.py @\d+$"
-        frames = lines_matching(out_lines, frame_pattern)
+        frames = re_lines(out_lines, frame_pattern).splitlines()
         self.assertEqual(len(real_messages), len(frames))
 
         # The last message should be "Writing data", and the last frame should
         # be write_file in data.py.
-        self.assertRegex(real_messages[-1], r"^pid\s+\d+: Writing data")
-        self.assertRegex(out_lines[-1], r"\s+write_file : .*coverage[/\\]data.py @\d+$")
+        self.assertRegex(real_messages[-1], r"^\d+\.\w{4}: Writing data")
+        last_line = out_lines.splitlines()[-1]
+        self.assertRegex(last_line, r"\s+write_file : .*coverage[/\\]data.py @\d+$")
 
     def test_debug_config(self):
         out_lines = self.f1_debug_output(["config"])
@@ -140,7 +152,10 @@ class DebugTraceTest(CoverageTest):
             """.split()
         for label in labels:
             label_pat = r"^\s*%s: " % label
-            self.assertEqual(len(lines_matching(out_lines, label_pat)), 1)
+            self.assertEqual(
+                len(re_lines(out_lines, label_pat).splitlines()),
+                1
+            )
 
     def test_debug_sys(self):
         out_lines = self.f1_debug_output(["sys"])
@@ -153,7 +168,7 @@ class DebugTraceTest(CoverageTest):
         for label in labels:
             label_pat = r"^\s*%s: " % label
             self.assertEqual(
-                len(lines_matching(out_lines, label_pat)),
+                len(re_lines(out_lines, label_pat).splitlines()),
                 1,
                 msg="Incorrect lines for %r" % label,
             )
@@ -191,8 +206,3 @@ class ShortStackTest(CoverageTest):
     def test_short_stack_skip(self):
         stack = f_one(skip=1).splitlines()
         self.assertIn("f_two", stack[-1])
-
-
-def lines_matching(lines, pat):
-    """Gives the list of lines from `lines` that match `pat`."""
-    return [l for l in lines if re.search(pat, l)]