debug: more details in debug messages

Author: nedbat

coverage/debug.py

@@ -8,6 +8,7 @@
 import _thread
 import atexit
 import contextlib
+import datetime
 import functools
 import inspect
 import itertools
@@ -19,13 +20,7 @@
 import traceback
 import types
 from collections.abc import Iterable, Iterator, Mapping
-from typing import (
-    IO,
-    Any,
-    Callable,
-    Final,
-    overload,
-)
+from typing import IO, Any, Callable, Final, overload
 
 from coverage.misc import human_sorted_items, isolate_module
 from coverage.types import AnyCallable, TWritable
@@ -222,6 +217,20 @@ def short_filename(filename: str | None) -> str | None:
     return filename
 
 
+def file_summary(filename: str) -> str:
+    """A one-line summary of a file, for log messages."""
+    try:
+        s = os.stat(filename)
+    except FileNotFoundError:
+        summary = "does not exist"
+    except Exception as e:
+        summary = f"error: {e}"
+    else:
+        mod = datetime.datetime.fromtimestamp(s.st_mtime)
+        summary = f"{s.st_size} bytes, modified {mod}"
+    return summary
+
+
 def short_stack(
     skip: int = 0,
     full: bool = False,

coverage/patch.py

@@ -56,7 +56,7 @@ def _patch__exit(cov: Coverage, debug: TDebugCtl) -> None:
 
     def coverage_os_exit_patch(status: int) -> NoReturn:
         with contextlib.suppress(Exception):
-            debug.write("Using _exit patch")
+            debug.write(f"Using _exit patch with {cov = }")
         with contextlib.suppress(Exception):
             cov.save()
         old_exit(status)
@@ -74,7 +74,7 @@ def _patch_execv(cov: Coverage, config: CoverageConfig, debug: TDebugCtl) -> Non
     def make_execv_patch(fname: str, old_execv: Any) -> Any:
         def coverage_execv_patch(*args: Any, **kwargs: Any) -> Any:
             with contextlib.suppress(Exception):
-                debug.write(f"Using execv patch for {fname}")
+                debug.write(f"Using execv patch for {fname} with {cov = }")
             with contextlib.suppress(Exception):
                 cov.save()
 

coverage/sqldata.py

@@ -20,13 +20,9 @@
 import threading
 import zlib
 from collections.abc import Collection, Mapping, Sequence
-from typing import (
-    Any,
-    Callable,
-    cast,
-)
+from typing import Any, Callable, cast
 
-from coverage.debug import NoDebugging, auto_repr
+from coverage.debug import NoDebugging, auto_repr, file_summary
 from coverage.exceptions import CoverageException, DataError
 from coverage.misc import file_be_gone, isolate_module
 from coverage.numbits import numbits_to_nums, numbits_union, nums_to_numbits
@@ -120,7 +116,7 @@ def _wrapped(self: CoverageData, *args: Any, **kwargs: Any) -> Any:
             self._debug.write(f"Locking {self._lock!r} for {method.__name__}")
         with self._lock:
             if self._debug.should("lock"):
-                self._debug.write(f"Locked  {self._lock!r} for {method.__name__}")
+                self._debug.write(f"Locked {self._lock!r} for {method.__name__}")
             return method(self, *args, **kwargs)
     return _wrapped
 
@@ -259,6 +255,11 @@ def __init__(
 
     __repr__ = auto_repr
 
+    def _debug_dataio(self, msg: str, filename: str) -> None:
+        """A helper for debug messages which are all similar."""
+        if self._debug.should("dataio"):
+            self._debug.write(f"{msg} {filename!r} ({file_summary(filename)})")
+
     def _choose_filename(self) -> None:
         """Set self._filename based on inited attributes."""
         if self._no_disk:
@@ -287,8 +288,7 @@ def close(self, force: bool = False) -> None:
 
     def _open_db(self) -> None:
         """Open an existing db file, and read its metadata."""
-        if self._debug.should("dataio"):
-            self._debug.write(f"Opening data file {self._filename!r}")
+        self._debug_dataio("Opening data file", self._filename)
         self._dbs[threading.get_ident()] = SqliteDb(self._filename, self._debug)
         self._read_db()
 
@@ -327,8 +327,7 @@ def _read_db(self) -> None:
 
     def _init_db(self, db: SqliteDb) -> None:
         """Write the initial contents of the database."""
-        if self._debug.should("dataio"):
-            self._debug.write(f"Initing data file {self._filename!r}")
+        self._debug_dataio("Initing data file", self._filename)
         db.executescript(SCHEMA)
         db.execute_void("insert into coverage_schema (version) values (?)", (SCHEMA_VERSION,))
 
@@ -377,8 +376,7 @@ def dumps(self) -> bytes:
         .. versionadded:: 5.0
 
         """
-        if self._debug.should("dataio"):
-            self._debug.write(f"Dumping data from data file {self._filename!r}")
+        self._debug_dataio("Dumping data from data file", self._filename)
         with self._connect() as con:
             script = con.dump()
             return b"z" + zlib.compress(script.encode("utf-8"))
@@ -398,8 +396,7 @@ def loads(self, data: bytes) -> None:
         .. versionadded:: 5.0
 
         """
-        if self._debug.should("dataio"):
-            self._debug.write(f"Loading data into data file {self._filename!r}")
+        self._debug_dataio("Loading data into data file", self._filename)
         if data[:1] != b"z":
             raise DataError(
                 f"Unrecognized serialization: {data[:40]!r} (head of {len(data)} bytes)",
@@ -834,16 +831,14 @@ def erase(self, parallel: bool = False) -> None:
         self._reset()
         if self._no_disk:
             return
-        if self._debug.should("dataio"):
-            self._debug.write(f"Erasing data file {self._filename!r}")
+        self._debug_dataio("Erasing data file", self._filename)
         file_be_gone(self._filename)
         if parallel:
             data_dir, local = os.path.split(self._filename)
             local_abs_path = os.path.join(os.path.abspath(data_dir), local)
             pattern = glob.escape(local_abs_path) + ".*"
             for filename in glob.glob(pattern):
-                if self._debug.should("dataio"):
-                    self._debug.write(f"Erasing parallel data file {filename!r}")
+                self._debug_dataio("Erasing parallel data file", filename)
                 file_be_gone(filename)
 
     def read(self) -> None:
@@ -854,7 +849,7 @@ def read(self) -> None:
 
     def write(self) -> None:
         """Ensure the data is written to the data file."""
-        pass
+        self._debug_dataio("Writing (no-op) data file", self._filename)
 
     def _start_using(self) -> None:
         """Call this before using the database at all."""

tests/test_data.py

@@ -727,11 +727,14 @@ def test_debug_output_with_debug_option(self) -> None:
         print(debug.get_output())
 
         assert re.search(
-            r"^Closing dbs, force=False: {}\n" +
-            r"Erasing data file '.*\.coverage'\n" +
-            r"Opening data file '.*\.coverage'\n" +
-            r"Initing data file '.*\.coverage'\n" +
-            r"Opening data file '.*\.coverage'\n$",
+            r"^" +
+            r"Closing dbs, force=False: {}\n" +
+            r"Erasing data file '.*\.coverage' \(does not exist\)\n" +
+            r"Opening data file '.*\.coverage' \(does not exist\)\n" +
+            r"Initing data file '.*\.coverage' \(0 bytes, modified [-:. 0-9]+\)\n" +
+            r"Writing \(no-op\) data file '.*\.coverage' \(\d+ bytes, modified [-:. 0-9]+\)\n" +
+            r"Opening data file '.*\.coverage' \(\d+ bytes, modified [-:. 0-9]+\)\n" +
+            r"$",
             debug.get_output(),
         )
 

tests/test_debug.py

@@ -162,8 +162,8 @@ def test_debug_trace_pid(self) -> None:
     def test_debug_callers(self) -> None:
         out_text = self.f1_debug_output(["pid", "dataop", "dataio", "callers", "lock"])
         # 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 = re_lines(r":\d+", out_text, match=False)
+        #       "f1_debug_output : /Users/ned/coverage/tests/test_debug.py:71"
+        real_messages = re_lines(r"\.py:\d+$", out_text, match=False)
         frame_pattern = r"\s+f1_debug_output : .*tests[/\\]test_debug.py:\d+$"
         frames = re_lines(frame_pattern, out_text)
         assert len(real_messages) == len(frames)
@@ -173,8 +173,8 @@ def test_debug_callers(self) -> None:
         # The details of what to expect on the stack are empirical, and can change
         # as the code changes. This test is here to ensure that the debug code
         # continues working. It's ok to adjust these details over time.
-        assert re_lines(r"^\s*\d+\.\w{4}: Adding file tracers: 0 files", real_messages[-1])
-        assert re_lines(r"\s+add_file_tracers : .*coverage[/\\]sqldata.py:\d+$", last_line)
+        assert re_lines(r"^\s*\d+\.\w{4}: Writing \(no-op\) data file", real_messages[-1])
+        assert re_lines(r"\s+_debug_dataio : .*coverage[/\\]sqldata.py:\d+$", last_line)
 
     def test_debug_config(self) -> None:
         out_text = self.f1_debug_output(["config"])