diff --git a/CHANGELOG.md b/CHANGELOG.md index ef4076d..54d37ba 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,24 @@ - Race messages name the threads (`by thread T5 (ftm-refill)`), the text summary labels each stack with its thread, and JSON stacks carry a `thread` field. - A race whose access is in PyO3's own source says so, with the PyO3 version and line. +- **`stress/panic` is located per call, not per message.** The driver records the native + thread of each panic and Rust prints the same id in its panic line, so two sites that + panic with the same message are two findings, each naming the callables that panicked + there with their own counts. When Rust prints no thread id, a finding lists every + site that shares the message. +- **A panic inside a dependency says so.** The message names the dependency and its + version (and PyO3's argument conversion when the site is there), and the headline + counts it as "inside a dependency, reached from your extension". When the log holds a + Rust backtrace, the first frame in the crate's own code is the location. +- A `stress/panic` message says when mutators were running. + +### JSON + +- `stress.panics`: every distinct panic message per callable, with a count. +- `stress.panic_threads`: per native thread id, the panicking calls in order, as + `[callable, message, count]` runs. +- A `stress/panic` finding inside a dependency carries `dependency` (for example + `"pyo3 0.29.2"`). ## 0.1.0 — 2026-09-25 diff --git a/docs/limitations.md b/docs/limitations.md index 4186dd8..d7d8bb6 100644 --- a/docs/limitations.md +++ b/docs/limitations.md @@ -47,15 +47,19 @@ Known gaps, each still open: invisible to it. - **Exceptions raised only under concurrency**, other than Rust panics, are counted in the JSON output (`stress.exceptions`) but not surfaced in the text summary. -- **A panic raised inside a dependency's code** is located at the dependency's source - line, not at the frame of yours that led there. The finding's symbol is the only pointer - to your callable. -- **Panic locations are matched by message text.** When two sites panic with the same - message, a finding can be filed at the other site, and the second site may not appear - as a finding of its own. +- **A panic raised inside a dependency's code** is labelled with the dependency and + located at its source line. The frame of yours that led there is found only when the + log holds a Rust backtrace: replay with `RUST_BACKTRACE=1` set. Backtraces are off by + default because printing one for every panic slows each panicking call about tenfold, + which changes the schedule under test. +- **Panic sites are told apart by thread id**, which current Rust prints in its panic + line. With a toolchain that prints none, a panic is located by its message, and when + two sites share the message the finding lists both without saying which call panicked + where. - **A panic on input a mutator made invalid reads as a concurrency panic**, because the - single-threaded baseline never sees the mutator's transient state. A mutator must keep - the shared inputs valid at every instant. + single-threaded baseline never sees the mutator's transient state. The finding says + when mutators were running, but does not check whether one caused it. A mutator must + keep the shared inputs valid at every instant. - **Some dependency-internal TSan reports still fail runs.** Beyond the suppressed crossbeam-deque race, reports inside dependencies' fence-based synchronisation (which TSan does not model) and glibc's thread-local teardown can be filed as "in your diff --git a/docs/stress.md b/docs/stress.md index 65f79b9..601071a 100644 --- a/docs/stress.md +++ b/docs/stress.md @@ -134,7 +134,7 @@ was, so that shows mutators reach this class of bug, not that they find it unaid A mutator must keep the shared inputs **valid at every instant**. The baseline never sees a mutator's transient state, so a call that panics on input the mutator made invalid is -reported as a panic under concurrency. +reported as a panic under concurrency. The finding says that mutators were running. A mutator that only **rewrites a buffer's contents** in place (a slice assignment into a `bytearray` the extension is reading, or a numpy array refilled with `arr[:] = ...`) races @@ -199,10 +199,15 @@ across Python threads, so they are neither driven nor counted as a coverage hole **Panics under contention are findings.** A Rust panic (`PanicException`) that a callable raises under concurrency but never in its baseline is -reported as `stress/panic`, with the count, the first panic message and — from Rust's +reported as `stress/panic`, with the count, the panic message and — from Rust's own panic output — the source line that panicked. Callables panicking at the same line are -one finding. The line is matched by panic message, so two sites panicking with the same -message can be filed under one of them (see Limits). It is not a data +one finding, with each callable's own count. The driver records the thread each panic +happened on, and Rust prints the same thread id in its panic line, so two sites panicking +with the same message are two findings. A panic inside a dependency (PyO3, another crate, +the standard library) says so and carries a `dependency` field, and the headline counts it +as inside a dependency rather than in your extension. When the log holds a Rust +backtrace (replay with `RUST_BACKTRACE=1` set), the first frame in your own code becomes +the location. It is not a data race and TSan may see nothing, but it is contention the code does not handle — and since `PanicException` is a `BaseException`, callers' `except Exception` will not catch it. A panic the baseline also raised is how the method treats those arguments, and @@ -289,9 +294,9 @@ relative to that directory. Every run prints the complete command that replays i - **Wrong results are not checked.** A call that returns a wrong value under concurrency without raising is invisible; exceptions other than panics that occur only under concurrency are counted in the JSON output but not surfaced in the summary. -- **Panic attribution is coarse.** A panic inside a dependency is located at the - dependency's source line, not at your frame that led there; panic sites are matched by - message text, so one site can hide another with the same message. +- **A panic inside a dependency is located at the dependency's line** unless the log holds + a backtrace (replay with `RUST_BACKTRACE=1`). When the toolchain prints no thread + id in its panic lines, sites that share a message are listed together. - **Mutators must keep inputs valid** (above), or their transient state reads as a - concurrency panic. + concurrency panic; the finding says mutators were running, nothing more. - See [limitations.md](limitations.md#what-stress-does-not-report-yet) for the full list. diff --git a/fixtures/racy/stress-panic-two-sites/Cargo.lock b/fixtures/racy/stress-panic-two-sites/Cargo.lock new file mode 100644 index 0000000..35d755f --- /dev/null +++ b/fixtures/racy/stress-panic-two-sites/Cargo.lock @@ -0,0 +1,132 @@ +# This file is automatically @generated by Cargo. +# It is not intended for manual editing. +version = 4 + +[[package]] +name = "heck" +version = "0.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2304e00983f87ffb38b55b444b5e3b60a884b5d30c0fca7d82fe33449bbe55ea" + +[[package]] +name = "libc" +version = "0.2.189" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3eaf3ede3fee6db1a4c2ee091bf8a8b4dccdc6d17f656fb07896ee72867612f2" + +[[package]] +name = "once_cell" +version = "1.21.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9f7c3e4beb33f85d45ae3e3a1792185706c8e16d043238c593331cc7cd313b50" + +[[package]] +name = "portable-atomic" +version = "1.15.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "05c8b63e8d9609db387f0324918f81d68fe27748f084ef092fb35954d0539a85" + +[[package]] +name = "proc-macro2" +version = "1.0.107" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "985e7ec9bb745e6ce6535b544d84d6cd6f7ad8bd711c398938ae983b91a766d9" +dependencies = [ + "unicode-ident", +] + +[[package]] +name = "pyo3" +version = "0.29.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4688ddedf473e32662b9b067670129a8afb8c18e351482c70d62ba4a88171e8b" +dependencies = [ + "libc", + "once_cell", + "portable-atomic", + "pyo3-build-config", + "pyo3-ffi", + "pyo3-macros", +] + +[[package]] +name = "pyo3-build-config" +version = "0.29.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f41027e41b4bd03f6e60f9f417fe24a6341a6bb744edd62b6f709f2a52ea30e9" +dependencies = [ + "target-lexicon", +] + +[[package]] +name = "pyo3-ffi" +version = "0.29.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e591a95526fead067432c3b3a33fc74770b87b1e04e73671090d9c2055a2b327" +dependencies = [ + "libc", + "pyo3-build-config", +] + +[[package]] +name = "pyo3-macros" +version = "0.29.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "73225868fc1cd84eef2c3c230ddb91273bf1de46aeb8a4248da76d32a0924a1c" +dependencies = [ + "proc-macro2", + "pyo3-macros-backend", + "quote", + "syn", +] + +[[package]] +name = "pyo3-macros-backend" +version = "0.29.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "571575aa3749fa6216757dd47d2a3e7ef360f329a40f0666a9fbd14889024952" +dependencies = [ + "heck", + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "quote" +version = "1.0.47" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1fbf4db142a473a8d80c26bbf18454ed458bf8d26c8219c331daecfdbd079001" +dependencies = [ + "proc-macro2", +] + +[[package]] +name = "stress-panic-two-sites" +version = "0.0.0" +dependencies = [ + "pyo3", +] + +[[package]] +name = "syn" +version = "2.0.119" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "872831b642d1a07999a962a351ed35b955ea2cfc8f3862091e2a240a84f17297" +dependencies = [ + "proc-macro2", + "quote", + "unicode-ident", +] + +[[package]] +name = "target-lexicon" +version = "0.13.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "adb6935a6f5c20170eeceb1a3835a49e12e19d792f6dd344ccc76a985ca5a6ca" + +[[package]] +name = "unicode-ident" +version = "1.0.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d245f478577f809a851594d02313b640fb437e0bb33866753cff937863096954" diff --git a/fixtures/racy/stress-panic-two-sites/Cargo.toml b/fixtures/racy/stress-panic-two-sites/Cargo.toml new file mode 100644 index 0000000..8ce0500 --- /dev/null +++ b/fixtures/racy/stress-panic-two-sites/Cargo.toml @@ -0,0 +1,12 @@ +[package] +name = "stress-panic-two-sites" +version = "0.0.0" +edition = "2021" +publish = false + +[lib] +name = "stress_panic_two_sites" +crate-type = ["cdylib", "rlib"] + +[dependencies] +pyo3 = { version = "0.29", features = ["extension-module"] } diff --git a/fixtures/racy/stress-panic-two-sites/expected.toml b/fixtures/racy/stress-panic-two-sites/expected.toml new file mode 100644 index 0000000..6d7583d --- /dev/null +++ b/fixtures/racy/stress-panic-two-sites/expected.toml @@ -0,0 +1,5 @@ +race = false +rules = [] +stress_rules = ["stress/panic"] +symbols = ["head", "tail"] +justification = "Two `try_lock().expect()` sites with the same message on one shared instance: neither panics on one thread, each panics at its own line once two threads overlap. Not a data race (a real mutex guards the data), so TSan must stay silent. `stress` must report two stress/panic findings, one per line, each naming only the method that panicked there. Matching panics to sites by message text filed both under one line." diff --git a/fixtures/racy/stress-panic-two-sites/src/lib.rs b/fixtures/racy/stress-panic-two-sites/src/lib.rs new file mode 100644 index 0000000..c254f7d --- /dev/null +++ b/fixtures/racy/stress-panic-two-sites/src/lib.rs @@ -0,0 +1,43 @@ +//! Two panic sites with one message — not a data race. +//! +//! `head` and `tail` each take the same exclusive claim with `try_lock` and +//! `expect` it, with the same message. On one thread neither panics; as soon +//! as two threads overlap, each panics at its own line. The two sites print +//! identical messages, so a tool that locates panics by message alone files +//! both under one line and loses the other. Each must be reported at its own +//! line, naming the method that panicked there. + +use pyo3::prelude::*; +use std::sync::Mutex; + +#[pyclass] +struct Queue { + items: Mutex>, +} + +#[pymethods] +impl Queue { + #[new] + fn new() -> Self { + Queue { + items: Mutex::new((0..64).collect()), + } + } + + fn head(&self) -> u32 { + let guard = self.items.try_lock().expect("queue is busy"); + std::thread::sleep(std::time::Duration::from_micros(50)); + guard[0] + } + + fn tail(&self) -> u32 { + let guard = self.items.try_lock().expect("queue is busy"); + std::thread::sleep(std::time::Duration::from_micros(50)); + guard[guard.len() - 1] + } +} + +#[pymodule] +fn stress_panic_two_sites(m: &Bound<'_, PyModule>) -> PyResult<()> { + m.add_class::() +} diff --git a/fixtures/racy/stress-panic-two-sites/tests/test_threads.py b/fixtures/racy/stress-panic-two-sites/tests/test_threads.py new file mode 100644 index 0000000..c441f00 --- /dev/null +++ b/fixtures/racy/stress-panic-two-sites/tests/test_threads.py @@ -0,0 +1,10 @@ +"""Each test builds its own object, so under `ftcheck ci` no instance is +shared and neither site panics.""" +import stress_panic_two_sites as m + + +def test_head_and_tail(): + queue = m.Queue() + for _ in range(100): + assert queue.head() == 0 + assert queue.tail() == 63 diff --git a/python/ftcheck/ci/__init__.py b/python/ftcheck/ci/__init__.py index 0aa23f6..9770bea 100644 --- a/python/ftcheck/ci/__init__.py +++ b/python/ftcheck/ci/__init__.py @@ -24,16 +24,28 @@ def describe_findings(findings: list[dict]) -> str: ("stress/panic", "panic under concurrency", "panics under concurrency"), ("stress/hang", "hang under concurrency", "hangs under concurrency"), ] + # A panic inside a dependency's code is reached through the extension's + # surface, but calling it "in your extension" sent users to the wrong code. + dependency = sum(1 for f in findings if f["rule"] == "stress/panic" and f.get("dependency")) + yours = [f for f in findings if not (f["rule"] == "stress/panic" and f.get("dependency"))] parts = [] for prefix, one, many in kinds: - n = sum(1 for f in findings if f["rule"].startswith(prefix)) + n = sum(1 for f in yours if f["rule"].startswith(prefix)) if n: parts.append(f"{n} {one if n == 1 else many}") - other = len(findings) - sum(int(p.split()[0]) for p in parts) + other = len(yours) - sum(int(p.split()[0]) for p in parts) if other: parts.append(f"{other} other finding{'s' if other != 1 else ''}") - joined = parts[0] if len(parts) == 1 else ", ".join(parts[:-1]) + " and " + parts[-1] - return f"{joined} in your extension" + described = [] + if parts: + joined = parts[0] if len(parts) == 1 else ", ".join(parts[:-1]) + " and " + parts[-1] + described.append(f"{joined} in your extension") + if dependency: + noun = "panic" if dependency == 1 else "panics" + described.append( + f"{dependency} {noun} under concurrency inside a dependency, reached from your extension" + ) + return " and ".join(described) # pytest exit statuses that mean the suite itself never ran properly. _PYTEST_BROKEN = {2: "interrupted", 3: "internal error", 4: "usage error", 5: "no tests collected"} diff --git a/python/ftcheck/stress/__init__.py b/python/ftcheck/stress/__init__.py index a136e49..db2d762 100644 --- a/python/ftcheck/stress/__init__.py +++ b/python/ftcheck/stress/__init__.py @@ -218,29 +218,134 @@ def _hang_finding(step: str, threads: int, seed: int) -> dict: } +# `thread '' () panicked at :::` then the +# message. Older Rust prints no thread id. _PANIC_AT = re.compile( + r"(?:thread '[^'\n]*'(?: \((?P\d+)\))? )?" r"panicked at (?P[^\n]+?):(?P\d+):(?P\d+):\n(?P[^\n]*)" ) +_BACKTRACE_FRAME = re.compile(r"^\s+\d+: (?P\S.*)$") +_BACKTRACE_AT = re.compile(r"^\s+at (?P.+?):(?P\d+)(?::(?P\d+))?$") +_REGISTRY = re.compile(r"/registry/src/[^/]+/(?P[A-Za-z0-9_.-]+?)-(?P\d+\.\d+\.\d+[^/]*)/") +_GIT_CHECKOUT = re.compile(r"/git/checkouts/(?P[^/]+?)-[0-9a-f]+/") +_STD = re.compile(r"^/rustc/|/lib/rustlib/src/rust/library/") +# How far past a thread's last matched panic line the next one is looked for. +# Extra lines on a thread (a panic the extension caught itself) are skipped. +_JOIN_WINDOW = 16 -def panic_locations(log_text: str) -> dict[str, dict]: - """Panic message -> where it panicked, from the Rust panic lines in the log. +def panic_locations(log_text: str) -> list[dict]: + """Every Rust panic line in the log, in order: where, on which thread, and + the frames if a backtrace follows (only when RUST_BACKTRACE is set). `PanicException` carries the message but not the location; Rust prints - both to stderr (`thread '...' panicked at src/lib.rs:40:17:` then the - message), which the driver log captures. + both to stderr, which the driver log captures, with the native thread id + the driver also records for each panicking call. """ - found: dict[str, dict] = {} - for m in _PANIC_AT.finditer(log_text): - found.setdefault( - m.group("message").strip(), - {"file": m.group("file"), "line": int(m.group("line")), "column": int(m.group("column"))}, + found = [] + matches = list(_PANIC_AT.finditer(log_text)) + for i, m in enumerate(matches): + tail = log_text[m.end() : matches[i + 1].start() if i + 1 < len(matches) else len(log_text)] + found.append( + { + "tid": int(m.group("tid")) if m.group("tid") else None, + "file": m.group("file"), + "line": int(m.group("line")), + "column": int(m.group("column")), + "message": m.group("message").strip(), + "frames": _backtrace(tail), + } ) return found +def _backtrace(tail: str) -> list[dict]: + lines = tail.splitlines() + try: + start = next(i for i, ln in enumerate(lines[:4]) if ln.strip() == "stack backtrace:") + except StopIteration: + return [] + frames = [] + for line in lines[start + 1 :]: + frame, at = _BACKTRACE_FRAME.match(line), _BACKTRACE_AT.match(line) + if frame: + frames.append({"symbol": frame.group("symbol").strip(), "location": None}) + elif at and frames: + file = at.group("file") + frames[-1]["location"] = { + "file": file.removeprefix("./"), + "line": int(at.group("line")), + "column": int(at.group("column") or 1), + } + else: + break + return frames + + +def _dependency(path: str) -> str | None: + """"pyo3 0.29.2" when `path` is a dependency's source, else None (yours).""" + if m := _REGISTRY.search(path): + return f"{m.group('crate')} {m.group('ver')}" + if m := _GIT_CHECKOUT.search(path): + return m.group("crate") + if _STD.search(path): + return "the Rust standard library" + return None + + +def _short(path: str) -> str: + """A dependency's file from its crate directory on: `pyo3-0.29.2/src/x.rs`.""" + m = _REGISTRY.search(path) or _GIT_CHECKOUT.search(path) + return path[m.start("crate") :] if m else path + + +def _same_message(logged: str, raised: str) -> bool: + # The log holds the first line of the message; the driver keeps 300 characters. + return logged[:300] == raised.split("\n", 1)[0].strip() + + +def _join(result: dict, events: list[dict], wanted: set[str]) -> tuple[dict, set[int]]: + """(qual -> {event index of the site: panics there}, consumed event indices). + + Each thread's panicking calls, in order, are matched to that thread's + panic lines, in order, so a site is known per call rather than guessed + from the message. + """ + by_tid: dict[int, list[int]] = {} + for i, e in enumerate(events): + if e["tid"] is not None: + by_tid.setdefault(e["tid"], []).append(i) + located: dict[str, dict[int, int]] = {} + consumed: set[int] = set() + for tid, runs in (result.get("panic_threads") or {}).items(): + mine = by_tid.get(int(tid), []) + k = 0 + for qual, message, count in runs: + for _ in range(count): + j = next( + ( + j + for j in range(k, min(k + _JOIN_WINDOW, len(mine))) + if _same_message(events[mine[j]]["message"], message) + ), + None, + ) + if j is None: + continue + k = j + 1 + consumed.add(mine[j]) + if qual in wanted: + site = located.setdefault(qual, {}) + site[mine[j]] = site.get(mine[j], 0) + 1 + return located, consumed + + +def _site_key(event: dict) -> str: + return f"{event['file']}:{event['line']}" + + def panic_findings( - result: dict | None, threads: int, seed: int, locations: dict[str, dict] | None = None + result: dict | None, threads: int, seed: int, locations: list[dict] | None = None ) -> list[dict]: """Rust panics a callable raised only when driven from many threads. @@ -250,56 +355,152 @@ def panic_findings( panic the baseline also raised is how the method behaves with those arguments, and is left alone. - Callables that panic at the same source location are one finding: one - `borrow()` shared by many methods produces the same panic in each of them. + One finding per source location, naming every callable that panicked + there with its own count: one `borrow()` shared by many methods produces + the same panic in each of them. The site of each panic comes from joining + the driver's per-thread record with the thread id in Rust's panic line. + Without thread ids (older Rust), a panic is located by its message, and + when several sites share the message the finding names them all. """ if not result: return [] - locations = locations or {} - groups: dict[str, dict] = {} + events = locations or [] + totals: dict[str, int] = {} for group in result.get("groups", []): serial = group.get("serial_exceptions", {}) for qual in group.get("driven", []): n = result.get("exceptions", {}).get(qual, {}).get("PanicException", 0) - if not n or "PanicException" in serial.get(qual, []): - continue - calls = result.get("calls", {}).get(qual, 0) - message = result.get("messages", {}).get(qual, {}).get("PanicException", "") - where = locations.get(message.strip()) - key = f"{where['file']}:{where['line']}" if where else f"message:{message}" - entry = groups.setdefault( - key, {"where": where, "message": message, "callables": [], "panics": 0, "calls": 0} - ) - entry["callables"].append(qual) - entry["panics"] += n - entry["calls"] += calls - out = [] - for entry in groups.values(): - callables = entry["callables"] - where = entry["where"] - named = ", ".join(f"`{q}`" for q in callables[:5]) + ( - f" and {len(callables) - 5} more" if len(callables) > 5 else "" - ) - at = f" at {where['file']}:{where['line']}" if where else "" - out.append( - { - "rule": "stress/panic", - "message": ( - f"Panicked{at} in {entry['panics']} of {entry['calls']} calls to {named} " - f"when driven from {threads} threads, and never in the single-threaded " - f"baseline: {entry['message'] or '(no message)'}. Replay with --replay {seed} " - f"--threads {threads}." - ), - "confidence": "certain", - "producer": "stress", - "symbol": callables[0], - "primary": where or {"file": "", "line": 1, "column": 1}, - "stacks": [], - "justification": None, - "occurrences": len(callables), - } + if n and "PanicException" not in serial.get(qual, []): + totals[qual] = n + located, consumed = _join(result, events, set(totals)) + + groups: dict[str, dict] = {} + + def add(key, sites, message, qual, n): + entry = groups.setdefault(key, {"sites": sites, "message": message, "callables": {}}) + entry["callables"][qual] = entry["callables"].get(qual, 0) + n + + for qual, n in totals.items(): + for index, count in located.get(qual, {}).items(): + event = events[index] + add(_site_key(event), [event], event["message"], qual, count) + rest = n - sum(located.get(qual, {}).values()) + if rest <= 0: + continue + # Not joined to a line: located by message, naming every candidate site. + raised = result.get("panics", {}).get(qual) or { + result.get("messages", {}).get(qual, {}).get("PanicException", ""): rest + } + pool = [e for i, e in enumerate(events) if i not in consumed] or events + sites = {} + for message in raised: + for e in pool: + if _same_message(e["message"], message): + sites.setdefault(_site_key(e), e) + first = next(iter(raised), "") + if not sites: + add(f"message:{first}", [], first, qual, rest) + else: + ordered = [sites[k] for k in sorted(sites)] + add(" | ".join(sorted(sites)), ordered, ordered[0]["message"] or first, qual, rest) + + calls = result.get("calls", {}) + mutators = result.get("mutators") or [] + return [ + _panic_finding(entry, calls, mutators, threads, seed) for entry in groups.values() + ] + + +def _inside(dependency: str, site: dict) -> str: + where = f"{_short(site['file'])}:{site['line']}" + if dependency.startswith("pyo3 ") and ( + "/conversions/" in site["file"] or "extract_argument" in site["file"] + ): + return f" inside PyO3's argument conversion ({dependency}, a dependency) at {where}" + if dependency.startswith("the Rust"): + return f" inside {dependency} at {where}" + return f" inside the dependency {dependency} at {where}" + + +def _your_frame(frames: list[dict]) -> tuple[dict | None, list[dict]]: + """The first backtrace frame in the crate's own Rust code, and the stack + from the first frame outside the standard library down to it.""" + mine = [ + i + for i, fr in enumerate(frames) + if fr["location"] + and fr["location"]["file"].endswith(".rs") + and _dependency(fr["location"]["file"]) is None + ] + if not mine: + return None, [] + first = mine[0] + start = next( + (i for i, fr in enumerate(frames) if fr["location"] and not _STD.search(fr["location"]["file"])), + first, + ) + return frames[first], [{"frames": frames[start : first + 1]}] + + +def _panic_finding(entry: dict, calls: dict, mutators: list, threads: int, seed: int) -> dict: + callables = entry["callables"] + names = list(callables) + total = sum(callables.values()) + n_calls = sum(calls.get(q, 0) for q in names) + if len(names) == 1: + named = f"{total} of {n_calls} calls to `{names[0]}`" + else: + each = [f"`{q}` ({callables[q]} of {calls.get(q, 0)})" for q in names[:5]] + more = f" and {len(names) - 5} more" if len(names) > 5 else "" + named = f"{total} of {n_calls} calls to {', '.join(each)}{more}" + sites = entry["sites"] + dependency = _dependency(sites[0]["file"]) if len(sites) == 1 else None + yours, stacks, reached, hint = None, [], "", "" + if dependency: + at = _inside(dependency, sites[0]) + yours, stacks = _your_frame(sites[0]["frames"]) + if yours: + where = yours["location"] + reached = f" It was reached from `{yours['symbol']}` at {where['file']}:{where['line']}." + else: + hint = " (with RUST_BACKTRACE=1 set, to see which of your frames led there)" + elif len(sites) == 1: + at = f" at {_site_key(sites[0])}" + elif sites: + at = f" at one of {', '.join(_site_key(e) for e in sites)} (the log does not say which)" + else: + at = "" + mutated = "" + if mutators: + mutated = ( + f" Mutators were running ({', '.join(mutators)}): if one can leave the shared " + "inputs invalid, this panic may be its doing rather than contention. Mutators " + "must keep the inputs valid at every instant." ) - return out + if yours: + primary = dict(yours["location"]) + elif sites: + primary = {k: sites[0][k] for k in ("file", "line", "column")} + else: + primary = {"file": "", "line": 1, "column": 1} + finding = { + "rule": "stress/panic", + "message": ( + f"Panicked{at} in {named} when driven from {threads} threads, and never in the " + f"single-threaded baseline: {entry['message'] or '(no message)'}.{reached}" + f"{mutated} Replay with --replay {seed} --threads {threads}{hint}." + ), + "confidence": "certain", + "producer": "stress", + "symbol": names[0], + "primary": primary, + "stacks": stacks, + "justification": None, + "occurrences": len(names), + } + if dependency: + finding["dependency"] = dependency + return finding def _crash_logged(tsan_dir: pathlib.Path) -> bool: diff --git a/python/ftcheck/stress/driver.py b/python/ftcheck/stress/driver.py index 3296cd7..336e1de 100644 --- a/python/ftcheck/stress/driver.py +++ b/python/ftcheck/stress/driver.py @@ -77,6 +77,9 @@ _MAX_COMBOS = 64 # derivation attempts per callable _MAX_ARGSETS = 3 # distinct argument tuples kept per callable +_MAX_PANIC_MESSAGES = 20 # distinct panic messages kept per callable +_MAX_PANIC_RUNS = 256 # changes of (callable, message) recorded per thread +_MAX_PANIC_RUNS_TOTAL = 20000 # and in the whole run, to bound the result file class Progress: @@ -610,9 +613,17 @@ def __init__(self): self.returned = {} self.exceptions = {} self.messages = {} # qual -> {exception name: first message} + self.panics = {} # qual -> {panic message: count} + # Native thread id -> [[qual, message, count], ...], in call order. Rust + # prints the same id in its panic line, so the orchestrator can tell + # which call panicked at which site: two sites with one message were + # otherwise indistinguishable (one was filed under the other). + self.panic_threads = {} + self._panic_full = set() + self._panic_runs = 0 self.total = 0 # every call, for progress: a hang is no call finishing - def record(self, qual, exc_name, message=None): + def record(self, qual, exc_name, message=None, tid=None): with self.lock: self.total += 1 self.calls[qual] = self.calls.get(qual, 0) + 1 @@ -623,9 +634,31 @@ def record(self, qual, exc_name, message=None): per[exc_name] = per.get(exc_name, 0) + 1 if message is not None: self.messages.setdefault(qual, {}).setdefault(exc_name, message[:300]) + if exc_name == "PanicException" and message is not None: + self._record_panic(qual, message[:300], tid) + + def _record_panic(self, qual, message, tid): + per = self.panics.setdefault(qual, {}) + if message in per or len(per) < _MAX_PANIC_MESSAGES: + per[message] = per.get(message, 0) + 1 + key = str(tid) + if tid is None or key in self._panic_full: + return + runs = self.panic_threads.setdefault(key, []) + if runs and runs[-1][0] == qual and runs[-1][1] == message: + runs[-1][2] += 1 + elif len(runs) < _MAX_PANIC_RUNS and self._panic_runs < _MAX_PANIC_RUNS_TOTAL: + self._panic_runs += 1 + runs.append([qual, message, 1]) + else: + # Past the cap the thread records nothing more, so what it did + # record stays in step with its panic lines. Its later panics are + # located by message, as when no thread id is known. + self._panic_full.add(key) def _worker(shared, work, rng, iterations, counters, barrier, errors, deadline): + tid = threading.get_native_id() try: barrier.wait() for _ in range(iterations): @@ -643,7 +676,7 @@ def _worker(shared, work, rng, iterations, counters, barrier, errors, deadline): except BaseException as exc: exc_name = type(exc).__name__ message = str(exc) - counters.record(qual, exc_name, message) + counters.record(qual, exc_name, message, tid) # Seeded yield points perturb the interleaving reproducibly. if rng.random() < 0.05: time.sleep(0) @@ -674,6 +707,7 @@ def _heartbeat(progress, step, counters, done, on_tick=None): def _mutator(name, mutate, counters, done): """Runs one declared mutator in a loop until the phase ends.""" + tid = threading.get_native_id() while not done.is_set(): exc_name = message = None try: @@ -682,7 +716,7 @@ def _mutator(name, mutate, counters, done): raise except BaseException as exc: exc_name, message = type(exc).__name__, str(exc) - counters.record(f"mutator:{name}", exc_name, message) + counters.record(f"mutator:{name}", exc_name, message, tid) time.sleep(0) @@ -891,6 +925,8 @@ def _write_result_locked(cfg, seed, started, surface, groups, counters, complete returned = dict(counters.returned) exceptions = {k: dict(v) for k, v in counters.exceptions.items()} messages = {k: dict(v) for k, v in counters.messages.items()} + panics = {k: dict(v) for k, v in counters.panics.items()} + panic_threads = {k: [list(r) for r in v] for k, v in counters.panic_threads.items()} for g in groups: g["raised_all"] = [q for q in g.get("driven", []) if calls.get(q) and not returned.get(q)] result = { @@ -906,6 +942,8 @@ def _write_result_locked(cfg, seed, started, surface, groups, counters, complete "returned": returned, "exceptions": exceptions, "messages": messages, + "panics": panics, + "panic_threads": panic_threads, } tmp = cfg["output_path"] + ".tmp" with open(tmp, "w") as fh: diff --git a/tests/test_ci_verdict.py b/tests/test_ci_verdict.py index e998fc8..bfbe8d3 100644 --- a/tests/test_ci_verdict.py +++ b/tests/test_ci_verdict.py @@ -93,3 +93,17 @@ def test_the_headline_names_each_kind_of_finding(): assert describe_findings([tsan, tsan, panic]) == ( "2 ThreadSanitizer reports and 1 panic under concurrency in your extension" ) + + +def test_a_panic_inside_a_dependency_is_not_called_yours(): + from ftcheck.ci import describe_findings + + tsan = {"rule": "tsan/data-race"} + dep = {"rule": "stress/panic", "dependency": "tinyqueue 1.2.3"} + assert describe_findings([dep, dep]) == ( + "2 panics under concurrency inside a dependency, reached from your extension" + ) + assert describe_findings([tsan, dep]) == ( + "1 ThreadSanitizer report in your extension and 1 panic under concurrency " + "inside a dependency, reached from your extension" + ) diff --git a/tests/test_stress_config.py b/tests/test_stress_config.py index 3c80c79..c25ce01 100644 --- a/tests/test_stress_config.py +++ b/tests/test_stress_config.py @@ -130,6 +130,186 @@ def test_panics_at_one_location_are_one_finding_located_there(): assert "`m.store.put`" in finding["message"] and "`m.store.get`" in finding["message"] +def _two_site_result(panic_threads, **extra): + """Two callables on one type, both panicking with the same message.""" + return { + "groups": [ + { + "driven": ["m.Shelf.left", "m.Shelf.right"], + "serial_exceptions": {"m.Shelf.left": [], "m.Shelf.right": []}, + } + ], + "calls": {"m.Shelf.left": 40, "m.Shelf.right": 60}, + "exceptions": { + "m.Shelf.left": {"PanicException": 2}, + "m.Shelf.right": {"PanicException": 1}, + }, + "messages": { + "m.Shelf.left": {"PanicException": "claim taken"}, + "m.Shelf.right": {"PanicException": "claim taken"}, + }, + "panic_threads": panic_threads, + **extra, + } + + +_TWO_SITES_LOG = ( + "thread '' (101) panicked at src/lib.rs:16:39:\n" + "claim taken\n" + "note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace\n" + "\n" + "thread '' (102) panicked at src/lib.rs:22:39:\n" + "claim taken\n" + "\n" + "thread '' (101) panicked at src/lib.rs:16:39:\n" + "claim taken\n" +) + + +def test_two_sites_sharing_one_message_are_two_findings_joined_by_thread(): + """Matched by message alone, both callables were filed at whichever site + panicked first, and the second site never appeared.""" + from ftcheck.stress import panic_findings, panic_locations + + result = _two_site_result( + {"101": [["m.Shelf.left", "claim taken", 2]], "102": [["m.Shelf.right", "claim taken", 1]]} + ) + findings = panic_findings(result, threads=8, seed=1, locations=panic_locations(_TWO_SITES_LOG)) + by_line = {f["primary"]["line"]: f for f in findings} + assert sorted(by_line) == [16, 22] + assert by_line[16]["symbol"] == "m.Shelf.left" + assert "2 of 40 calls to `m.Shelf.left`" in by_line[16]["message"] + assert "m.Shelf.right" not in by_line[16]["message"] + assert "1 of 60 calls to `m.Shelf.right`" in by_line[22]["message"] + + +def test_a_callable_that_panicked_at_two_sites_is_counted_at_each(): + """One thread that ran both callables (the mix phase): its panics are + joined in order, so each site gets exactly the calls that panicked there.""" + from ftcheck.stress import panic_findings, panic_locations + + log = ( + "thread '' (103) panicked at src/lib.rs:16:39:\nclaim taken\n" + "thread '' (103) panicked at src/lib.rs:22:39:\nclaim taken\n" + "thread '' (103) panicked at src/lib.rs:22:39:\nclaim taken\n" + ) + result = _two_site_result( + {"103": [["m.Shelf.left", "claim taken", 1], ["m.Shelf.left", "claim taken", 1]]}, + ) + result["exceptions"] = {"m.Shelf.left": {"PanicException": 2}} + result["panic_threads"]["103"].insert(1, ["m.Shelf.right", "claim taken", 1]) + result["exceptions"]["m.Shelf.right"] = {"PanicException": 1} + findings = panic_findings(result, threads=8, seed=1, locations=panic_locations(log)) + by_line = {f["primary"]["line"]: f for f in findings} + assert sorted(by_line) == [16, 22] + assert "1 of 40 calls to `m.Shelf.left`" in by_line[16]["message"] + assert "`m.Shelf.right`" in by_line[22]["message"] + assert "`m.Shelf.left`" in by_line[22]["message"] + + +def test_without_thread_ids_every_site_with_the_message_is_listed(): + """Older Rust prints no thread id. The site cannot be told apart then, so + the finding names every candidate instead of picking one silently.""" + from ftcheck.stress import panic_findings, panic_locations + + log = _TWO_SITES_LOG.replace(" (101)", "").replace(" (102)", "") + result = _two_site_result({}) + del result["panic_threads"] + (finding,) = panic_findings(result, threads=8, seed=1, locations=panic_locations(log)) + assert "src/lib.rs:16" in finding["message"] and "src/lib.rs:22" in finding["message"] + assert "3 of 100 calls" in finding["message"] + + +_DEP = "/opt/cargo/registry/src/index.crates.io-0000000000000000" + + +def test_a_panic_inside_a_dependency_says_so_and_names_the_callable(): + from ftcheck.ci import describe_findings + from ftcheck.stress import panic_findings, panic_locations + + log = ( + f"thread '' (101) panicked at {_DEP}/tinyqueue-1.2.3/src/lib.rs:88:13:\n" + "queue closed\n" + ) + result = _two_site_result({"101": [["m.Shelf.left", "queue closed", 2]]}) + result["exceptions"] = {"m.Shelf.left": {"PanicException": 2}} + result["messages"] = {"m.Shelf.left": {"PanicException": "queue closed"}} + (finding,) = panic_findings(result, threads=8, seed=1, locations=panic_locations(log)) + assert finding["dependency"] == "tinyqueue 1.2.3" + assert "inside the dependency tinyqueue 1.2.3" in finding["message"] + assert "`m.Shelf.left`" in finding["message"] + assert "RUST_BACKTRACE=1" in finding["message"], "the way to see your frame is named" + assert describe_findings([finding]) == ( + "1 panic under concurrency inside a dependency, reached from your extension" + ) + + +def test_a_panic_in_pyo3_argument_conversion_is_named_as_such(): + from ftcheck.stress import panic_findings, panic_locations + + log = ( + f"thread '' (101) panicked at {_DEP}/pyo3-0.29.2/src/conversions/std/num.rs:" + "31:9:\nconversion failed\n" + ) + result = _two_site_result({"101": [["m.Shelf.left", "conversion failed", 2]]}) + result["exceptions"] = {"m.Shelf.left": {"PanicException": 2}} + result["messages"] = {"m.Shelf.left": {"PanicException": "conversion failed"}} + (finding,) = panic_findings(result, threads=8, seed=1, locations=panic_locations(log)) + assert finding["dependency"] == "pyo3 0.29.2" + assert "inside PyO3's argument conversion (pyo3 0.29.2, a dependency)" in finding["message"] + + +def test_a_backtrace_in_the_log_locates_the_panic_at_your_frame(): + """With RUST_BACKTRACE=1 set (a replay), the first frame in your crate is + the location, and the dependency's line is kept in the message.""" + from ftcheck.stress import panic_findings, panic_locations + + log = ( + f"thread '' (101) panicked at {_DEP}/tinyqueue-1.2.3/src/lib.rs:88:13:\n" + "queue closed\n" + "stack backtrace:\n" + " 0: __rustc::rust_begin_unwind\n" + " at /rustc/0000/library/std/src/panicking.rs:689:5\n" + " 1: core::panicking::panic_fmt\n" + " at /rustc/0000/library/core/src/panicking.rs:80:14\n" + " 2: tinyqueue::Queue::pop\n" + f" at {_DEP}/tinyqueue-1.2.3/src/lib.rs:88:13\n" + " 3: examplelib::Shelf::left\n" + " at ./src/lib.rs:16:39\n" + " 4: examplelib::Shelf::__pymethod_left__\n" + " at ./src/lib.rs:9:1\n" + " 5: _PyFunction_Vectorcall\n" + "note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.\n" + ) + result = _two_site_result({"101": [["m.Shelf.left", "queue closed", 2]]}) + result["exceptions"] = {"m.Shelf.left": {"PanicException": 2}} + result["messages"] = {"m.Shelf.left": {"PanicException": "queue closed"}} + (finding,) = panic_findings(result, threads=8, seed=1, locations=panic_locations(log)) + assert finding["primary"] == {"file": "src/lib.rs", "line": 16, "column": 39} + assert "tinyqueue-1.2.3/src/lib.rs:88" in finding["message"] + assert "reached from `examplelib::Shelf::left`" in finding["message"] + symbols = [fr["symbol"] for fr in finding["stacks"][0]["frames"]] + assert symbols == ["tinyqueue::Queue::pop", "examplelib::Shelf::left"] + + +def test_a_panic_while_mutators_ran_says_so(): + """The baseline never sees a mutator's transient state: the message must + say mutators were running, and point at the rule they must follow.""" + from ftcheck.stress import panic_findings, panic_locations + + result = _two_site_result( + {"101": [["m.Shelf.left", "claim taken", 2]], "102": [["m.Shelf.right", "claim taken", 1]]}, + mutators=["churn"], + ) + findings = panic_findings(result, threads=8, seed=1, locations=panic_locations(_TWO_SITES_LOG)) + for f in findings: + assert "Mutators were running (churn)" in f["message"] + assert "valid at every instant" in f["message"] + quiet = _two_site_result({"101": [["m.Shelf.left", "claim taken", 2]]}, mutators=[]) + for f in panic_findings(quiet, threads=8, seed=1, locations=panic_locations(_TWO_SITES_LOG)): + assert "Mutators" not in f["message"] + + def test_declared_test_dependencies_are_found_in_the_usual_places(tmp_path): """A first user's two projects both failed test collection: the venv held only the wheel and the runner.""" diff --git a/tests/test_stress_driver.py b/tests/test_stress_driver.py index 47201e8..3cfb323 100644 --- a/tests/test_stress_driver.py +++ b/tests/test_stress_driver.py @@ -507,3 +507,51 @@ def test_mutator_threads_keep_their_name_within_fifteen_characters(tmp_path): def test_json_groups_list_what_raised_on_every_call(tmp_path): g = group(run_driver(tmp_path), "standin.Counter") assert "standin.Counter.reject" in g["raised_all"] + + +def test_each_panic_is_recorded_with_its_thread_and_every_message(tmp_path): + """The log's panic lines carry the native thread id; the driver records + which callable panicked on which thread, in order, so the two can be + joined. Every distinct message is kept, with a count, not only the first.""" + (tmp_path / "panicky.py").write_text(textwrap.dedent( + ''' + import threading + + class PanicException(BaseException): + """Named like pyo3_runtime.PanicException.""" + + class Shelf: + def __init__(self): + self.n = 0 + def left(self): + self.n += 1 + raise PanicException("left " + ("odd" if self.n % 2 else "even")) + def right(self): + return 1 + ''' + )) + result = run_driver(tmp_path, modules=["panicky"], skip={}, threads=2, iterations=10) + left = "panicky.Shelf.left" + assert set(result["panics"][left]) == {"left odd", "left even"} + assert sum(result["panics"][left].values()) == result["exceptions"][left]["PanicException"] + recorded = [run for runs in result["panic_threads"].values() for run in runs] + assert {q for q, _, _ in recorded} == {left}, "only panicking calls are recorded" + assert sum(n for _, _, n in recorded) == result["exceptions"][left]["PanicException"] + assert all(tid.isdigit() for tid in result["panic_threads"]) + + +def test_a_thread_past_the_record_cap_records_nothing_more(monkeypatch): + """Regression: merging a later panic into the last run after the cap made + the record skip calls the log still had, and the join then filed one + callable's panics at the other's site.""" + import importlib.util + + spec = importlib.util.spec_from_file_location("ftcheck_driver", DRIVER) + driver = importlib.util.module_from_spec(spec) + spec.loader.exec_module(driver) + monkeypatch.setattr(driver, "_MAX_PANIC_RUNS", 2) + counters = driver.Counters() + for qual in ("a", "b", "a", "b", "a"): + counters.record(qual, "PanicException", "boom", tid=7) + assert counters.panic_threads == {"7": [["a", "boom", 1], ["b", "boom", 1]]} + assert counters.panics == {"a": {"boom": 3}, "b": {"boom": 2}} diff --git a/tests/test_tsan_ground_truth.py b/tests/test_tsan_ground_truth.py index b70b2fe..f4915c7 100644 --- a/tests/test_tsan_ground_truth.py +++ b/tests/test_tsan_ground_truth.py @@ -179,3 +179,15 @@ def test_the_gap_fixture_is_invisible_to_ci_and_caught_by_stress(results): stress = results[("stress-unshared-state", "stress")] assert ci["exit_code"] == 0 and ci["findings"] == [] assert stress["exit_code"] == 1 and stress["findings"] + + +def test_two_panic_sites_with_one_message_are_reported_at_their_own_lines(results): + """Matched by message, both methods were filed under one line.""" + report = results[("stress-panic-two-sites", "stress")] + panics = [f for f in report["findings"] if f["rule"] == "stress/panic"] + by_line = {f["primary"]["line"]: f for f in panics} + assert sorted(by_line) == [28, 34], [f["primary"] for f in panics] + assert by_line[28]["symbol"].endswith("Queue.head") + assert "Queue.tail" not in by_line[28]["message"] + assert by_line[34]["symbol"].endswith("Queue.tail") + assert "Queue.head" not in by_line[34]["message"]