Coverage for scanpath_studio/debug_log.py: 98%
153 statements
« prev ^ index » next coverage.py v7.16.2, created at 2026-10-07 21:10 +0000
1"""In-app debug log + state inspector.
3Streamlit reruns the script top-to-bottom on every interaction, and plain
4``logging`` / ``print`` output only reaches the *server* terminal — never the
5browser. This module bridges that gap: a :class:`logging.Handler` captures log
6records into a capped buffer in ``st.session_state`` so they can be rendered
7inside the app, behind a debug toggle.
9Activation is a single toggle (**UX-37**), in the dialog the nav's ❓ Help →
10🐛 **Debug** entry opens (**UX-179** — it was a block of the retired 💾 Session
11dialog). Switching it on adds the log panel under it: a level filter, an
12app/session-state snapshot, and a JSON export. It used to be two-stage and the
13first stage was a URL param — ``?debug=1`` revealed the toggle — which meant the
14whole feature was reachable only by someone who already knew it existed. The
15param is still honoured as a *seed* so old links keep working, but it is no
16longer the way in.
17"""
19from __future__ import annotations
21import json
22import logging
23from collections import deque
24from contextlib import contextmanager
25from datetime import datetime
26from time import perf_counter
27from typing import Any
29import streamlit as st
30from streamlit.runtime.scriptrunner import StopException
32from .constants import ICONS
33from .crash_report import guarded
35# Keep the buffer small: it lives in session_state and is re-rendered every run.
36_MAX_RECORDS = 500
37_BUFFER_KEY = "_debug_log_records"
39#: Session key of the "🐛 Debug mode" toggle under ❓ Help. This *is* the gate —
40#: :func:`debug_enabled` reads nothing else.
41DEBUG_STATE_KEY = "_debug_mode_on"
43#: The legacy URL param. Kept as a one-shot seed for links already in the world;
44#: see :func:`seed_debug_mode`.
45DEBUG_URL_PARAM = "debug"
47#: The package's own logger. Everything the app logs is a child of this, which is
48#: what :class:`_AppRecordsOnly` keys on.
49_APP_LOGGER = "scanpath_studio"
51_LEVELS = ["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]
52_LEVEL_COLOR = {
53 "DEBUG": "#888",
54 "INFO": "#3b82f6",
55 "WARNING": "#d97706",
56 "ERROR": "#dc2626",
57 "CRITICAL": "#dc2626",
58}
61@contextmanager
62def timed(what: str, level: int = logging.INFO, **fields: Any):
63 """Log ``what`` with how long it took, and with any facts worth having.
65 The debug panel's whole value is answering "what did that click actually
66 do?", and a log line per *computation* is what makes it answerable — the
67 stages are otherwise invisible: Streamlit reruns the script top to bottom and
68 a cache hit looks exactly like a cache miss.
70 Cheap enough to leave on: one ``perf_counter`` pair and one formatted string
71 per stage, at stage granularity, not per row. An exception still logs (at
72 WARNING, marked ``failed``) and then propagates — a stage that blew up is
73 exactly the line you want in the report.
75 with timed("normalize", rows=len(df)):
76 ...
77 """
78 extra = " ".join(f"{k}={v}" for k, v in fields.items())
79 start = perf_counter()
80 try:
81 yield
82 except Exception as exc: # re-raised below
83 logging.getLogger("scanpath_studio").warning(
84 "%s failed after %.0f ms%s: %s",
85 what,
86 (perf_counter() - start) * 1000,
87 f" · {extra}" if extra else "",
88 exc,
89 )
90 raise
91 logging.getLogger("scanpath_studio").log(
92 level,
93 "%s · %.0f ms%s",
94 what,
95 (perf_counter() - start) * 1000,
96 f" · {extra}" if extra else "",
97 )
100def log_event(what: str, **fields: Any) -> None:
101 """Log a user-driven state change (a pick, a toggle, a step).
103 Interactions are logged when they *change something* — the data source, the
104 trial, the view — not on every widget touch: Streamlit reruns the script for
105 each one, so a line per widget would be a line per rerun per widget and the
106 computation lines would drown in it.
107 """
108 extra = " ".join(f"{k}={v}" for k, v in fields.items())
109 logging.getLogger("scanpath_studio").info(
110 "%s%s", what, f" · {extra}" if extra else ""
111 )
114def log_state_change(state_key: str, value: Any, what: str, **fields: Any) -> None:
115 """:func:`log_event`, but only when ``value`` differs from the last run's.
117 A rerun re-executes everything, so logging a selection unconditionally would
118 print the same line on every interaction anywhere in the app. This keeps one
119 line per actual change, which is what makes the log readable.
120 """
121 marker = f"_logged_{state_key}"
122 if st.session_state.get(marker) == value:
123 return
124 st.session_state[marker] = value
125 log_event(what, **fields)
128def _buffer() -> deque[dict[str, Any]]:
129 """The session-scoped ring buffer of captured log records."""
130 buf = st.session_state.get(_BUFFER_KEY)
131 if buf is None:
132 buf = deque(maxlen=_MAX_RECORDS)
133 st.session_state[_BUFFER_KEY] = buf
134 return buf
137class _AppRecordsOnly(logging.Filter):
138 """Keep the app's own records, plus anything that went wrong anywhere.
140 The handler sits on the *root* logger, so without a filter the panel fills
141 with third-party chatter — tornado logs a line per websocket frame, watchdog
142 per filesystem event, urllib3 per connection. That is what made the panel
143 unreadable (UX-37 follow-up: "each log entry shows up identical like a
144 hundred times"), and none of it answers "what did the app just do?".
146 ``WARNING`` and above is kept whatever its source: a library that failed is
147 exactly what a bug report needs, and those arrive one at a time.
148 """
150 def filter(self, record: logging.LogRecord) -> bool:
151 return (
152 record.name == _APP_LOGGER
153 or record.name.startswith(f"{_APP_LOGGER}.")
154 or record.levelno >= logging.WARNING
155 )
158class _SessionStateHandler(logging.Handler):
159 """Append each emitted record to the session-state ring buffer.
161 Identical lines are **collapsed** rather than repeated: a match anywhere in
162 the buffer bumps that entry's ``count``, refreshes its timestamp and moves it
163 to the newest position. Streamlit reruns the whole script per interaction, so
164 anything logged outside a cache or a change-guard recurs verbatim — and 100
165 copies of one line push the other 99 events out of a 500-entry buffer. The
166 count keeps the "this happened a lot" signal without the noise.
168 The handler is attached to the root logger, so it can capture every module's
169 ``logging`` output; :class:`_AppRecordsOnly` narrows that to the app's own
170 records plus WARNING-and-above from anywhere. It never raises into the
171 logging machinery: a failure to record a log line must not break the thing
172 being logged.
174 One instance serves the whole process (see ``install_log_capture``): the
175 buffer it appends to is resolved through ``st.session_state`` at emit time,
176 which Streamlit binds to the *calling* thread's script-run context, so a
177 record logged during a session's run lands in that session's buffer and
178 nowhere else. A record emitted from a thread with no context raises inside
179 ``_buffer`` and is swallowed here rather than being misfiled.
180 """
182 def emit(self, record: logging.LogRecord) -> None:
183 try:
184 buf = _buffer()
185 stamp = datetime.fromtimestamp(record.created).strftime("%H:%M:%S.%f")[:-3]
186 seen = (record.levelname, record.name, record.getMessage())
187 for index, entry in enumerate(buf):
188 if (entry["level"], entry["logger"], entry["message"]) == seen:
189 entry["count"] += 1
190 entry["time"] = stamp
191 # Move to the newest position. Safe mid-iteration only
192 # because this returns immediately.
193 del buf[index]
194 buf.append(entry)
195 return
196 buf.append(
197 {
198 "time": stamp,
199 "level": record.levelname,
200 "logger": record.name,
201 "message": record.getMessage(),
202 "count": 1,
203 }
204 )
205 except (Exception, StopException):
206 # UX-166: an abandoned run's session state raises StopException on
207 # any access. Escaping here, it threw away the finished result of
208 # every cached build that logs through `timed()` — the log line comes
209 # after the value is computed. A stop stays requested, so the run
210 # still stops at its next yield point; logging must never crash its
211 # caller. RerunException is deliberately NOT caught here: unlike a
212 # stop, `ScriptRequests.on_scriptrunner_yield` *consumes* a rerun
213 # request as it hands it over, so swallowing it here — if `emit` is
214 # the first checkpoint after the request — would discard the rerun
215 # itself (reachable with `runner.fastReruns = false`).
216 pass
219class _TerminalHandler(logging.StreamHandler):
220 """The app logger's own stderr handler (BUG-100), marked so it is added once."""
223def install_log_capture(level: int = logging.INFO) -> None:
224 """Attach the session-state handler to the root logger (once per *process*).
226 Idempotent, and idempotent at the right scope: the guard reads the root
227 logger's own handler list, not ``st.session_state``. The root logger is
228 process-wide while session state is not, so a session-scoped flag let every
229 new session add another handler — N sessions meant N handlers, each record
230 appended N times to whichever session's buffer was live, and handlers piling
231 up for the process's lifetime (S10). One handler is enough: it resolves the
232 buffer per script-run context, so each session still sees only its own
233 records. Call this early in ``main()``.
235 The level is raised on the **app's** logger, not the root one. Raising root
236 to INFO switches on every library that hasn't set its own level — tornado,
237 watchdog, urllib3, PIL, streamlit's internals — and they, not the app, were
238 what flooded the panel. A record's level is tested where it is logged, and
239 propagation to an ancestor's *handlers* ignores the ancestor's level, so
240 scoping it here still delivers every ``scanpath_studio`` INFO line to this
241 handler; WARNING and up also go to the terminal (BUG-100).
242 """
243 app_logger = logging.getLogger(_APP_LOGGER)
244 if app_logger.level == logging.NOTSET or app_logger.level > level:
245 app_logger.setLevel(level)
246 # BUG-100: a handler anywhere on the chain switches off logging's
247 # ``lastResort`` — the stderr fallback that used to print the app's warnings
248 # — so the handler below made every app warning and traceback (a dataset
249 # whose normalization failed, say) vanish from the server terminal. Put the
250 # terminal back, for WARNING and up: INFO stays in the in-app panel.
251 if not any(isinstance(h, _TerminalHandler) for h in app_logger.handlers):
252 terminal = _TerminalHandler()
253 terminal.setLevel(logging.WARNING)
254 terminal.setFormatter(
255 logging.Formatter("%(asctime)s %(levelname)s %(name)s: %(message)s")
256 )
257 app_logger.addHandler(terminal)
258 root = logging.getLogger()
259 if any(isinstance(h, _SessionStateHandler) for h in root.handlers):
260 return
261 handler = _SessionStateHandler()
262 handler.setLevel(logging.DEBUG)
263 handler.addFilter(_AppRecordsOnly())
264 root.addHandler(handler)
267def seed_debug_mode() -> None:
268 """Honour a legacy ``?debug=1`` link by pre-arming the toggle, once.
270 ``setdefault`` rather than a write: the toggle is the gate now, so a user who
271 turns debug mode *off* on a ``?debug=1`` URL must stay off for the rest of
272 the session instead of having the param switch it back on every rerun. Call
273 from ``main`` before :func:`debug_enabled` is read.
274 """
275 if (st.query_params.get(DEBUG_URL_PARAM) or "").lower() in {"1", "true", "yes"}:
276 st.session_state.setdefault(DEBUG_STATE_KEY, True)
279def debug_enabled() -> bool:
280 """True when the ❓ Help → "🐛 Debug mode" toggle is on."""
281 return bool(st.session_state.get(DEBUG_STATE_KEY))
284#: UX-100 — the toggle's own widget key, mirrored into :data:`DEBUG_STATE_KEY`.
285#: The two used to be the same key, which was fine while the toggle rendered on
286#: every run; it now lives in the Debug **dialog**, whose body is a fragment
287#: that runs only while the modal is open — and Streamlit drops a widget's key at
288#: the end of any run in which it did not render, so debug mode switched itself
289#: off the moment the modal was dismissed. Splitting them makes the durable flag
290#: the source of truth and the widget a view of it, exactly as the persistence
291#: pause toggle already worked.
292_DEBUG_TOGGLE_KEY = "_debug_mode_toggle"
295def _mirror_debug_toggle() -> None:
296 """``on_change``: write the widget's value into the durable gate."""
297 st.session_state[DEBUG_STATE_KEY] = bool(st.session_state.get(_DEBUG_TOGGLE_KEY))
300def render_debug_toggle(host=None) -> None:
301 """Render the "🐛 Debug mode" toggle into the ❓ Help → About → Debug dialog.
303 The single gate (**UX-37**). Flipping it on shows the log panel under it
304 in the same dialog run (:func:`_debug_dialog`).
306 Seeded rather than passed a ``value=``: the widget key is a mirror of
307 :data:`DEBUG_STATE_KEY` (see :data:`_DEBUG_TOGGLE_KEY`), and a widget
308 carrying both a default and a session-state write logs Streamlit's "default
309 value but also had its value set via the Session State API" warning on every
310 run.
311 """
312 st.session_state[_DEBUG_TOGGLE_KEY] = bool(st.session_state.get(DEBUG_STATE_KEY))
313 (host if host is not None else st).toggle(
314 f"{ICONS['debug']} Debug mode",
315 key=_DEBUG_TOGGLE_KEY,
316 on_change=_mirror_debug_toggle,
317 help="Show the captured log, a snapshot of what's loaded and a JSON "
318 "for bug reports. Also lists the *Synthetic test trial* dataset.",
319 )
322def _state_snapshot() -> list[dict[str, str]]:
323 """A few high-signal facts about what's currently loaded, best-effort.
325 Reads optional session-state keys defensively — missing keys are simply
326 omitted so this never crashes regardless of app state.
327 """
328 ss = st.session_state
329 rows: list[dict[str, str]] = []
331 def add(label: str, value: Any) -> None:
332 if value is not None:
333 rows.append({"key": label, "value": str(value)})
335 add("Active view", ss.get("active_view"))
336 add("Dataset / source", ss.get("data_source") or ss.get("_active_source_name"))
337 add("Participant", ss.get("_deeplink_participant"))
339 # Frame shapes for any cached DataFrame-like objects in session_state.
340 for key, val in list(ss.items()):
341 shape = getattr(val, "shape", None)
342 if shape is not None and isinstance(shape, tuple) and len(shape) == 2:
343 add(f"{key} (rows×cols)", f"{shape[0]} × {shape[1]}")
345 rows.append({"key": "session_state keys", "value": str(len(ss))})
346 return rows
349def render_debug_panel(host=None) -> None:
350 """Render the debug panel into the 🐛 Debug menu popover.
352 No-op unless the Debug toggle is on. The panel is the captured-log view, a
353 state snapshot and a JSON download, drawn under the toggle in
354 :func:`_debug_dialog`.
355 """
356 if not debug_enabled():
357 return
359 panel = host if host is not None else st.container()
360 records = list(_buffer())
362 with panel:
363 cols = st.columns([3, 1])
364 with cols[0]:
365 min_level = st.selectbox(
366 "Min level", _LEVELS, index=_LEVELS.index("INFO"), key="_debug_level"
367 )
368 with cols[1]:
369 st.write("")
370 if st.button("Clear log", key="_debug_clear", width="stretch"):
371 _buffer().clear()
372 # The dialog body is a fragment: an app-scoped rerun would close
373 # the modal on the empty log it just asked for.
374 st.rerun(scope="fragment")
376 threshold = _LEVELS.index(min_level)
377 shown = [
378 r
379 for r in records
380 if r["level"] in _LEVELS and _LEVELS.index(r["level"]) >= threshold
381 ]
383 # "lines", not "records": identical ones are collapsed, so the two
384 # numbers differ and saying which is which is the whole point.
385 events = sum(int(r.get("count", 1)) for r in records)
386 st.caption(
387 f"{len(shown)} / {len(records)} lines"
388 + (
389 f" · {events} events, identical lines collapsed"
390 if events > len(records)
391 else ""
392 )
393 )
395 if shown:
396 lines = []
397 for r in reversed(shown): # newest first
398 color = _LEVEL_COLOR.get(r["level"], "#888")
399 # Collapsed repeats carry their tally; a one-off shows nothing,
400 # so the common case reads exactly as it did before.
401 repeats = int(r.get("count", 1))
402 tally = (
403 f' <span style="color:#888">× {repeats}</span>'
404 if repeats > 1
405 else ""
406 )
407 lines.append(
408 f'<div style="font-family:monospace;font-size:11px;'
409 f'line-height:1.5;white-space:pre-wrap;word-break:break-word">'
410 f'<span style="color:#888">{r["time"]}</span> '
411 f'<span style="color:{color};font-weight:600">'
412 f"{r['level']:<7}</span> "
413 f'<span style="color:#888">{r["logger"]}</span> '
414 f"{_escape(r['message'])}{tally}</div>"
415 )
416 st.markdown(
417 f'<div style="max-height:300px;overflow-y:auto">{"".join(lines)}</div>',
418 unsafe_allow_html=True,
419 )
420 else:
421 st.caption("No log records at this level yet.")
423 st.divider()
424 st.caption(
425 "App / session state",
426 help="What this browser session holds: the size of every table in "
427 "memory (rows × columns) and how many session-state keys exist. A "
428 "read-out only — nothing here changes the app. Send it with a bug "
429 "report.",
430 )
431 snapshot = _state_snapshot()
432 st.dataframe(snapshot, hide_index=True, width="stretch")
434 export = {
435 "exported_at": datetime.now().isoformat(timespec="seconds"),
436 "records": records,
437 "state": snapshot,
438 }
439 st.download_button(
440 f"{ICONS['download']} Download logs (JSON)",
441 data=json.dumps(export, indent=2, default=str),
442 file_name="scanpath_studio_debug.json",
443 mime="application/json",
444 width="stretch",
445 key="_debug_download",
446 )
449#: UX-179 — the Debug drawer's request flag. #374 F31 moved its way in from a
450#: ❓ Help nav entry to a button at the foot of About: one dialog cannot open
451#: another, so the button sets this and reruns, and ``app.main`` serves it
452#: early, beside FAQ and About.
453_DEBUG_DIALOG_KEY = "_debug_dialog_requested"
456def _arm_debug() -> None:
457 """Request the Debug dialog. Called by About's Debug button."""
458 st.session_state[_DEBUG_DIALOG_KEY] = True
461def maybe_show_debug() -> None:
462 """Open the Debug dialog if About's Debug button armed it."""
463 if st.session_state.pop(_DEBUG_DIALOG_KEY, False):
464 _debug_dialog()
467@st.dialog(f"{ICONS['debug']} Debug", width="large", position="right")
468@guarded()
469def _debug_dialog() -> None:
470 """The Debug drawer: the gate, then — once it is on — the log panel.
472 A right-side drawer (Streamlit 1.65) rather than a centred modal, so the
473 view the log describes stays in sight beside it; the user can widen it.
475 The toggle is the whole of the feature's switch (UX-37), so it sits here
476 even while it is off; the panel under it appears in the same fragment run
477 that turns it on, because the toggle's ``on_change`` mirrors the gate before
478 this body re-runs.
479 """
480 render_debug_toggle()
481 if debug_enabled():
482 render_debug_panel()
485def _escape(text: str) -> str:
486 """Minimal HTML escaping for log messages rendered via st.markdown."""
487 return text.replace("&", "&").replace("<", "<").replace(">", ">")