Skip to content

Commit

Permalink
wip: prevent ghost local events
Browse files Browse the repository at this point in the history 
python/cpython#111963
  • Loading branch information
@nedbat
nedbat committed Nov 30, 2023
1 parent ced46f4 commit f524742
Showing 1 changed file with 82 additions and 65 deletions.
147 changes: 82 additions & 65 deletions coverage/pep669_tracer.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,20 +15,30 @@
import sys
import threading
import traceback
import weakref

from types import CodeType, FrameType, ModuleType
from typing import Any, Callable, Dict, List, Optional, Set, Tuple, cast

#from coverage.debug import short_stack
from coverage.types import (
TArc, TFileDisposition, TLineNo, TTraceData, TTraceFileData, TTraceFn,
TTracer, TWarnFn,
)

# When running meta-coverage, this file can try to trace itself, which confuses
# everything. Don't trace ourselves.

THIS_FILE = __file__.rstrip("co")
class LoggingWrapper:
def __init__(self, wrapped, namespace):
self.wrapped = wrapped
self.namespace = namespace

def __getattr__(self, name):
def _wrapped(*args, **kwargs):
log(f"{self.namespace}.{name}{args}{kwargs}")
return getattr(self.wrapped, name)(*args, **kwargs)
return _wrapped

#sys_monitoring = LoggingWrapper(sys.monitoring, "sys.monitoring")
sys_monitoring = getattr(sys, "monitoring", None)

seen_threads = set()

Expand All @@ -37,7 +47,7 @@ def log(msg):
# Thread ids are reused across processes? Make a shorter number more likely
# to be unique.
pid = os.getpid()
tid = (os.getpid() * threading.current_thread().ident) % 9_999_991
tid = (pid * threading.current_thread().ident) % 9_999_991
tid = f"{tid:07d}"
if tid not in seen_threads:
seen_threads.add(tid)
Expand All @@ -55,7 +65,7 @@ def log(msg):
]
FILENAME_SUBS = []

def fname_repr(filename):
def short_fname(filename):
if not FILENAME_SUBS:
for pathdir in sys.path:
FILENAME_SUBS.append((pathdir, "syspath:"))
Expand All @@ -67,38 +77,41 @@ def fname_repr(filename):
filename = re.sub(pat, sub, filename)
for before, after in FILENAME_SUBS:
filename = filename.replace(before, after)
return repr(filename)
return filename

def arg_repr(arg):
if isinstance(arg, CodeType):
arg_repr = f"<name={arg.co_name}, file={fname_repr(arg.co_filename)}#{arg.co_firstlineno}>"
arg_repr = f"<code @{id(arg):#x} name={arg.co_name}, file={short_fname(arg.co_filename)!r}#{arg.co_firstlineno}>"
else:
arg_repr = repr(arg)
return arg_repr

def short_stack(full=True):
stack: Iterable[inspect.FrameInfo] = inspect.stack()[::-1]
return "\n".join(f"{fi.function:>30s} : 0x{id(fi.frame):x} {fi.filename}:{fi.lineno}" for fi in stack)
return "\n".join(f"{fi.function:>30s} : {id(fi.frame):#x} {short_fname(fi.filename)}:{fi.lineno}" for fi in stack)

def panopticon(*names):
def _decorator(meth):
def _wrapped(self, *args):
try:
# log("stack:\n" + short_stack())
# args_reprs = []
# for name, arg in zip(names, args):
# if name is None:
# continue
# args_reprs.append(f"{name}={arg_repr(arg)}")
# log(f"{id(self)}:{meth.__name__}({', '.join(args_reprs)})")
args_reprs = []
for name, arg in zip(names, args):
if name is None:
continue
args_reprs.append(f"{name}={arg_repr(arg)}")
log(f"{id(self):#x}:{meth.__name__}({', '.join(args_reprs)})")
ret = meth(self, *args)
# log(f" end {id(self)}:{meth.__name__}({', '.join(args_reprs)})")
#log(f" end {id(self):#x}:{meth.__name__}({', '.join(args_reprs)})")
return ret
except Exception as exc:
log(f"{exc.__class__.__name__}: {exc}")
with open("/tmp/pan.out", "a") as f:
traceback.print_exception(exc, file=f)
sys.monitoring.set_events(sys.monitoring.COVERAGE_ID, 0)
log(f"!!{exc.__class__.__name__}: {exc}")
log("".join(traceback.format_exception(exc)))
try:
sys_monitoring.set_events(sys.monitoring.COVERAGE_ID, 0)
except ValueError:
# We might have already shut off monitoring.
log(f"oops, shutting off events with disabled tool id")
raise
return _wrapped
return _decorator
Expand Down Expand Up @@ -126,7 +139,8 @@ class Pep669Tracer(TTracer):
# One of these will be used across threads. Be careful.

