Added more debugging controls, especially for data operations

4 files changed, 46 insertions, 14 deletions

diff --git a/coverage/control.py b/coverage/control.py
index fde6f63b..050b6fbd 100644
--- a/coverage/control.py
+++ b/coverage/control.py
@@ -201,9 +201,15 @@ class Coverage(object):
         if self._inited:
             return
 
-        # Create and configure the debugging controller.
+        # Create and configure the debugging controller. COVERAGE_DEBUG_FILE
+        # is an environment variable, the name of a file to append debug logs
+        # to.
         if self._debug_file is None:
-            self._debug_file = sys.stderr
+            debug_file_name = os.environ.get("COVERAGE_DEBUG_FILE")
+            if debug_file_name:
+                self._debug_file = open(debug_file_name, "a")
+            else:
+                self._debug_file = sys.stderr
         self.debug = DebugControl(self.config.debug, self._debug_file)
 
         # Load plugins
diff --git a/coverage/data.py b/coverage/data.py
index eed9406a..c09816df 100644
--- a/coverage/data.py
+++ b/coverage/data.py
@@ -319,6 +319,10 @@ class CoverageData(object):
         data.
 
         """
+        if self._debug and self._debug.should('dataop'):
+            self._debug.write("Setting lines: %d files, %d lines total" % (
+                len(line_data), sum(len(lines) for lines in line_data.values())
+            ))
         if self._has_arcs():
             raise CoverageException("Can't add lines to existing arc data")
 
@@ -336,6 +340,10 @@ class CoverageData(object):
         data.
 
         """
+        if self._debug and self._debug.should('dataop'):
+            self._debug.write("Setting arcs: %d files, %d arcs total" % (
+                len(arc_data), sum(len(arcs) for arcs in arc_data.values())
+            ))
         if self._has_lines():
             raise CoverageException("Can't add arcs to existing line data")
 
@@ -350,6 +358,9 @@ class CoverageData(object):
         `file_tracers` is { filename: plugin_name, ... }
 
         """
+        if self._debug and self._debug.should('dataop'):
+            self._debug.write("Setting file tracers: %d files" % (len(file_tracers),))
+
         existing_files = self._arcs or self._lines
         for filename, plugin_name in iitems(file_tracers):
             if filename not in existing_files:
@@ -375,6 +386,8 @@ class CoverageData(object):
         but repeated keywords overwrite each other.
 
         """
+        if self._debug and self._debug.should('dataop'):
+            self._debug.write("Adding run info: %r" % (kwargs,))
         if not self._runs:
             self._runs = [{}]
         self._runs[0].update(kwargs)
@@ -382,6 +395,8 @@ class CoverageData(object):
 
     def touch_file(self, filename):
         """Ensure that `filename` appears in the data, empty if needed."""
+        if self._debug and self._debug.should('dataop'):
+            self._debug.write("Touching %r" % (filename,))
         (self._arcs or self._lines).setdefault(filename, [])
         self._validate()
 
diff --git a/coverage/debug.py b/coverage/debug.py
index 8d36c1cd..8ae087d7 100644
--- a/coverage/debug.py
+++ b/coverage/debug.py
@@ -7,6 +7,7 @@ import inspect
 import json
 import os
 import re
+import sys
 
 
 # When debugging, it can be helpful to force some options, especially when
@@ -27,9 +28,7 @@ class DebugControl(object):
         self.output = output
 
     def __repr__(self):
-        return "<DebugControl options=%r output=%r>" % (
-            self.options, self.output
-            )
+        return "<DebugControl options=%r output=%r>" % (self.options, self.output)
 
     def should(self, option):
         """Decide whether to output debug information in category `option`."""
@@ -40,6 +39,8 @@ class DebugControl(object):
         if self.should('pid'):
             msg = "pid %5d: %s" % (os.getpid(), msg)
         self.output.write(msg+"\n")
+        if self.should('callers'):
+            dump_stack_frames(self.output)
         self.output.flush()
 
     def write_formatted_info(self, header, info):
@@ -94,9 +95,11 @@ def short_stack():                                          # pragma: debugging
     return "\n".join("%30s : %s @%d" % (t[3], t[1], t[2]) for t in stack)
 
 
-def dump_stack_frames():                                    # pragma: debugging
-    """Print a summary of the stack to stdout."""
-    print(short_stack())
+def dump_stack_frames(out=None):                            # pragma: debugging
+    """Print a summary of the stack to stdout, or some place else."""
+    out = out or sys.stdout
+    out.write(short_stack())
+    out.write("\n")
 
 
 def pretty_data(data):
diff --git a/doc/cmd.rst b/doc/cmd.rst
index a438eb33..83acb888 100644
--- a/doc/cmd.rst
+++ b/doc/cmd.rst
@@ -417,22 +417,30 @@ and ``data`` to show a summary of the collected coverage data.
 The ``--debug`` option is available on all commands.  It instructs coverage.py
 to log internal details of its operation, to help with diagnosing problems.  It
 takes a comma-separated list of options, each indicating a facet of operation
-to log to stderr:
+to log:
 
-* ``trace``: print every decision about whether to trace a file or not. For
-  files not being traced, the reason is also given.
+* ``callers``: annotate each debug message with a stack trace of the callers
+  to that point.
 
 * ``config``: before starting, dump all the :ref:`configuration <config>`
   values.
 
-* ``sys``: before starting, dump all the system and environment information,
-  as with :ref:`coverage debug sys <cmd_debug>`.
-
 * ``dataio``: log when reading or writing any data file.
 
+* ``dataop``: log when data is added to the CoverageData object.
+
 * ``pid``: annotate all debug output with the process id.
 
 * ``plugin``: print information about plugin operations.
 
+* ``sys``: before starting, dump all the system and environment information,
+  as with :ref:`coverage debug sys <cmd_debug>`.
+
+* ``trace``: print every decision about whether to trace a file or not. For
+  files not being traced, the reason is also given.
+
 Debug options can also be set with the ``COVERAGE_DEBUG`` environment variable,
 a comma-separated list of these options.
+
+The debug output goes to stderr, unless the ``COVERAGE_DEBUG_FILE`` environment
+variable names a different file, which will be appended to.