From 2e36b66ca7364f1e0cb06127d2e6bff2e693a4dc Mon Sep 17 00:00:00 2001 From: DonislawDev Date: Mon, 28 Sep 2026 19:17:44 +0200 Subject: [PATCH] fix(crashlog): build the crash context outside the lock The context provider is the GUI's own code, and it ran while the crash logger held its only lock. An invalid form field made the provider record its own ValueError into that lock on the same thread, and a worker's Tk read waited for a main loop that was waiting on the lock. Either way every later report from every thread queued behind it: the window froze and STOP did nothing. - crashlog: de-duplicate under the lock, build the context outside it, insert under the lock again with a second look (a concurrent record of the same new fault merges into one). A thread-local guard records a fault the provider raises itself without asking the provider again. - gui/crash: the report reads plain data only - a raw form copy taken on the main thread each tick, and the last counter snapshot. An invalid field is reported as settings_error instead of being recorded. - Four tests and four mutation entries, all caught. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 8 ++ beantester/crashlog.py | 117 ++++++++++++++++++--------- beantester/gui/crash.py | 65 ++++++++++++--- tests/test_crashlog.py | 136 ++++++++++++++++++++++++++++++++ tests/test_mutation_registry.py | 43 +++++++++- 5 files changed, 319 insertions(+), 50 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f378b7f..0664db1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,14 @@ The format follows [Keep a Changelog](https://keepachangelog.com/); versions fol ## [Unreleased] +### Fixed + +- **The program no longer freezes while it records an internal error.** Writing a crash + report used to read the Control page form. If a field held a value the program cannot + accept, such as a letter typed into Loss, or if a background task hit an error at the + wrong moment, the window stopped responding and STOP did nothing. Crash reports still + carry the settings. When a field is invalid, the report now says so instead. + ## [0.7.0] - 2026-09-25 ### Added diff --git a/beantester/crashlog.py b/beantester/crashlog.py index 09fcc87..1c88047 100644 --- a/beantester/crashlog.py +++ b/beantester/crashlog.py @@ -54,6 +54,13 @@ whatever broke last. * **Unbounded disk.** The log rotates and is capped, so a program left running for a fortnight with a repeating fault cannot fill the volume it is diagnosing. +* **A logger that wedges the program.** Every thread reports here, the capture + thread and the watchdog included, so the one lock this module owns is never held + while code from OUTSIDE it runs. The context provider is the App's code, and it + used to run under that lock: a provider that recorded a fault of its own + deadlocked its thread on it, and one that waited for the Tk main loop deadlocked + against a main thread waiting for it. Every later report from every thread then + queued behind them - the GUI froze and the watchdog stopped watching. """ import faulthandler import hashlib @@ -90,6 +97,9 @@ # makes room by dropping the fault nobody has seen for longest. See _record. _seen: OrderedDict[str, dict] = OrderedDict() # fingerprint -> record (+ a count) _context_provider = None # set by the App/CLI: returns a dict of state +# Per thread: is this thread inside the context provider right now? A fault the +# provider itself records must not ask the provider again (see _collect_context). +_local = threading.local() _installed = False _enabled = True @@ -113,9 +123,15 @@ def _ensure_dir(): def set_context_provider(fn): """Register a callable returning a dict of app state to attach to every crash. - The App passes the seed, the settings, the counters and the open page; the CLI - passes the parsed configuration. Whatever it returns is best-effort: a context - provider that itself raises must not turn a crash into two. + The App passes the seed, the settings, the counters and the open page. Whatever + it returns is best-effort: a context provider that itself raises must not turn a + crash into two. + + It runs on WHICHEVER thread recorded the fault - the capture thread, the + watchdog, a worker - so it must read plain data only: no GUI toolkit call (Tk + waits for its own main loop, which may be the thread waiting on us), and no lock + a recording thread may already hold. A fault it records itself is recorded + without asking it again. """ global _context_provider _context_provider = fn @@ -132,13 +148,23 @@ def _collect_context(): "pydivert": _module_version("pydivert"), "threads": [t.name for t in threading.enumerate()], } - if _context_provider is not None: - try: - extra = _context_provider() or {} - if isinstance(extra, dict): - base.update(extra) - except Exception as exc: # a broken provider must not mask the crash - base["context_provider_failed"] = f"{type(exc).__name__}: {exc}" + if _context_provider is None: + return base + if getattr(_local, "in_provider", False): + # The provider recorded a fault of its own. Asking it again would run the + # same failing code again, record again, ask again - recursion, and before + # the context moved out of the lock, a thread deadlocked on itself. + base["context_provider_skipped"] = "re-entered" + return base + _local.in_provider = True + try: + extra = _context_provider() or {} + if isinstance(extra, dict): + base.update(extra) + except Exception as exc: # a broken provider must not mask the crash + base["context_provider_failed"] = f"{type(exc).__name__}: {exc}" + finally: + _local.in_provider = False return base @@ -215,39 +241,48 @@ def _record(exc, source, subsystem, severity, note): with _lock: existing = _seen.get(fingerprint) if existing is not None: - existing["count"] += 1 - existing["last_seen"] = _now_iso() - # Freshest last. The eviction below drops the OTHER end of the table, - # and a fault firing right now is the last thing it may drop. - _seen.move_to_end(fingerprint) # A repeating fault (a crash inside the tick loop fires 1.4x a second) # costs one integer from here on - not another disk write. - return existing - - entry = { - "fingerprint": fingerprint, - "first_seen": _now_iso(), - "last_seen": _now_iso(), - "count": 1, - "severity": severity, - "source": source, - "subsystem": subsystem or _subsystem_of(frames), - "type": getattr(exc_type, "__name__", str(exc_type)), - "message": str(exc)[:500], - "note": note, - "traceback": "".join( - traceback.format_exception(exc_type, exc, tb))[:8000], - "context": _collect_context(), - } + return _count_again(existing, fingerprint) + + # Built OUTSIDE the lock, and that is a deadlock fix, not tidiness (reproduced + # 2026-09-28, both ways). The context comes from the App's provider: the GUI's + # read a Tk variable and, on an invalid form field, recorded that ValueError - + # from inside the lock, into the lock, on the same thread. And a Tk call from a + # worker waits for the main loop, which could itself be waiting right here. + # Either way the lock stayed held, and every later report from every thread - + # the watchdog's too - queued behind it for good. + entry = { + "fingerprint": fingerprint, + "first_seen": _now_iso(), + "last_seen": _now_iso(), + "count": 1, + "severity": severity, + "source": source, + "subsystem": subsystem or _subsystem_of(frames), + "type": getattr(exc_type, "__name__", str(exc_type)), + "message": str(exc)[:500], + "note": note, + "traceback": "".join( + traceback.format_exception(exc_type, exc, tb))[:8000], + "context": _collect_context(), + } + with _lock: + existing = _seen.get(fingerprint) + if existing is not None: + # Another thread recorded this same NEW fault while this one was + # building its context: one record, one more occurrence, no second + # disk write. The context built here is simply dropped. + return _count_again(existing, fingerprint) # The table used to REFUSE a new fingerprint once it was full, and that # turned the ceiling into a cliff: a fault arriving late never got a slot, # so every one of its occurrences looked new, built a full context and # wrote to disk again. MEASURED on this machine (2026-09-03), the same # repeating fault: 137 us and zero writes with a slot, 1926 us and a write - # PER OCCURRENCE without one - 14x, with the expensive half built inside - # the lock every other caller of this module waits on. In other words the - # de-duplication this module is built around stopped working exactly when - # the program was failing most. + # PER OCCURRENCE without one - 14x, and back then the expensive half was + # built inside the lock every other caller of this module waits on. In + # other words the de-duplication this module is built around stopped + # working exactly when the program was failing most. # # So the table makes room instead of refusing: in a shipped build it is a # dedup CACHE and nothing else, since neither read-back helper at the @@ -266,6 +301,16 @@ def _record(exc, source, subsystem, severity, note): return entry +def _count_again(existing, fingerprint): + """One more occurrence of a fault already in the table. Caller holds ``_lock``.""" + existing["count"] += 1 + existing["last_seen"] = _now_iso() + # Freshest last. The eviction in _record drops the OTHER end of the table, + # and a fault firing right now is the last thing it may drop. + _seen.move_to_end(fingerprint) + return existing + + def _now_iso(): return datetime.now(timezone.utc).isoformat(timespec="seconds") diff --git a/beantester/gui/crash.py b/beantester/gui/crash.py index 035b051..34567b1 100644 --- a/beantester/gui/crash.py +++ b/beantester/gui/crash.py @@ -6,7 +6,9 @@ * **the report context** - rich, expensive, and PULLED at the moment a Python-level failure is recorded (``crashlog.set_context_provider``). It carries the seed and the settings, because a crash report should be one step away from a REPRO rather - than something to read. + than something to read. It is pulled on WHICHEVER thread failed, so it reads only + plain data: the form comes from a copy the main thread takes every tick, never + from a Tk variable (see ``context``). * **the breadcrumb** - three facts, cheap, and PUSHED to disk before anything goes wrong. A hard (C-level) crash writes a stack and nothing else: ``faulthandler`` cannot ask a provider, so whatever the tool was doing has to already be on disk. @@ -24,8 +26,17 @@ alternative - widening five private attributes into a public surface so one neighbour can read them - would freeze more, not less. """ +import weakref + from .. import crashlog from ..repro import settings_to_cli_string +from ..settings import settings_from_raw + +# The raw form as the MAIN thread last read it, per App - the only way a report +# written on another thread may learn what the form held. Kept here and not on +# App, because App sits exactly on both class ratchets in tests/test_code_shape.py +# (attributes and methods). Weak, so a test that builds many Apps keeps none alive. +_FORMS: weakref.WeakKeyDictionary[object, dict] = weakref.WeakKeyDictionary() def install(app): @@ -39,22 +50,45 @@ def context(app): The point is that a crash report should be one step away from a REPRO, not just something to read: the seed and the settings are what make the failure happen again. + + This runs on whichever thread recorded the fault, so it touches PLAIN data only + - and each of the three things it no longer does deadlocked the program + (reproduced 2026-09-28): it read the form through Tk variables (a worker's Tcl + call waits for the main loop, which may be waiting on the crash log); it took + the engine's statistics lock (``last_snapshot`` is the same numbers, one tick + old, lock-free); and on an invalid field it recorded that error into the crash + log whose lock its caller held. An invalid field is now a fact in the report. + + A real failure in here is still recorded, and that is safe now: the logger + holds no lock while this runs, and a fault recorded from inside it is written + without asking this function again (``crashlog._collect_context``). What is + filled in before the failure stays in the report. """ state = {"page": app._page_id, "running": app.running} - try: - state["seed"] = app.engine.effective_seed() - state["counters"] = dict(app.engine.stats_snapshot()) - settings = app._settings_from_widgets() - state["settings"] = settings - state["repro_command"] = settings_to_cli_string( - settings, seed=app.engine.effective_seed()) - state["log_tail"] = list(app._log_lines[-crashlog.MAX_LOG_TAIL:]) - state["open_windows"] = app.windows.open_ids() - except Exception as _exc: - crashlog.note(_exc, "gui.app") + with crashlog.quiet("gui.crash"): + _fill(app, state) return state +def _fill(app, state): + state["seed"] = app.engine.effective_seed() + if app.last_snapshot is not None: + state["counters"] = dict(app.last_snapshot) + state["log_tail"] = list(app._log_lines[-crashlog.MAX_LOG_TAIL:]) + state["open_windows"] = app.windows.open_ids() + raw = _FORMS.get(app) + if raw is None: + return # a fault before the first tick read the form + try: + settings = settings_from_raw(raw, app._lang) + except ValueError as exc: # what a user mid-typing leaves in a field + state["settings_error"] = str(exc) + state["form"] = raw + return + state["settings"] = settings + state["repro_command"] = settings_to_cli_string(settings, seed=state["seed"]) + + def leave_breadcrumb(app): """Put the three facts a NATIVE crash report cannot carry on disk. @@ -68,6 +102,13 @@ def leave_breadcrumb(app): Deliberately SMALL. The seed and the settings belong to ``context`` above, not to a file rewritten whenever the user changes tab. + + The same tick also copies the raw form for ``context`` - in memory, no disk - + for the same reason: it is the main thread, and it cannot be forgotten. The + read is the cheap one (no parsing, no regex); the parsing happens only when a + report is actually written. """ crashlog.breadcrumb(page=app._page_id, running=app.running, windows=app.windows.open_ids()) + with crashlog.quiet("gui.crash"): # a broken read must not cost the tick its rest + _FORMS[app] = app._raw_settings() diff --git a/tests/test_crashlog.py b/tests/test_crashlog.py index a34e12d..02a0df3 100644 --- a/tests/test_crashlog.py +++ b/tests/test_crashlog.py @@ -128,6 +128,142 @@ def broken(): assert entry is not None, "a broken context provider must not lose the crash" +# -- 3b) the lock is never held while the App's code runs -------------------- # +# The context provider is the App's code, and it used to run INSIDE the logger's +# only lock. Two deadlocks followed from that, both reproduced on 2026-09-28: the +# GUI's provider recorded an invalid form field into the lock its caller held, and +# its Tk read from a worker waited for a main loop that was waiting on the lock. +# Every test here swaps in a private lock first, so a regression wedges that lock +# and fails the test instead of hanging every test after it. +def _fault(kind, message): + """A real exception of ``kind``; the type alone gives it its own fingerprint.""" + try: + raise kind(message) + except kind as exc: + return exc + + +def _record_on_a_thread(exc, box, key): + thread = threading.Thread( + target=lambda: box.update({key: crashlog.record(exc, source="test")}), + daemon=True) + thread.start() + return thread + + +def test_a_provider_that_records_a_fault_of_its_own_does_not_wedge_the_logger( + isolated, monkeypatch): + """What the GUI's provider did on an invalid field: ValueError -> note().""" + monkeypatch.setattr(crashlog, "_lock", threading.Lock()) + + def provider(): + crashlog.note(_fault(ValueError, "the provider's own fault"), "provider") + return {"seed": 7} + + crashlog.set_context_provider(provider) + box = {} + worker = _record_on_a_thread(_fault(KeyError, "the real crash"), box, "entry") + worker.join(5.0) + assert not worker.is_alive(), "recording a fault deadlocked on the logger's own lock" + assert box["entry"]["context"]["seed"] == 7, "the real crash lost its context" + # The provider's own fault is recorded too - once, and WITHOUT asking the + # provider again: that would run the same failing code, record, ask again. + inner = [e for e in _entries(isolated) if e["message"] == "the provider's own fault"] + assert len(inner) == 1, inner + assert inner[0]["context"].get("context_provider_skipped") == "re-entered", inner[0] + assert inner[0]["count"] == 1, "the provider was asked again from inside itself" + + +def test_two_threads_can_build_their_context_at_the_same_time(isolated, monkeypatch): + """The context is built OUTSIDE the lock, so a slow provider stalls only its caller. + + Both threads must be inside the provider at once to pass the barrier. With the + context built under the lock the second thread waits for the first, the + barrier times out, and the provider reports it. + """ + monkeypatch.setattr(crashlog, "_lock", threading.Lock()) + barrier = threading.Barrier(2, timeout=5.0) + met = [] + + def provider(): + try: + barrier.wait() + met.append(True) + except threading.BrokenBarrierError: + met.append(False) + return {} + + crashlog.set_context_provider(provider) + box = {} + threads = [_record_on_a_thread(_fault(KeyError, "one"), box, "one"), + _record_on_a_thread(_fault(IndexError, "two"), box, "two")] + for thread in threads: + thread.join(10.0) + assert not any(t.is_alive() for t in threads), "a thread never got out of the logger" + assert met == [True, True], "one thread built its context while holding the lock" + + +def test_the_same_new_fault_from_two_threads_at_once_is_one_record(isolated, monkeypatch): + """Both threads saw the fault as NEW, both built a context - the second merges.""" + monkeypatch.setattr(crashlog, "_lock", threading.Lock()) + barrier = threading.Barrier(2, timeout=5.0) + crashlog.set_context_provider(lambda: barrier.wait() and {}) + box = {} + threads = [_record_on_a_thread(_fault(KeyError, "same"), box, key) + for key in ("a", "b")] + for thread in threads: + thread.join(10.0) + assert not any(t.is_alive() for t in threads) + written = _entries(isolated) + assert len(written) == 1, f"{len(written)} disk records for one fault" + assert box["a"] is box["b"] and box["a"]["count"] == 2, box + + +def test_a_gui_crash_report_never_reads_tk_off_the_main_thread(isolated): + """The wiring: a worker's report on the real App, with an invalid field. + + The main thread copies the form on its tick; a report written on a worker reads + that copy. Before, the worker read the Tk variables itself - and with an invalid + field it then deadlocked on the logger (the report's P0-1, reproduced). + """ + from gui_harness import run_gui + + out = run_gui(""" + import threading + from beantester import crashlog + + app.vars["loss"].set("abc") # what a user mid-typing leaves in the box + on_main = [] + real = app._raw_settings + + def spy(*args, **kwargs): + on_main.append(threading.current_thread() is threading.main_thread()) + return real(*args, **kwargs) + + app._raw_settings = spy + app._tick() # the main thread copies the form + box = {} + + def work(): + try: + raise RuntimeError("probe fault from a worker") + except RuntimeError as exc: + box["entry"] = crashlog.record(exc, source="probe") + + worker = threading.Thread(target=work, daemon=True) + worker.start() + worker.join(10.0) + assert not worker.is_alive(), "a worker's crash report deadlocked" + context = box["entry"]["context"] + assert on_main and all(on_main), f"the form was read off the main thread: {on_main}" + assert "Loss" in context["settings_error"], context + assert context["form"]["loss"] == "abc", context + assert "repro_command" not in context, context + print("CONTEXT_OK") + """, lang="en", allow_faults=("probe fault from a worker",)) + assert "CONTEXT_OK" in out, out + + # -- 4) it catches what nothing else does ------------------------------------ # def test_a_worker_thread_exception_is_recorded(isolated): """Previously recorded NOWHERE: threads print to a stderr a windowed build diff --git a/tests/test_mutation_registry.py b/tests/test_mutation_registry.py index ac50180..89017e0 100644 --- a/tests/test_mutation_registry.py +++ b/tests/test_mutation_registry.py @@ -1914,10 +1914,49 @@ # out to make room for faults seen once each. "label": "crashlog: the crash table evicts by arrival instead of by recency", "file": "beantester/crashlog.py", - "old": " _seen.move_to_end(fingerprint)", - "new": " pass", + "old": " _seen.move_to_end(fingerprint)", + "new": " pass", "test": "test_the_table_makes_room_by_dropping_the_coldest_fault_not_the_busiest", }, + { + # The provider recorded its own fault and was asked again from inside + # itself: the same failing code, another record, another ask. + "label": "crashlog: a provider's own fault asks the provider again", + "file": "beantester/crashlog.py", + "old": ' if getattr(_local, "in_provider", False):', + "new": " if False:", + "test": "test_a_provider_that_records_a_fault_of_its_own_does_not_wedge_the_logger", + }, + { + # The shipped deadlock: the App's provider runs while the logger's only + # lock is held, so a slow or re-entering provider wedges every thread. + "label": "crashlog: the context provider runs under the lock again", + "file": "beantester/crashlog.py", + "old": " extra = _context_provider() or {}", + "new": " with _lock:\n" + " extra = _context_provider() or {}", + "test": "test_two_threads_can_build_their_context_at_the_same_time", + }, + { + # Two threads built a context for the same NEW fault; without the second + # look the loser overwrites the record and writes it to disk again. + "label": "crashlog: a fault recorded twice at once is written twice", + "file": "beantester/crashlog.py", + "old": "disk write. The context built here is simply dropped.\n" + " return _count_again(existing, fingerprint)", + "new": "disk write. The context built here is simply dropped.\n" + " pass", + "test": "test_the_same_new_fault_from_two_threads_at_once_is_one_record", + }, + { + # Back to reading the Tk variables on whichever thread failed: a Tcl call + # from a worker waits for a main loop that may be waiting on the logger. + "label": "crash: the GUI's crash report reads the form through Tk again", + "file": "beantester/gui/crash.py", + "old": " raw = _FORMS.get(app)", + "new": " raw = app._raw_settings()", + "test": "test_a_gui_crash_report_never_reads_tk_off_the_main_thread", + }, { # One byte of the recorded driver hash. The version resource still reads # 2.2 - which is exactly what a swapped kernel driver looks like.