Skip to content

Commit a52981f

Browse files
fix(logging): keep console output to spinner banners only
Console sinks ignored log level, so debug diagnostics (run_conditions evaluation, guard skip/call lines, dataclass dumps) leaked to the terminal and GUI console. Gate sinks on level: debug now goes to the file log only; info and above reach the console. Stop the guard decorator from announcing skips on-console — it logs at debug only; meaningful skips are reported by the step's caller under its banner. Make the GUI console 1-to-1 with the terminal: clear the transient status line when a banner finishes, and render the finished banner as the plain done-title (no checkmark), exactly as the terminal prints it. Add parity and level-gating tests.
1 parent 793a5c4 commit a52981f

9 files changed

Lines changed: 167 additions & 18 deletions

File tree

src/subsearch/core/run_conditions.py

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,17 @@ class PipelineStep(StrEnum):
2828

2929
ConditionList = list[tuple[str, "bool | Callable[[], bool]"]]
3030

31+
STEP_DISPLAY_NAMES = {
32+
PipelineStep.SUBTITLE_POST_PROCESSING: "Post-processing",
33+
PipelineStep.EXTRACT_FILES: "Extracting subtitles",
34+
PipelineStep.SUBTITLE_RENAME: "Renaming subtitle",
35+
PipelineStep.SUBTITLE_MOVE_BEST: "Moving best subtitle",
36+
PipelineStep.SUBTITLE_MOVE_ALL: "Moving all subtitles",
37+
PipelineStep.RUN_PROVIDER_DIAGNOSTICS: "Provider diagnostics",
38+
PipelineStep.FINISH_NOTIFICATION: "Finish notification",
39+
PipelineStep.DOWNLOAD_FILES: "Downloading subtitles",
40+
}
41+
3142
SKIP_LABEL_EXPLANATIONS = {
3243
"provider_enabled": "disabled in settings",
3344
"language_supports_opensubtitles": "does not support the selected language",
@@ -55,17 +66,6 @@ class PipelineStep(StrEnum):
5566
"diagnostics_enabled": "diagnostics are disabled in settings",
5667
}
5768

58-
STEP_DISPLAY_NAMES = {
59-
PipelineStep.SUBTITLE_POST_PROCESSING: "Post-processing",
60-
PipelineStep.EXTRACT_FILES: "Extracting subtitles",
61-
PipelineStep.SUBTITLE_RENAME: "Renaming subtitle",
62-
PipelineStep.SUBTITLE_MOVE_BEST: "Moving best subtitle",
63-
PipelineStep.SUBTITLE_MOVE_ALL: "Moving all subtitles",
64-
PipelineStep.RUN_PROVIDER_DIAGNOSTICS: "Provider diagnostics",
65-
PipelineStep.FINISH_NOTIFICATION: "Finish notification",
66-
PipelineStep.DOWNLOAD_FILES: "Downloading subtitles",
67-
}
68-
6969

7070
class RunConditions:
7171
def __init__(self, bootstrap: Bootstrap) -> None:

src/subsearch/decorators/conditional_execution.py

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,9 @@
66

77

88
def run_if_conditions_met(func: Callable[..., Any]) -> Callable[..., Any]:
9+
# The guard's skip/call/explanation lines are diagnostics for the file log
10+
# only (debug level), never the console. Meaningful skips a user should see
11+
# are reported explicitly by the step's caller, swallowed by its banner.
912

1013
@functools.wraps(func)
1114
def wrapper(*args: Any, **kwargs: Any) -> Any:
@@ -16,7 +19,7 @@ def wrapper(*args: Any, **kwargs: Any) -> Any:
1619
log.event(LogEvent.GUARD_STEP_SKIPPED, level="debug", qualified_name=qualified_name)
1720
skip_explanation = instance.call_conditions.skip_explanation(func.__name__)
1821
if skip_explanation is not None:
19-
log.event(LogEvent.PIPELINE_STEP_SKIPPED, message=skip_explanation)
22+
log.event(LogEvent.PIPELINE_STEP_SKIPPED, level="debug", message=skip_explanation)
2023
return None
2124
log.event(LogEvent.GUARD_STEP_CALLED, level="debug", qualified_name=qualified_name)
2225
return func(*args, **kwargs)