def __init__(self) -> None:
log(f"Pep669Tracer.__init__: @{id(self)}\n{short_stack()}")
test_name = os.environ.get("PYTEST_CURRENT_TEST", "no-test")
log(f"Pep669Tracer.__init__: @{id(self):#x} in {test_name}\n{short_stack()}")
# pylint: disable=super-init-not-called
# Attributes set from the collector:
self.data: TTraceData
Expand All @@ -137,16 +151,14 @@ def __init__(self) -> None:
self.switch_context: Optional[Callable[[Optional[str]], None]] = None
self.warn: TWarnFn

# The threading module to use, if any.
self.threading: Optional[ModuleType] = None

self.code_infos: Dict[CodeType, CodeInfo] = {}
self.last_lines: Dict[FrameType, int] = {}
self.local_event_codes = None

self.stats = {
"starts": 0,
}

self.thread: Optional[threading.Thread] = None
self.stopped = False
self._activity = False

Expand All @@ -155,45 +167,40 @@ def __init__(self) -> None:
atexit.register(setattr, self, "in_atexit", True)

def __repr__(self) -> str:
me = id(self)
points = sum(len(v) for v in self.data.values())
files = len(self.data)
return f"<Pep669Tracer at 0x{me:x}: {points} data points in {files} files>"
return f"<Pep669Tracer at {id(self):#x}: {points} data points in {files} files>"

@panopticon()
def start(self) -> TTraceFn: # TODO: wrong return type
"""Start this Tracer."""
self.stopped = False
if self.threading:
if self.thread is None:
self.thread = self.threading.current_thread()
else:
if self.thread.ident != self.threading.current_thread().ident:
# Re-starting from a different thread!? Don't set the trace
# function, but we are marked as running again, so maybe it
# will be ok?
1/0
return self._cached_bound_method_trace

