Big refactor of debug logging

2 files changed, 124 insertions, 51 deletions

diff --git a/coverage/control.py b/coverage/control.py
index 4cc76459..30923b9d 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 5ffed39d..4cec390f 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
     )