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.