self.local_event_codes = weakref.WeakSet()
self.myid = sys.monitoring.COVERAGE_ID
sys.monitoring.use_tool_id(self.myid, "coverage.py")
sys_monitoring.use_tool_id(self.myid, "coverage.py")
events = sys.monitoring.events
sys.monitoring.set_events(
sys_monitoring.set_events(
self.myid,
events.PY_START | events.PY_RETURN | events.PY_RESUME | events.PY_YIELD | events.PY_UNWIND,
events.PY_START | events.PY_UNWIND,
)
sys.monitoring.register_callback(self.myid, events.PY_START, self.sysmon_py_start)
sys.monitoring.register_callback(self.myid, events.PY_RESUME, self.sysmon_py_resume)
sys.monitoring.register_callback(self.myid, events.PY_RETURN, self.sysmon_py_return)
sys.monitoring.register_callback(self.myid, events.PY_YIELD, self.sysmon_py_yield)
sys.monitoring.register_callback(self.myid, events.PY_UNWIND, self.sysmon_py_unwind)
sys.monitoring.register_callback(self.myid, events.LINE, self.sysmon_line)
sys.monitoring.register_callback(self.myid, events.BRANCH, self.sysmon_branch)
sys.monitoring.register_callback(self.myid, events.JUMP, self.sysmon_jump)

sys_monitoring.register_callback(self.myid, events.PY_START, self.sysmon_py_start)
sys_monitoring.register_callback(self.myid, events.PY_RESUME, self.sysmon_py_resume)
sys_monitoring.register_callback(self.myid, events.PY_RETURN, self.sysmon_py_return)
sys_monitoring.register_callback(self.myid, events.PY_YIELD, self.sysmon_py_yield)
sys_monitoring.register_callback(self.myid, events.PY_UNWIND, self.sysmon_py_unwind)
sys_monitoring.register_callback(self.myid, events.LINE, self.sysmon_line)
sys_monitoring.register_callback(self.myid, events.BRANCH, self.sysmon_branch)
sys_monitoring.register_callback(self.myid, events.JUMP, self.sysmon_jump)

@panopticon()
def stop(self) -> None:
"""Stop this Tracer."""
sys.monitoring.set_events(self.myid, 0)
sys.monitoring.free_tool_id(self.myid)
sys_monitoring.set_events(self.myid, 0)
for code in self.local_event_codes:
sys_monitoring.set_local_events(self.myid, code, 0)
self.local_event_codes = None
sys_monitoring.free_tool_id(self.myid)

def activity(self) -> bool:
"""Has there been any activity?"""
Expand Down Expand Up @@ -255,19 +262,20 @@ def sysmon_py_start(self, code, instruction_offset: int):

if tracing_code:
events = sys.monitoring.events
log(f"set_local_events(code={arg_repr(code)})")
sys.monitoring.set_local_events(
sys_monitoring.set_local_events(
self.myid,
code,
sys.monitoring.events.LINE |
sys.monitoring.events.BRANCH |
sys.monitoring.events.JUMP,
events.PY_RETURN | events.PY_RESUME | events.PY_YIELD |
events.LINE |
events.BRANCH |
events.JUMP,
)
self.local_event_codes.add(code)

if tracing_code:
frame = self.callers_frame()
self.last_lines[frame] = -code.co_firstlineno
log(f" {file_data=}")
#log(f" {file_data=}")

@panopticon("code", "@")
def sysmon_py_resume(self, code, instruction_offset: int):
Expand All @@ -282,10 +290,10 @@ def sysmon_py_return(self, code, instruction_offset: int, retval: object):
if self.trace_arcs:
arc = (self.last_lines[frame], -code.co_firstlineno)
cast(Set[TArc], code_info.file_data).add(arc)
log(f" add1({arc=})")
#log(f" add1({arc=})")

# Leaving this function, no need for the frame any more.
log(f" popping frame 0x{id(frame):x}")
#log(f" popping frame {id(frame):#x}")
self.last_lines.pop(frame, None)

@panopticon("code", "@", None)
Expand All @@ -300,29 +308,38 @@ def sysmon_py_unwind(self, code, instruction_offset: int, exception):
if self.trace_arcs:
arc = (self.last_lines[frame], -code.co_firstlineno)
cast(Set[TArc], code_info.file_data).add(arc)
log(f" add3({arc=})")
#log(f" add3({arc=})")

# Leaving this function.
self.last_lines.pop(frame, None)

@panopticon("code", "line")
def sysmon_line(self, code, line_number: int):
frame = self.callers_frame()
code_info = self.code_infos[code]
if not code_info.tracing:
log("DISABLE")
return sys.monitoring.DISABLE
if code_info.file_data is not None:
frame = self.callers_frame()
if self.trace_arcs:
arc = (self.last_lines[frame], line_number)
cast(Set[TArc], code_info.file_data).add(arc)
log(f" add4({arc=})")
#log(f" add4({arc=})")
else:
cast(Set[TLineNo], code_info.file_data).add(line_number)
log(f" add5({line_number=})")
#log(f" add5({line_number=})")
self.last_lines[frame] = line_number

@panopticon("code", "from@", "to@")
def sysmon_branch(self, code, instruction_offset: int, destination_offset: int):
...
code_info = self.code_infos[code]
if not code_info.tracing:
log("DISABLE")
return sys.monitoring.DISABLE

@panopticon("code", "from@", "to@")
def sysmon_jump(self, code, instruction_offset: int, destination_offset: int):
...
code_info = self.code_infos[code]
if not code_info.tracing:
log("DISABLE")
return sys.monitoring.DISABLE

0 comments on commit f524742

Please sign in to comment.