diff options
| -rw-r--r-- | coverage/control.py | 14 | ||||
| -rw-r--r-- | coverage/debug.py | 161 | ||||
| -rw-r--r-- | doc/cmd.rst | 3 | ||||
| -rw-r--r-- | tests/coveragetest.py | 12 | ||||
| -rw-r--r-- | tests/test_data.py | 3 | ||||
| -rw-r--r-- | tests/test_debug.py | 50 |
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)] |