src/subsearch/decorators/process_guard.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ def _release_mutex(kernel32: Any, mutex: Any) -> None:
3838
def _log_single_instance_setting() -> None:
3939
try:
4040
single_instance = config_session.get_config_session().read(ConfigKey.APPLICATION_SINGLE_INSTANCE)
41-
except (FileNotFoundError, KeyError, TypeError):
41+
except FileNotFoundError, KeyError, TypeError:
4242
return
4343

4444
log.event(

src/subsearch/runtime/logging/logger.py

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -96,7 +96,7 @@ def _clear_crash_log_periodically() -> None:
9696
counter_path = FILE_PATHS.crash.with_suffix(".count")
9797
try:
9898
run_count = int(counter_path.read_text(encoding="utf-8")) + 1
99-
except (FileNotFoundError, ValueError):
99+
except FileNotFoundError, ValueError:
100100
run_count = 1
101101
if run_count >= CRASH_CLEAR_EVERY_RUNS:
102102
FILE_PATHS.crash.unlink(missing_ok=True)
@@ -179,6 +179,10 @@ def write(
179179
is_last: bool = False,
180180
) -> None:
181181
self.file_logger.log(LEVELS[level], message, stacklevel=3)
182+
# Debug lines are diagnostics for the file log only; the console (terminal
183+
# banner and GUI mirror) shows the user-facing run, so they never reach a sink.
184+
if LEVELS[level] < logging.INFO:
185+
return
182186
self._console_history.append(
183187
ConsoleRecord(
184188
message=message,

src/subsearch/ui/widgets/console_view.py

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,6 @@
1515
# animates with the same glyphs the terminal shows.
1616
SPINNER_FRAMES = ("◜", "◠", "◝", "◞", "◡", "◟")
1717
SPINNER_INTERVAL_MS = 100
18-
SPINNER_DONE_MARK = "✔"
1918

2019
CONSOLE_STYLE_SHEET = """
2120
QListWidget {
@@ -129,11 +128,20 @@ def _finish_banner(self, done_title: str) -> None:
129128
if self._banner_item is None:
130129
return
131130
self._spinner_timer.stop()
132-
self._banner_item.setText(f"{SPINNER_DONE_MARK} {done_title}")
131+
# The transient status line is cleared on finish, exactly as the terminal
132+
# console drops its in-place line; the spinner glyph is replaced by the
133+
# plain done-title the terminal prints (no decoration), so both match.
134+
self._remove_status_item()
135+
self._banner_item.setText(done_title)
133136
self._banner_item = None
134-
self._status_item = None
135137
self._banner_title = ""
136138

139+
def _remove_status_item(self) -> None:
140+
if self._status_item is None:
141+
return
142+
self._list.takeItem(self._list.row(self._status_item))
143+
self._status_item = None
144+
137145
def _tick_spinner(self) -> None:
138146
if self._banner_item is None:
139147
return

tests/test_console_parity.py

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,87 @@
1+
from subsearch.runtime.logging.spinner_console import SpinnerConsole
2+
3+
# A representative run: a banner with two transient lines, a plain line before
4+
# any banner, a second banner, and a final is_last close. The terminal and GUI
5+
# consoles must end up showing the same visible lines.
6+
RECORDS = [
7+
{"message": "early line"},
8+
{"message": "--- [Searching] ---", "is_banner": True, "title": "Searching", "done_title": "Searched"},
9+
{"message": "opensubtitles: searching"},
10+
{"message": "opensubtitles: found 3"},
11+
{"message": "--- [Cleaning up] ---", "is_banner": True, "title": "Cleaning up", "done_title": "Cleaned up"},
12+
{"message": "", "is_last": True},
13+
]
14+
15+
16+
def terminal_visible_lines() -> list[str]:
17+
printed: list[str] = []
18+
transient: list[str] = []
19+
20+
class StubTransient:
21+
def update(self, spinner, message: str) -> None:
22+
if transient:
23+
transient[-1] = message
24+
else:
25+
transient.append(message)
26+
27+
def clear(self, spinner) -> None:
28+
transient.clear()
29+
30+
class StubSpinner:
31+
def __init__(self, text: str) -> None:
32+
self.text = text
33+
34+
def start(self) -> None:
35+
pass
36+
37+
def stop(self) -> None:
38+
pass
39+
40+
console = SpinnerConsole(
41+
spinner_factory=StubSpinner,
42+
printer=printed.append,
43+
transient_line=StubTransient(),
44+
)
45+
for record in RECORDS:
46+
console.write(record["message"], **{key: value for key, value in record.items() if key != "message"})
47+
return printed
48+
49+
50+
def gui_visible_lines(qtbot) -> list[str]:
51+
from subsearch.runtime.logging.logger import log
52+
from subsearch.ui.services.console_view import ConsoleViewSink
53+
from subsearch.ui.widgets.console_view import ConsoleView
54+
55+
# The logger is a process-wide singleton; other tests leave records in its
56+
# history that the sink would replay into the view. Isolate to this sequence.
57+
log._console_history.clear()
58+
sink = ConsoleViewSink()
59+
view = ConsoleView(sink)
60+
qtbot.addWidget(view)
61+
dispatch = {
62+
"line": view._append,
63+
"banner": view._start_banner,
64+
"finish": view._finish_banner,
65+
"status": view._update_status,
66+
}
67+
try:
68+
for record in RECORDS:
69+
sink._on_message(
70+
record["message"],
71+
**{key: value for key, value in record.items() if key != "message"},
72+
)
73+
# Drive the view directly from the sink's recorded protocol; the live
74+
# widget uses queued connections that need an event loop to deliver.
75+
for kind, payload in sink.history():
76+
dispatch[kind](payload)
77+
return [view._list.item(row).text() for row in range(view._list.count())]
78+
finally:
79+
sink.detach()
80+
81+
82+
def test_terminal_and_gui_show_the_same_lines(qtbot) -> None:
83+
# No normalization: the GUI must render finished banners as the plain
84+
# done-title the terminal prints, with no checkmark or other decoration.
85+
terminal = terminal_visible_lines()
86+
gui = gui_visible_lines(qtbot)
87+
assert terminal == gui
Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,29 @@
1+
from subsearch.runtime.logging.logger import Logger
2+
3+
4+
def _capture(logger: Logger) -> list[str]:
5+
captured: list[str] = []
6+
logger._sinks.clear()
7+
logger.add_sink(lambda message, **_: captured.append(message))
8+
return captured
9+
10+
11+
def test_debug_messages_never_reach_console_sinks() -> None:
12+
logger = Logger()
13+
captured = _capture(logger)
14+
15+
logger.debug("diagnostic detail")
16+
17+
assert captured == []
18+
assert logger._console_history == []
19+
20+
21+
def test_info_and_above_reach_console_sinks() -> None:
22+
logger = Logger()
23+
captured = _capture(logger)
24+
25+
logger.info("user-facing line")
26+
logger.warning("heads up")
27+
logger.error("something failed")
28+
29+
assert captured == ["user-facing line", "heads up", "something failed"]

tests/test_run_conditions.py

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -287,6 +287,24 @@ def test_unmet_condition_labels_empty_when_provider_runs(fake_cls: FakeBootstrap
287287
assert fake_cls.call_conditions.unmet_condition_labels("opensubtitles") == []
288288

289289

290+
def test_skip_explanation_for_mode_gate(fake_cls: FakeBootstrap) -> None:
291+
fake_cls.app_mode = AppMode.SEARCH_MANUAL
292+
293+
explanation = fake_cls.call_conditions.skip_explanation("subtitle_post_processing")
294+
assert explanation is not None
295+
assert "Post-processing skipped" in explanation
296+
297+
298+
def test_skip_explanation_shown_for_actionable_skip(fake_cls: FakeBootstrap) -> None:
299+
fake_cls.app_mode = AppMode.SEARCH_HYBRID
300+
fake_cls.extracted_subtitle_archives = 1
301+
fake_cls.app_config.post_processing["rename"] = False
302+
303+
explanation = fake_cls.call_conditions.skip_explanation("subtitle_rename")
304+
assert explanation is not None
305+
assert "renaming is disabled" in explanation
306+
307+
290308
def test_conditions_finish_notification(fake_cls: FakeBootstrap) -> None:
291309
fake_cls.app_mode = AppMode.SEARCH_HYBRID
292310
assert fake_cls.call_conditions.conditions_met(fake_cls.func_name) is True

tests/test_ui_entrypoint.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,8 +6,8 @@ def _spinner_titles(events):
66

77

88
def _patch_window(monkeypatch, events):
9-
from subsearch.ui.application import entrypoint
109
from subsearch.runtime.logging.logger import log
10+
from subsearch.ui.application import entrypoint
1111

1212
class FakeWindow:
1313
def __init__(self, *args, **kwargs) -> None:

0 commit comments

Comments
 (0)