From 0085596f29c0c722afc108b7162bdcade2ded425 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Walenciak?= Date: Sun, 24 May 2026 13:17:22 +0200 Subject: [PATCH] Pass proper loggers --- tests/common.py | 6 +- tests/melt/test_pair_matcher_unit.py | 2 +- tests/melt/test_performer_unit.py | 8 +- tests/utils/test_logging_usage.py | 79 +++++++++++++ twotone/tools/concatenate.py | 7 +- twotone/tools/language_fixer.py | 10 +- twotone/tools/melt/jellyfin.py | 6 +- twotone/tools/melt/melt_analyzer.py | 5 +- twotone/tools/melt/melt_performer.py | 101 ++++++++++------- twotone/tools/melt/melt_tool.py | 4 +- twotone/tools/melt/pair_matcher.py | 12 +- twotone/tools/merge.py | 34 +++--- twotone/tools/subtitles_fixer.py | 15 ++- twotone/tools/transcode.py | 18 +-- twotone/tools/utilities.py | 13 ++- twotone/tools/utils/generic_utils.py | 8 +- twotone/tools/utils/process_utils.py | 16 ++- twotone/tools/utils/subtitles_utils.py | 48 +++++--- twotone/tools/utils/tmdb_cache.py | 5 +- twotone/tools/utils/video_utils.py | 149 +++++++++++++++---------- twotone/twotone.py | 4 +- 21 files changed, 360 insertions(+), 190 deletions(-) create mode 100644 tests/utils/test_logging_usage.py diff --git a/tests/common.py b/tests/common.py index 7f64cf28..595d888e 100644 --- a/tests/common.py +++ b/tests/common.py @@ -498,11 +498,11 @@ def run_twotone(tool: str, tool_options: list[str] | None = None, global_options def simulate_process_failure(target_exec: str): original = process_utils.start_process - def wrapper(cmd, args): + def wrapper(cmd, args, *wrapper_args, **wrapper_kwargs): _, exec_name, _ = files_utils.split_path(cmd) if exec_name == target_exec: - return process_utils.ProcessResult(1, b"", b"") - return original(cmd, args) + return process_utils.ProcessResult(1, "", "") + return original(cmd, args, *wrapper_args, **wrapper_kwargs) with patch("twotone.tools.utils.process_utils.start_process", side_effect=wrapper) as p: yield p diff --git a/tests/melt/test_pair_matcher_unit.py b/tests/melt/test_pair_matcher_unit.py index 87f3759d..cb3b940e 100644 --- a/tests/melt/test_pair_matcher_unit.py +++ b/tests/melt/test_pair_matcher_unit.py @@ -24,7 +24,7 @@ def _make_pair_matcher(self, lhs_fps: float = 25.0, rhs_fps: float = 25.0) -> Pa fps_map = {"/fake/lhs.mp4": str(lhs_fps), "/fake/rhs.mp4": str(rhs_fps)} with patch.object(video_utils, 'get_video_data', - side_effect=lambda p: {"video": [{"fps": fps_map[p]}]}): + side_effect=lambda p, **_kwargs: {"video": [{"fps": fps_map[p]}]}): pm = PairMatcher( interruption=generic_utils.InterruptibleProcess(), wd=tempfile.mkdtemp(), diff --git a/tests/melt/test_performer_unit.py b/tests/melt/test_performer_unit.py index 47c9b11a..ee424159 100644 --- a/tests/melt/test_performer_unit.py +++ b/tests/melt/test_performer_unit.py @@ -100,7 +100,7 @@ def fake_raise_on_error(result): right_points = [p[1] for p in segment_pairs] source_segment_dur = max(right_points) - min(right_points) - def fake_get_duration(path): + def fake_get_duration(path, **_kwargs): if "source_trimmed" in path or "source_scaled" in path or "out." in path: return source_segment_dur return base_duration_ms @@ -703,7 +703,7 @@ def fake_start_process(tool, args, **kwargs): calls.append((tool, list(args))) return _FAKE_PROCESS_OK - def fake_get_duration(path): + def fake_get_duration(path, **_kwargs): # Trimmed audio is shorter than requested → simulates AVI deficit if "source_trimmed" in path: return actual_trimmed_dur @@ -773,7 +773,7 @@ def test_patch_audio_no_deficit_keeps_original_sync_offset(self): pairs = [(seg1_start, seg2_start), (seg1_end, seg2_end)] source_dur = seg2_end - seg2_start - def fake_get_duration(path): + def fake_get_duration(path, **_kwargs): if "source_trimmed" in path or "source_scaled" in path or "out." in path: return source_dur # no deficit — actual equals requested return 7000000 @@ -808,7 +808,7 @@ def test_patch_audio_fill_gaps_raises_on_deficit(self): source_dur = seg2_end - seg2_start audio_deficit_ms = 488 - def fake_get_duration(path): + def fake_get_duration(path, **_kwargs): if "source_trimmed" in path: return source_dur - audio_deficit_ms return 7000000 diff --git a/tests/utils/test_logging_usage.py b/tests/utils/test_logging_usage.py new file mode 100644 index 00000000..9b6bcce3 --- /dev/null +++ b/tests/utils/test_logging_usage.py @@ -0,0 +1,79 @@ +import ast +import unittest +from pathlib import Path + + +FORBIDDEN_LOGGING_CALLS = { + "critical", + "debug", + "error", + "exception", + "info", + "log", + "warn", + "warning", +} + + +class LoggingUsageTests(unittest.TestCase): + def test_production_code_does_not_use_root_logging_calls(self): + project_root = Path(__file__).resolve().parents[2] + production_root = project_root / "twotone" + + offenders: list[str] = [] + for path in sorted(production_root.rglob("*.py")): + tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path)) + for node in ast.walk(tree): + if not isinstance(node, ast.Call): + continue + func = node.func + if not isinstance(func, ast.Attribute): + continue + value = func.value + if not isinstance(value, ast.Name) or value.id != "logging": + continue + if func.attr not in FORBIDDEN_LOGGING_CALLS: + continue + + rel_path = path.relative_to(project_root) + offenders.append(f"{rel_path}:{node.lineno} logging.{func.attr}()") + + self.assertEqual([], offenders) + + def test_production_code_uses_twotone_logger_hierarchy(self): + project_root = Path(__file__).resolve().parents[2] + production_root = project_root / "twotone" + + offenders: list[str] = [] + for path in sorted(production_root.rglob("*.py")): + tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path)) + for node in ast.walk(tree): + if not isinstance(node, ast.Call): + continue + func = node.func + if not isinstance(func, ast.Attribute): + continue + value = func.value + if not isinstance(value, ast.Name) or value.id != "logging": + continue + if func.attr != "getLogger": + continue + + rel_path = path.relative_to(project_root) + if not node.args: + offenders.append(f"{rel_path}:{node.lineno} logging.getLogger()") + continue + + logger_name = node.args[0] + if isinstance(logger_name, ast.Constant) and isinstance(logger_name.value, str): + if not logger_name.value.startswith("TwoTone"): + offenders.append(f"{rel_path}:{node.lineno} logging.getLogger({logger_name.value!r})") + continue + + offenders.append(f"{rel_path}:{node.lineno} logging.getLogger()") + + self.assertEqual([], offenders) + + +if __name__ == "__main__": + unittest.main() diff --git a/twotone/tools/concatenate.py b/twotone/tools/concatenate.py index f61f4d12..4e0f1ed0 100644 --- a/twotone/tools/concatenate.py +++ b/twotone/tools/concatenate.py @@ -14,8 +14,7 @@ class Concatenate(generic_utils.InterruptibleProcess): def __init__(self, logger: logging.Logger, working_dir: str): - super().__init__() - + super().__init__(logger) self.logger = logger self.working_dir = working_dir @@ -109,7 +108,7 @@ def perform(self, sorted_videos: dict[str, list[tuple[str, int]]]) -> None: audio_codec = "copy" for input_file in input_files: - file_details = video_utils.get_video_data(input_file) + file_details = video_utils.get_video_data(input_file, logger=self.logger) audio_streams = file_details.get("audio", []) for audio_stream in audio_streams: codec = audio_stream.get("codec") @@ -125,7 +124,7 @@ def escape_path(path: str) -> str: ffmpeg_args = ["-f", "concat", "-safe", "0", "-i", input_file, "-c:v", "copy", "-c:a", audio_codec, output] self.logger.info(f"Concatenating files into {output} file") - status = process_utils.start_process("ffmpeg", ffmpeg_args) + status = process_utils.start_process("ffmpeg", ffmpeg_args, logger=self.logger) if status.returncode == 0: for input_file in input_files: os.remove(input_file) diff --git a/twotone/tools/language_fixer.py b/twotone/tools/language_fixer.py index b24d3e20..89dc9ee0 100644 --- a/twotone/tools/language_fixer.py +++ b/twotone/tools/language_fixer.py @@ -327,7 +327,7 @@ def _scan_directory(self, path: str, include_audio: bool) -> list[dict]: def _set_context(self, logger: logging.Logger, working_dir: str) -> None: self.logger = logger self.working_dir = working_dir - self._interruption = generic_utils.InterruptibleProcess() + self._interruption = generic_utils.InterruptibleProcess(logger) def check_for_stop(self) -> None: if self._interruption is not None: @@ -348,7 +348,7 @@ def _is_rmvb(path: str) -> bool: def _get_tracks_mkvmerge(self, video_path: str) -> list[dict]: start = time.perf_counter() - info = video_utils.get_video_full_info_mkvmerge(video_path) + info = video_utils.get_video_full_info_mkvmerge(video_path, logger=self.logger) self._log_if_slow("get_tracks_mkvmerge", video_path, start) tracks: list[dict] = [] @@ -383,7 +383,7 @@ def _get_tracks_mkvmerge(self, video_path: str) -> list[dict]: def _get_tracks_ffprobe(self, video_path: str) -> list[dict]: start = time.perf_counter() - info = video_utils.get_video_full_info(video_path) + info = video_utils.get_video_full_info(video_path, logger=self.logger) self._log_if_slow("get_tracks_ffprobe", video_path, start) tracks: list[dict] = [] for stream in info.get("streams", []): @@ -581,7 +581,7 @@ def _detect_subtitle_languages(self, video_path: str, missing_subtitles: list[in encoding = subtitles_utils.file_encoding(path) self._log_if_slow("subtitle_file_encoding", path, encoding_start) lang_start = time.perf_counter() - detected_lang = subtitles_utils.guess_subtitle_language(path, encoding) + detected_lang = subtitles_utils.guess_subtitle_language(path, encoding, logger=self.logger) self._log_if_slow("subtitle_language_guess", path, lang_start) if detected_lang: try: @@ -664,7 +664,7 @@ def _apply_language_updates(self, video_path: str, updates: dict[int, str]) -> b args.extend(["--language", f"{tid}:{lang}"]) args.append(video_path) - status = process_utils.start_process("mkvmerge", args) + status = process_utils.start_process("mkvmerge", args, logger=self.logger) if status.returncode not in (0, 1): output = (status.stdout or "") + (status.stderr or "") self.logger.error( diff --git a/twotone/tools/melt/jellyfin.py b/twotone/tools/melt/jellyfin.py index 83bccc5a..cf2b0950 100644 --- a/twotone/tools/melt/jellyfin.py +++ b/twotone/tools/melt/jellyfin.py @@ -12,6 +12,9 @@ from .duplicates_source import DuplicatesSource +DEFAULT_LOGGER = logging.getLogger("TwoTone.melt.jellyfin") + + class JellyfinSource(DuplicatesSource): def __init__(self, interruption: generic_utils.InterruptibleProcess, url: str, token: str, path_fix: tuple[str, str] | None, logger: logging.Logger | None = None) -> None: super().__init__(interruption) @@ -19,8 +22,7 @@ def __init__(self, interruption: generic_utils.InterruptibleProcess, url: str, t self.url = url self.token = token self.path_fix = path_fix - # allow injecting a logger for better control in callers/tests - self.logger = logger or logging.getLogger(__name__) + self.logger = logger or DEFAULT_LOGGER self.tmdb_id_by_path: dict[str, str] = {} self.tmdb_cache = TmdbCache(logger=self.logger) diff --git a/twotone/tools/melt/melt_analyzer.py b/twotone/tools/melt/melt_analyzer.py index add7b2b5..02869f6c 100644 --- a/twotone/tools/melt/melt_analyzer.py +++ b/twotone/tools/melt/melt_analyzer.py @@ -168,9 +168,8 @@ def _print_attachments_details(self, ids: dict[str, int], all_attachments: Itera file_id = ids[path] self.logger.debug(f"Attachment ID #{tid} from file #{file_id}") - @staticmethod - def _probe_inputs(files: Sequence[str]) -> tuple[dict[str, Any], dict[str, Any], dict[str, Any]]: - details_full = {file: video_utils.get_video_data_mkvmerge(file, enrich=True) for file in files} + def _probe_inputs(self, files: Sequence[str]) -> tuple[dict[str, Any], dict[str, Any], dict[str, Any]]: + details_full = {file: video_utils.get_video_data_mkvmerge(file, enrich=True, logger=self.logger) for file in files} attachments = {file: info["attachments"] for file, info in details_full.items()} tracks = {file: info["tracks"] for file, info in details_full.items()} return details_full, attachments, tracks diff --git a/twotone/tools/melt/melt_performer.py b/twotone/tools/melt/melt_performer.py index ae5ee402..1441b365 100644 --- a/twotone/tools/melt/melt_performer.py +++ b/twotone/tools/melt/melt_performer.py @@ -138,7 +138,7 @@ def process_duplicates(self, plan: list[dict[str, Any]]) -> None: self.logger.info("Generating file: %s", self._display_path(output)) process_utils.raise_on_error( - process_utils.start_process("mkvmerge", generation_args, show_progress=True) + process_utils.start_process("mkvmerge", generation_args, show_progress=True, logger=self.logger) ) self.logger.info("%s saved.", output) @@ -241,8 +241,8 @@ def patch_audio_constant_offset( seg2_start, seg2_end = seg.rhs_start, seg.rhs_end # 1. Extract head/tail directly from base video, normalized to source params - source_params = self._get_audio_params(source_video) - base_duration_ms = video_utils.get_video_duration(base_video) + source_params = self._get_audio_params(source_video, logger=self.logger) + base_duration_ms = video_utils.get_video_duration(base_video, logger=self.logger) has_head = seg1_start > 0 and not use_silence has_tail = seg1_end < base_duration_ms and not use_silence @@ -268,7 +268,7 @@ def patch_audio_constant_offset( "-i", base_video, "-map", "0:a:0", *self._normalize_args(source_params), "-c:a", "flac", head_path, - ]) + ], logger=self.logger) ) if has_tail: process_utils.raise_on_error( @@ -277,7 +277,7 @@ def patch_audio_constant_offset( "-i", base_video, "-map", "0:a:0", *self._normalize_args(source_params), "-c:a", "flac", tail_path, - ]) + ], logger=self.logger) ) # 2. Trim + time-scale source audio. @@ -296,9 +296,9 @@ def patch_audio_constant_offset( "-i", source_video, "-map", "0:a:0", "-c:a", "copy", output_path, - ]) + ], logger=self.logger) ) - actual_dur = video_utils.get_video_duration(output_path) + actual_dur = video_utils.get_video_duration(output_path, logger=self.logger) deficit = source_dur - actual_dur if not use_silence and deficit > 50: @@ -320,19 +320,19 @@ def patch_audio_constant_offset( trimmed_audio = os.path.join(wd, "source_trimmed.flac") process_utils.raise_on_error( - process_utils.start_process("ffmpeg", [ - "-y", - "-ss", str(seg2_start / 1000), - "-to", str(seg2_end / 1000), - "-i", source_video, - "-map", "0:a:0", - "-sample_fmt", self._flac_safe_fmt(source_params[2]), - "-c:a", "flac", - trimmed_audio, - ]) + process_utils.start_process("ffmpeg", [ + "-y", + "-ss", str(seg2_start / 1000), + "-to", str(seg2_end / 1000), + "-i", source_video, + "-map", "0:a:0", + "-sample_fmt", self._flac_safe_fmt(source_params[2]), + "-c:a", "flac", + trimmed_audio, + ], logger=self.logger) ) - actual_source_dur = video_utils.get_video_duration(trimmed_audio) + actual_source_dur = video_utils.get_video_duration(trimmed_audio, logger=self.logger) expected_scaled_dur = round(actual_source_dur * video_ratio) # Compute sync offset from the measured trim deficit. @@ -371,18 +371,19 @@ def patch_audio_constant_offset( "-filter:a", f"asetrate={adjusted_rate:.6f},aresample={sample_rate}", "-sample_fmt", "s32", "-c:a", "flac", scaled_audio, - ]) + ], logger=self.logger) ) - scaled_dur = video_utils.get_video_duration(scaled_audio) + scaled_dur = video_utils.get_video_duration(scaled_audio, logger=self.logger) self._validate_audio_duration(scaled_dur, expected_scaled_dur, "scaled audio") # 3. Concatenate and encode to AAC - channel_layout = self._get_audio_channel_layout(source_video) + channel_layout = self._get_audio_channel_layout(source_video, logger=self.logger) self._concat_and_encode( [scaled_audio], has_head, head_path, has_tail, tail_path, os.path.join(wd, "concat.txt"), output_path, channel_layout=channel_layout, + logger=self.logger, ) return sync_offset @@ -573,9 +574,13 @@ def _log_coverage( self.logger.info("Overlap diagram:\n%s", "\n".join(diagram)) @staticmethod - def _extract_audio_to_flac(video_path: str, output_path: str) -> None: + def _extract_audio_to_flac(video_path: str, output_path: str, logger: logging.Logger | None = None) -> None: process_utils.raise_on_error( - process_utils.start_process("ffmpeg", ["-y", "-i", video_path, "-map", "0:a:0", "-sample_fmt", "s32", "-c:a", "flac", output_path]) + process_utils.start_process( + "ffmpeg", + ["-y", "-i", video_path, "-map", "0:a:0", "-sample_fmt", "s32", "-c:a", "flac", output_path], + logger=logger, + ) ) @staticmethod @@ -585,16 +590,16 @@ def _segment_range(pairs: Sequence[tuple[int, int]]) -> _SegmentRange: return _SegmentRange(min(left), max(left), min(right), max(right)) @staticmethod - def _get_audio_params(audio_path: str) -> tuple[int, int, str]: + def _get_audio_params(audio_path: str, logger: logging.Logger | None = None) -> tuple[int, int, str]: """Return (channels, sample_rate, sample_fmt) of the first audio stream.""" - info = video_utils.get_video_full_info(audio_path) + info = video_utils.get_video_full_info(audio_path, logger=logger) stream = next(s for s in info["streams"] if s["codec_type"] == "audio") return int(stream["channels"]), int(stream["sample_rate"]), stream["sample_fmt"] @staticmethod - def _get_audio_channel_layout(audio_path: str) -> str | None: + def _get_audio_channel_layout(audio_path: str, logger: logging.Logger | None = None) -> str | None: """Return the channel layout string of the first audio stream, or None.""" - info = video_utils.get_video_full_info(audio_path) + info = video_utils.get_video_full_info(audio_path, logger=logger) stream = next(s for s in info["streams"] if s["codec_type"] == "audio") return stream.get("channel_layout") or None @@ -688,6 +693,7 @@ def _extract_head_tail( head_path: str, tail_path: str, normalize_to: tuple[int, int, str] | None = None, + logger: logging.Logger | None = None, ) -> tuple[bool, bool]: """Extract head/tail segments from the base audio track. @@ -709,17 +715,17 @@ def _extract_head_tail( process_utils.start_process("ffmpeg", [ "-y", "-ss", "0", "-to", str(seg_start_ms / 1000), "-i", base_audio, *norm_args, "-c:a", "flac", head_path, - ]) + ], logger=logger) ) - base_duration_ms = video_utils.get_video_duration(base_video) + base_duration_ms = video_utils.get_video_duration(base_video, logger=logger) has_tail = seg_end_ms < base_duration_ms if has_tail: process_utils.raise_on_error( process_utils.start_process("ffmpeg", [ "-y", "-ss", str(seg_end_ms / 1000), "-i", base_audio, *norm_args, "-c:a", "flac", tail_path, - ]) + ], logger=logger) ) return has_head, has_tail @@ -742,6 +748,7 @@ def _concat_and_encode( concat_list_path: str, output_path: str, channel_layout: str | None = None, + logger: logging.Logger | None = None, ) -> None: """Concatenate audio parts (head + middle segments + tail) and encode to AAC. @@ -781,7 +788,7 @@ def _esc(p: str) -> str: *layout_args, "-c:a", "aac", output_path, - ]) + ], logger=logger) ) def _patch_audio_segment( @@ -823,10 +830,10 @@ def _patch_audio_segment( # 1. Extract audio tracks if not use_silence: v1_audio = os.path.join(wd, "v1_audio.flac") - self._extract_audio_to_flac(base_video, v1_audio) - self._extract_audio_to_flac(source_video, v2_audio) + self._extract_audio_to_flac(base_video, v1_audio, logger=self.logger) + self._extract_audio_to_flac(source_video, v2_audio, logger=self.logger) - source_params = self._get_audio_params(v2_audio) + source_params = self._get_audio_params(v2_audio, logger=self.logger) # 2. Extract head/tail from base audio (skipped when use_silence — caller uses --sync) if use_silence: @@ -836,6 +843,7 @@ def _patch_audio_segment( has_head, has_tail = self._extract_head_tail( v1_audio, base_video, seg1_start, seg1_end, head_path, tail_path, normalize_to=source_params, + logger=self.logger, ) # 3. Generate subsegment split points from provided mapping pairs @@ -897,7 +905,8 @@ def closest_pair(value: int, pairs: Sequence[tuple[int, int]]) -> tuple[int, int "-i", v2_audio, "-c:a", "flac", raw_cut, - ] + ], + logger=self.logger, ) ) @@ -909,18 +918,20 @@ def closest_pair(value: int, pairs: Sequence[tuple[int, int]]) -> tuple[int, int "-filter:a", f"atempo={ratio:.3f}", "-sample_fmt", "s32", "-c:a", "flac", scaled_cut, - ] + ], + logger=self.logger, ) ) temp_segments.append(scaled_cut) # 5. Concatenate and encode - channel_layout = self._get_audio_channel_layout(source_video) + channel_layout = self._get_audio_channel_layout(source_video, logger=self.logger) self._concat_and_encode( temp_segments, has_head, head_path, has_tail, tail_path, os.path.join(wd, "concat.txt"), output_path, channel_layout=channel_layout, + logger=self.logger, ) def _build_output_path(self, title: str, output_name: str) -> str: @@ -960,10 +971,10 @@ def _shift_audio_no_reencode( "-i", source_video, "-map", "0:a:0", "-c:a", "copy", output_path, - ]) + ], logger=self.logger) ) - actual_dur = video_utils.get_video_duration(output_path) + actual_dur = video_utils.get_video_duration(output_path, logger=self.logger) self._validate_audio_duration(actual_dur, expected_dur, "stream-copied audio (no reencode)") deficit = expected_dur - actual_dur @@ -1082,7 +1093,11 @@ def _choose_audio_strategy( return _AudioStrategy.CONSTANT_OFFSET @staticmethod - def _video_track_duration(path: str, files_details: dict[str, Any]) -> int | None: + def _video_track_duration( + path: str, + files_details: dict[str, Any], + logger: logging.Logger | None = None, + ) -> int | None: """Return video track duration in ms from pre-probed plan data. Falls back to container-level ffprobe duration when plan data is @@ -1095,7 +1110,7 @@ def _video_track_duration(path: str, files_details: dict[str, Any]) -> int | Non length = track.get("length") if length is not None: return length - return video_utils.get_video_duration(path) + return video_utils.get_video_duration(path, logger=logger) def _prepare_stream_entries( self, @@ -1110,7 +1125,7 @@ def _prepare_stream_entries( streams_list: list[tuple[str, int, str, str | None]] = [] video_path_base, _, _ = video_streams[0] details = files_details or {} - base_duration = self._video_track_duration(video_path_base, details) + base_duration = self._video_track_duration(video_path_base, details, logger=self.logger) protected_paths = ( {p for (p, _, _) in video_streams} | {p for (p, _, _) in subtitle_streams} @@ -1121,7 +1136,7 @@ def _prepare_stream_entries( streams_list.append(("video", stream_index, path, language)) for (path, stream_index, language) in audio_streams: - duration = self._video_track_duration(path, details) + duration = self._video_track_duration(path, details, logger=self.logger) if _is_length_mismatch(base_duration, duration, self.tolerance_ms): assert base_duration is not None # guaranteed by _is_length_mismatch original_path = path diff --git a/twotone/tools/melt/melt_tool.py b/twotone/tools/melt/melt_tool.py index 50ae4797..ced288b6 100644 --- a/twotone/tools/melt/melt_tool.py +++ b/twotone/tools/melt/melt_tool.py @@ -139,7 +139,7 @@ def _nonneg_int(value: str) -> int: @override def analyze(self, args, logger: logging.Logger, working_dir: str) -> Plan: - interruption = generic_utils.InterruptibleProcess() + interruption = generic_utils.InterruptibleProcess(logger) data_source: DuplicatesSource | None = None parser = self.parser if parser is None: @@ -220,7 +220,7 @@ def perform(self, args, logger: logging.Logger, working_dir: str, plan: Plan) -> if not isinstance(plan, MeltPlan): raise TypeError(f"Expected MeltPlan, got {type(plan).__name__}") - interruption = generic_utils.InterruptibleProcess() + interruption = generic_utils.InterruptibleProcess(logger) cache = MeltCache(args.cache_dir, logger.getChild("cache")) if args.cache_dir else None performer = MeltPerformer( logger, diff --git a/twotone/tools/melt/pair_matcher.py b/twotone/tools/melt/pair_matcher.py index 81bdaed5..7c12f764 100644 --- a/twotone/tools/melt/pair_matcher.py +++ b/twotone/tools/melt/pair_matcher.py @@ -29,8 +29,8 @@ def __init__(self, interruption: generic_utils.InterruptibleProcess, wd: str, lh self.logger = logger self.cache = cache self.phash = PhashCache() - self.lhs_fps = generic_utils.fps_str_to_float(video_utils.get_video_data(lhs_path)["video"][0]["fps"]) - self.rhs_fps = generic_utils.fps_str_to_float(video_utils.get_video_data(rhs_path)["video"][0]["fps"]) + self.lhs_fps = generic_utils.fps_str_to_float(video_utils.get_video_data(lhs_path, logger=self.logger)["video"][0]["fps"]) + self.rhs_fps = generic_utils.fps_str_to_float(video_utils.get_video_data(rhs_path, logger=self.logger)["video"][0]["fps"]) lhs_wd = os.path.join(self.wd, "lhs") rhs_wd = os.path.join(self.wd, "rhs") @@ -692,8 +692,8 @@ def snap_to_edges( lhs_threshold_ms = snap_frames * 1000 / self.lhs_fps rhs_threshold_ms = snap_frames * 1000 / self.rhs_fps - lhs_duration = video_utils.get_video_duration(self.lhs_path) - rhs_duration = video_utils.get_video_duration(self.rhs_path) + lhs_duration = video_utils.get_video_duration(self.lhs_path, logger=self.logger) + rhs_duration = video_utils.get_video_duration(self.rhs_path, logger=self.logger) lhs_keys = sorted(lhs_all_frames.keys()) rhs_keys = sorted(rhs_all_frames.keys()) @@ -1610,6 +1610,7 @@ def _probe_frames_for(self, video_path: str, label: str) -> dict[int, dict]: result = video_utils.probe_frame_timestamps( video_path, interruption=self.interruption, desc=f"[2/6] Probing frames: {label}", + logger=self.logger, ) if cache: @@ -1666,6 +1667,7 @@ def _extract_scene_frames_for( video_path, target_dir, scene_ranges, probed_metadata, scale=(960, -2), format="png", interruption=self.interruption, desc=f"[3/6] Extracting scene frames: {label}", + logger=self.logger, ) if cache: @@ -1749,11 +1751,13 @@ def _extract_and_refine_boundaries( self.lhs_path, self.lhs_boundary_wd, lhs_boundary_ranges, self.lhs_all_frames, scale=(960, -2), format="png", interruption=self.interruption, desc=f"[6/6] Extracting boundary frames: {self.lhs_label}", + logger=self.logger, ) video_utils.extract_frames_at_ranges( self.rhs_path, self.rhs_boundary_wd, rhs_boundary_ranges, self.rhs_all_frames, scale=(960, -2), format="png", interruption=self.interruption, desc=f"[6/6] Extracting boundary frames: {self.rhs_label}", + logger=self.logger, ) # Normalize the newly extracted boundary frames and merge diff --git a/twotone/tools/merge.py b/twotone/tools/merge.py index 27614a36..0bac49a4 100644 --- a/twotone/tools/merge.py +++ b/twotone/tools/merge.py @@ -16,7 +16,7 @@ class Merge(generic_utils.InterruptibleProcess): def __init__(self, logger: logging.Logger, language: str, lang_priority: str, working_dir: str) -> None: - super().__init__() + super().__init__(logger) self.logger = logger self.language = language self.lang_priority = lang_priority.split(",") if lang_priority else [] @@ -26,7 +26,7 @@ def __init__(self, logger: logging.Logger, language: str, lang_priority: str, wo def _build_subtitle_from_path(self, path: str) -> subtitles_utils.SubtitleFile: language = None if self.language == "auto" else self.language - return subtitles_utils.build_subtitle_from_path(path, language) + return subtitles_utils.build_subtitle_from_path(path, language, logger=self.logger) def _directory_subtitle_matcher(self, dir_path: str) -> dict[str, list[subtitles_utils.SubtitleFile]]: """ @@ -43,7 +43,7 @@ def _directory_subtitle_matcher(self, dir_path: str) -> dict[str, list[subtitles path = entry.path if video_utils.is_video(path): videos.append(path) - elif subtitles_utils.is_subtitle(path): + elif subtitles_utils.is_subtitle(path, logger=self.logger): subtitles.append(path) # sort both lists by length @@ -88,7 +88,7 @@ def _recursive_subtitle_search(self, path: str) -> list[subtitles_utils.Subtitle # if there is a video file then all possible subtitles at this level (and below) belong to # it, quit recursion for current directory return [] - elif subtitles_utils.is_subtitle(entry.path): + elif subtitles_utils.is_subtitle(entry.path, logger=self.logger): found_subtitles.append(entry.path) # if we got here, then no video was found at this level @@ -107,13 +107,14 @@ def _aggressive_subtitle_search(self, path: str) -> list[subtitles_utils.Subtitl subtitles = [] directory = Path(path).parent - for entry in os.scandir(directory): - if entry.is_dir(): - sub_subtitles = self._recursive_subtitle_search(entry.path) - subtitles.extend(sub_subtitles) - elif entry.is_file() and subtitles_utils.is_subtitle(entry.path): - subtitle = self._build_subtitle_from_path(entry.path) - subtitles.append(subtitle) + with os.scandir(directory) as it: + for entry in it: + if entry.is_dir(): + sub_subtitles = self._recursive_subtitle_search(entry.path) + subtitles.extend(sub_subtitles) + elif entry.is_file() and subtitles_utils.is_subtitle(entry.path, logger=self.logger): + subtitle = self._build_subtitle_from_path(entry.path) + subtitles.append(subtitle) return subtitles @@ -158,7 +159,7 @@ def _convert_subtitle(self, video_fps: str, subtitle: subtitles_utils.SubtitleFi raise RuntimeError(f"Unsupported subtitle format: {input_file}") fps = generic_utils.fps_str_to_float(video_fps) - subs = subtitles_utils.open_subtitle_file(input_file, fps=fps) + subs = subtitles_utils.open_subtitle_file(input_file, fps=fps, logger=self.logger) if subs is None: raise RuntimeError(f"Failed to open subtitle: {input_file}") @@ -181,7 +182,7 @@ def _merge(self, input_video: str, subtitles: list[subtitles_utils.SubtitleFile] temporary_output_video = video_dir + "/_tt_merge_" + video_name + "." + "mkv" # collect details about input file - input_file_details = video_utils.get_video_data(input_video) + input_file_details = video_utils.get_video_data(input_video, logger=self.logger) input_files: set[str] = set() @@ -234,7 +235,12 @@ def _merge(self, input_video: str, subtitles: list[subtitles_utils.SubtitleFile] # perform self.logger.debug("\tMerge in progress...") - video_utils.generate_mkv(input_video=input_video, output_path=temporary_output_video, subtitles=prepared_subtitles) + video_utils.generate_mkv( + input_video=input_video, + output_path=temporary_output_video, + subtitles=prepared_subtitles, + logger=self.logger, + ) # Remove all inputs for input in input_files: diff --git a/twotone/tools/subtitles_fixer.py b/twotone/tools/subtitles_fixer.py index d8fcf34e..88a00a42 100644 --- a/twotone/tools/subtitles_fixer.py +++ b/twotone/tools/subtitles_fixer.py @@ -16,7 +16,7 @@ class Fixer(generic_utils.InterruptibleProcess): def __init__(self, logger: logging.Logger, working_dir: str) -> None: - super().__init__() + super().__init__(logger) self.logger = logger self.working_dir = working_dir @@ -71,7 +71,7 @@ def _get_resolver(self, content: pysubs2.SSAFile, video_track: dict, drop_broken def _fix_subtitle(self, broken_subtitle: str, video_info: dict, drop_broken: bool) -> bool: video_track = video_info["video"][0] - subs = subtitles_utils.open_subtitle_file(broken_subtitle, fps = video_track["fps"]) + subs = subtitles_utils.open_subtitle_file(broken_subtitle, fps = video_track["fps"], logger=self.logger) if not subs: msg = f"Failed to open subtitles file: {broken_subtitle}" raise OSError(msg) @@ -151,13 +151,18 @@ def repair_videos(self, broken_videos_info: list[tuple[dict, list[int]]], drop_b # remove all subtitles from video self.logger.debug("Removing existing subtitles from file") video_without_subtitles = video_file + ".nosubtitles.mkv" - process_utils.start_process("mkvmerge", ["-o", video_without_subtitles, "-S", video_file]) + process_utils.start_process("mkvmerge", ["-o", video_without_subtitles, "-S", video_file], logger=self.logger) # add fixed subtitles to video self.logger.debug("Adding fixed subtitles to file") temporaryVideoPath = video_file + ".fixed.mkv" - video_utils.generate_mkv(input_video = video_without_subtitles, output_path = temporaryVideoPath, subtitles = new_subtitles) + video_utils.generate_mkv( + input_video=video_without_subtitles, + output_path=temporaryVideoPath, + subtitles=new_subtitles, + logger=self.logger, + ) # overwrite broken video with fixed one os.replace(temporaryVideoPath, video_file) @@ -169,7 +174,7 @@ def repair_videos(self, broken_videos_info: list[tuple[dict, list[int]]], drop_b def _check_if_broken(self, video_file: str) -> tuple[dict, list[int]] | None: self.logger.debug(f"Processing file {video_file}") - video_info = video_utils.get_video_data(video_file) + video_info = video_utils.get_video_data(video_file, logger=self.logger) video_info["path"] = video_file video_length = video_info["video"][0]["length"] diff --git a/twotone/tools/transcode.py b/twotone/tools/transcode.py index 4312dcd4..f259eeb2 100644 --- a/twotone/tools/transcode.py +++ b/twotone/tools/transcode.py @@ -17,7 +17,7 @@ class Transcoder(generic_utils.InterruptibleProcess): def __init__(self, working_dir: str, logger: logging.Logger, target_ssim: float = 0.98, codec: str = "libx265") -> None: - super().__init__() + super().__init__(logger) self.logger = logger self.target_ssim = target_ssim self.codec = codec @@ -41,7 +41,7 @@ def _calculate_quality(self, original: str, transcoded: str) -> float | None: "-lavfi", "ssim", "-f", "null", "-" ] - result = process_utils.start_process("ffmpeg", args) + result = process_utils.start_process("ffmpeg", args, logger=self.logger) ssim_line = [line for line in result.stderr.splitlines() if "All:" in line] if ssim_line: @@ -87,7 +87,7 @@ def _transcode_video( output_file ] - process_utils.raise_on_error(process_utils.start_process("ffmpeg", args, show_progress=show_progress)) + process_utils.raise_on_error(process_utils.start_process("ffmpeg", args, show_progress=show_progress, logger=self.logger)) def _extract_segment(self, video_file: str, start_time: float, end_time: float, output_file: str) -> None: @@ -135,7 +135,7 @@ def _select_scenes(self, video_file: str, segment_duration: int = 5) -> list[tup "-vsync", "vfr", "-f", "null", "/dev/null" ] - result = process_utils.start_process("ffmpeg", args) + result = process_utils.start_process("ffmpeg", args, logger=self.logger) # Parse timestamps from the ffmpeg output timestamps = [] @@ -164,7 +164,7 @@ def _select_scenes(self, video_file: str, segment_duration: int = 5) -> list[tup def _select_segments(self, video_file: str, segment_duration: int = 5) -> list[tuple[float, float]]: - duration = video_utils.get_video_duration(video_file) / 1000 + duration = video_utils.get_video_duration(video_file, logger=self.logger) / 1000 num_segments = max(3, min(10, int(duration // 30))) if duration <= 0 or num_segments <= 0 or segment_duration <= 0: @@ -276,7 +276,11 @@ def _final_transcode(self, input_file: str, crf: int) -> None: raise ValueError() - process_utils.start_process("exiftool", ["-overwrite_original", "-TagsFromFile", input_file, "-all:all>all:all", temp_file]) + process_utils.start_process( + "exiftool", + ["-overwrite_original", "-TagsFromFile", input_file, "-all:all>all:all", temp_file], + logger=self.logger, + ) if overwrite_input: try: @@ -310,7 +314,7 @@ def find_optimal_crf(self, input_file: str, allow_segments: bool = True) -> int """Find the optimal CRF using bisection.""" original_size = os.path.getsize(input_file) - duration = video_utils.get_video_duration(input_file) + duration = video_utils.get_video_duration(input_file, logger=self.logger) if not duration: return None diff --git a/twotone/tools/utilities.py b/twotone/tools/utilities.py index fd204689..48e72af1 100644 --- a/twotone/tools/utilities.py +++ b/twotone/tools/utilities.py @@ -12,7 +12,11 @@ from .utils import video_utils, process_utils, files_utils -def extract_scenes(video_path, output_dir, format: str, scale: float): +DEFAULT_LOGGER = logging.getLogger("TwoTone.utilities") + + +def extract_scenes(video_path, output_dir, format: str, scale: float, logger: logging.Logger | None = None): + logger = logger or DEFAULT_LOGGER """ Extracts all video frames, names them based on their timestamp, and groups them into scene subdirectories. @@ -23,7 +27,7 @@ def extract_scenes(video_path, output_dir, format: str, scale: float): os.makedirs(output_dir, exist_ok=True) # Get scene change timestamps - scene_changes = [float(sc) for sc in video_utils.detect_scene_changes(video_path)] + scene_changes = [float(sc) for sc in video_utils.detect_scene_changes(video_path, logger=logger)] scene_changes.append(math.inf) # Extract all frames while capturing PTS times @@ -41,7 +45,7 @@ def extract_scenes(video_path, output_dir, format: str, scale: float): output_pattern ] - result = process_utils.start_process("ffmpeg", args = args) + result = process_utils.start_process("ffmpeg", args = args, logger=logger) # Parse PTS times from stderr frame_pts_map = {} # Maps sequential frame numbers to PTS timestamps @@ -82,7 +86,7 @@ def extract_scenes(video_path, output_dir, format: str, scale: float): # Rename and move the file in one step os.rename(old_path, new_path) else: - logging.warning(f"Frame {frame_number} ({frame_file}) not found in PTS map, skipping") + logger.warning(f"Frame {frame_number} ({frame_file}) not found in PTS map, skipping") # Cleanup temp folder os.rmdir(temp_folder) @@ -159,4 +163,5 @@ def perform(self, args, logger: logging.Logger, working_dir: str, plan: Plan) -> output_dir=plan.output, format=plan.format, scale=float(plan.scale), + logger=logger.getChild("extract_scenes"), ) diff --git a/twotone/tools/utils/generic_utils.py b/twotone/tools/utils/generic_utils.py index a6b538ae..fc1757cf 100644 --- a/twotone/tools/utils/generic_utils.py +++ b/twotone/tools/utils/generic_utils.py @@ -14,6 +14,7 @@ DISABLE_PROGRESSBARS = False +DEFAULT_LOGGER = logging.getLogger("TwoTone.utils.generic_utils") def hide_progressbar() -> bool: @@ -85,18 +86,19 @@ class InterruptibleProcess: process-wide signal handlers — keep at most one live instance. """ - def __init__(self): + def __init__(self, logger: logging.Logger | None = None): + self.logger = logger or DEFAULT_LOGGER self._work = True signal.signal(signal.SIGINT, self.exit_gracefully) signal.signal(signal.SIGTERM, self.exit_gracefully) def exit_gracefully(self, signum, frame): - logging.info(f"Got signal #{signum}. Exiting soon.") + self.logger.info(f"Got signal #{signum}. Exiting soon.") self._work = False def check_for_stop(self): if not self._work: - logging.warning("Exiting now due to received signal.") + self.logger.warning("Exiting now due to received signal.") sys.exit(1) diff --git a/twotone/tools/utils/process_utils.py b/twotone/tools/utils/process_utils.py index ac4df8e8..c9601e1b 100644 --- a/twotone/tools/utils/process_utils.py +++ b/twotone/tools/utils/process_utils.py @@ -12,6 +12,8 @@ from . import generic_utils from . import video_utils +DEFAULT_LOGGER = logging.getLogger("TwoTone.utils.process_utils") + DEFAULT_TOOL_OPTIONS: dict[str, list[str]] = { "ffmpeg": ["-hide_banner"], "ffprobe": ["-hide_banner"], @@ -26,7 +28,13 @@ class ProcessResult: stderr: str -def start_process(process: str, args: list[str], show_progress = False) -> ProcessResult: +def start_process( + process: str, + args: list[str], + show_progress: bool = False, + logger: logging.Logger | None = None, +) -> ProcessResult: + logger = logger or DEFAULT_LOGGER defaults = DEFAULT_TOOL_OPTIONS.get(process, []) for opt in reversed(defaults): if opt not in args: @@ -36,7 +44,7 @@ def start_process(process: str, args: list[str], show_progress = False) -> Proce command.extend(args) full_cmd = f"{process} {' '.join(args)}" - logging.debug(f"Starting {full_cmd}") + logger.debug(f"Starting {full_cmd}") popen_kwargs: dict[str, Any] = { "stdout": subprocess.PIPE, "stderr": subprocess.PIPE, @@ -60,7 +68,7 @@ def start_process(process: str, args: list[str], show_progress = False) -> Proce if video_utils.is_video(input_file) and sub_process.stderr: progress_pattern = re.compile(r"frame= *(\d+)") - frames = video_utils.get_video_frames_count(input_file) + frames = video_utils.get_video_frames_count(input_file, logger=logger) with tqdm(desc="Processing video", unit="frame", total=frames, **generic_utils.get_tqdm_defaults()) as pbar: last_frame = 0 for line in sub_process.stderr: @@ -87,7 +95,7 @@ def start_process(process: str, args: list[str], show_progress = False) -> Proce stdout, stderr = sub_process.communicate() - logging.debug(f"Process finished with {sub_process.returncode}") + logger.debug(f"Process finished with {sub_process.returncode}") return ProcessResult(sub_process.returncode, str(stdout), str(stderr)) diff --git a/twotone/tools/utils/subtitles_utils.py b/twotone/tools/utils/subtitles_utils.py index 0a3e52b6..aa7c356f 100644 --- a/twotone/tools/utils/subtitles_utils.py +++ b/twotone/tools/utils/subtitles_utils.py @@ -85,6 +85,8 @@ class SubtitleFile(SubtitleCommonData): "whisper_jax", } +DEFAULT_LOGGER = logging.getLogger("TwoTone.utils.subtitles_utils") + def subtitle_format_from_extension(path: str) -> str | None: ext = Path(path).suffix.lower() @@ -111,7 +113,12 @@ def file_encoding(file: str) -> str: return encoding -def open_subtitle_file(file: str, fps: float = ffmpeg_default_fps) -> pysubs2.SSAFile | None: +def open_subtitle_file( + file: str, + fps: float = ffmpeg_default_fps, + logger: logging.Logger | None = None, +) -> pysubs2.SSAFile | None: + logger = logger or DEFAULT_LOGGER try: encoding = file_encoding(file) subs = pysubs2.load(file, encoding = encoding, fps = fps) @@ -119,24 +126,25 @@ def open_subtitle_file(file: str, fps: float = ffmpeg_default_fps) -> pysubs2.SS return subs except Exception as e: - logging.debug(f"Error opening subtitle file {file}: {e}") + logger.debug(f"Error opening subtitle file {file}: {e}") return None -def is_subtitle(file: str) -> bool: - logging.debug(f"Checking file {file} for being subtitle") +def is_subtitle(file: str, logger: logging.Logger | None = None) -> bool: + logger = logger or DEFAULT_LOGGER + logger.debug(f"Checking file {file} for being subtitle") path_obj = Path(file) suffix = path_obj.suffix.lower() if suffix not in SUBTITLE_EXTENSIONS: - logging.debug("\tNot a subtitle file") + logger.debug("\tNot a subtitle file") return False if suffix == ".sub" and _vobsub_idx_exists(path_obj): - logging.debug("\tDetected VobSub pair, skipping .sub file") + logger.debug("\tDetected VobSub pair, skipping .sub file") return False if suffix == ".idx" and _vobsub_sub_exists(path_obj): - logging.debug("\tDetected VobSub pair, accepting .idx file") + logger.debug("\tDetected VobSub pair, accepting .idx file") return True from . import process_utils @@ -144,22 +152,23 @@ def is_subtitle(file: str) -> bool: status = process_utils.start_process( "ffprobe", ["-v", "error", "-show_entries", "format=format_name", "-of", "default=nw=1:nk=1", file], + logger=logger, ) if status.returncode == 0: formats = {fmt.strip().lower() for fmt in status.stdout.split(",") if fmt.strip()} if formats & FFPROBE_SUBTITLE_FORMATS: - logging.debug("\tSubtitle format detected") + logger.debug("\tSubtitle format detected") return True if suffix in NON_AMBIGUOUS_SUBTITLE_EXTENSIONS: - logging.debug("\tAssuming subtitle based on extension") + logger.debug("\tAssuming subtitle based on extension") return True else: if suffix in FALLBACK_SUBTITLE_EXTENSIONS: - logging.debug("\tAssuming subtitle based on extension (ffprobe failed)") + logger.debug("\tAssuming subtitle based on extension (ffprobe failed)") return True - logging.debug("\tNot a subtitle file") + logger.debug("\tNot a subtitle file") return False @@ -190,17 +199,18 @@ def _strip_microdvd_header(subs: pysubs2.SSAFile | None, fps: float | None = Non del subs[0] -def is_subtitle_microdvd(subtitle: SubtitleFile) -> bool: +def is_subtitle_microdvd(subtitle: SubtitleFile, logger: logging.Logger | None = None) -> bool: assert subtitle.path - subs = open_subtitle_file(subtitle.path) + subs = open_subtitle_file(subtitle.path, logger=logger) if subs and subs.format and subs.format.lower() == "microdvd": return True else: return False -def guess_subtitle_language(path: str, encoding: str) -> str: +def guess_subtitle_language(path: str, encoding: str, logger: logging.Logger | None = None) -> str: + logger = logger or DEFAULT_LOGGER result = "" if not encoding: @@ -230,20 +240,24 @@ def guess_subtitle_language(path: str, encoding: str) -> str: try: result = langid.classify(content)[0] except Exception as e: - logging.debug(f"Language detection failed for {path}: {e}") + logger.debug(f"Language detection failed for {path}: {e}") result = "" return result -def build_subtitle_from_path(path: str, language: str | None = "") -> SubtitleFile: +def build_subtitle_from_path( + path: str, + language: str | None = "", + logger: logging.Logger | None = None, +) -> SubtitleFile: """ if language == None - use autodetection. Empty string - no language 2/3 letter language code - use that language """ encoding = file_encoding(path) - language = guess_subtitle_language(path, encoding) if language is None else language + language = guess_subtitle_language(path, encoding, logger=logger) if language is None else language return SubtitleFile(path = path, language = language, encoding = encoding) diff --git a/twotone/tools/utils/tmdb_cache.py b/twotone/tools/utils/tmdb_cache.py index 065f9ade..48ca5173 100644 --- a/twotone/tools/utils/tmdb_cache.py +++ b/twotone/tools/utils/tmdb_cache.py @@ -10,6 +10,9 @@ from . import generic_utils +DEFAULT_LOGGER = logging.getLogger("TwoTone.utils.tmdb_cache") + + class TmdbCache: """Disk backed cache for TMDB metadata. @@ -24,7 +27,7 @@ def __init__( cache_filename: str = "tmdb_cache.json", logger: logging.Logger | None = None, ) -> None: - self._logger = logger or logging.getLogger(__name__) + self._logger = logger or DEFAULT_LOGGER cache_dir = generic_utils.get_twotone_config_dir() os.makedirs(cache_dir, exist_ok=True) self._cache_path = os.path.join(cache_dir, cache_filename) diff --git a/twotone/tools/utils/video_utils.py b/twotone/tools/utils/video_utils.py index 6f3ca95d..4d655666 100644 --- a/twotone/tools/utils/video_utils.py +++ b/twotone/tools/utils/video_utils.py @@ -15,11 +15,14 @@ from .generic_utils import InterruptibleProcess, fps_str_to_float, get_tqdm_defaults, time_to_ms from .subtitles_utils import SubtitleFile +DEFAULT_LOGGER = logging.getLogger("TwoTone.utils.video_utils") + def _start_ffmpeg_streaming( args: list[str], interruption: InterruptibleProcess | None = None, on_line: "Callable[[str], None] | None" = None, + logger: logging.Logger | None = None, ) -> tuple[subprocess.Popen, list[str]]: """Start an ffmpeg subprocess and read its stderr line-by-line. @@ -35,8 +38,9 @@ def _start_ffmpeg_streaming( if opt not in full_args: full_args.insert(0, opt) + logger = logger or DEFAULT_LOGGER command = ["ffmpeg"] + full_args - logging.debug(f"Starting ffmpeg {' '.join(full_args)}") + logger.debug(f"Starting ffmpeg {' '.join(full_args)}") popen_kwargs: dict[str, Any] = { "stdout": subprocess.PIPE, @@ -85,14 +89,16 @@ def is_video(file: str) -> bool: return Path(file).suffix[1:].lower() in ["mkv", "mp4", "avi", "mpg", "mpeg", "mov", "rmvb"] -def get_video_frames_count(video_file: str): +def get_video_frames_count(video_file: str, logger: logging.Logger | None = None): + logger = logger or DEFAULT_LOGGER result = process_utils.start_process("ffprobe", ["-v", "error", "-select_streams", "v:0", "-count_packets", - "-show_entries", "stream=nb_read_packets", "-of", "csv=p=0", video_file]) + "-show_entries", "stream=nb_read_packets", "-of", "csv=p=0", video_file], + logger=logger) try: return int(result.stdout.strip()) except ValueError: - logging.error(f"Failed to get frame count for {video_file}") + logger.error(f"Failed to get frame count for {video_file}") return None @@ -111,6 +117,7 @@ def detect_scene_changes( When *logger* is given (and no *desc*), an info message is emitted. When *interruption* is given, ctrl+c can cleanly stop the process. """ + logger = logger or DEFAULT_LOGGER args = [ "-i", file_path, @@ -125,7 +132,7 @@ def detect_scene_changes( basename = os.path.basename(file_path) bar_desc = desc or f"Detecting scenes: {basename}" - duration_ms = get_video_duration(file_path) + duration_ms = get_video_duration(file_path, logger=logger) duration_s = (duration_ms / 1000.0) if duration_ms else None pts_time_re = re.compile(r"pts_time:(\d+\.?\d*)") @@ -147,13 +154,13 @@ def _on_line(line: str) -> None: pbar.update(delta) last_time = t - proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line) + proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line, logger=logger) if duration_s and last_time < duration_s: pbar.update(duration_s - last_time) pbar.close() if proc.returncode != 0: - logging.warning(f"ffmpeg scene detection exited with code {proc.returncode}") + logger.warning(f"ffmpeg scene detection exited with code {proc.returncode}") # Look for lines with "pts_time:"; these indicate the timestamp of a scene change. scene_times = [] @@ -165,13 +172,12 @@ def _on_line(line: str) -> None: time_ms = int(round(time_s * 1000)) scene_times.append(time_ms) - if logger: - logger.debug(f"Detected {len(scene_times)} scene changes in {basename}") + logger.debug(f"Detected {len(scene_times)} scene changes in {basename}") return sorted(set(scene_times)) -def extract_timestamp_frame_mapping(video_path: str) -> dict[int, int]: +def extract_timestamp_frame_mapping(video_path: str, logger: logging.Logger | None = None) -> dict[int, int]: """ Extracts a mapping of timestamp (seconds) to frame number from a video. @@ -182,6 +188,7 @@ def extract_timestamp_frame_mapping(video_path: str) -> dict[int, int]: dict: A dictionary mapping {timestamp in ms (int): frame number (int)} """ + logger = logger or DEFAULT_LOGGER args = [ "-v", "error", "-select_streams", "v:0", @@ -191,7 +198,7 @@ def extract_timestamp_frame_mapping(video_path: str) -> dict[int, int]: ] # Run the command - result = process_utils.start_process("ffprobe", args) + result = process_utils.start_process("ffprobe", args, logger=logger) # Parse output timestamp_frame_map = {} @@ -229,6 +236,8 @@ def extract_all_frames( When *logger* is given, an info message is emitted. When *interruption* is given, ctrl+c can cleanly stop the process. """ + provided_logger = logger + logger = logger or DEFAULT_LOGGER # Clear target directory def clean_target_dir(): @@ -271,7 +280,7 @@ def build_args(extra_args: list[str]) -> list[str]: bar_desc = desc or f"Extracting frames: {basename}" # Get total frame count for a real progress bar - total_frames = get_video_frames_count(video_path) + total_frames = get_video_frames_count(video_path, logger=logger) fallback_options: list[list[str]] = [ ["-fps_mode", "vfr"], @@ -303,7 +312,7 @@ def _on_line(line: str) -> None: showinfo_entries.append((frame_number, timestamp_ms)) pbar.update(1) - proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line) + proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line, logger=logger) pbar.close() last_stderr = stderr_lines @@ -321,7 +330,7 @@ def _on_line(line: str) -> None: # Handle count mismatch gracefully — use the smaller count usable = min(len(showinfo_entries), len(frame_files)) if len(showinfo_entries) != len(frame_files): - logging.warning( + logger.warning( f"Frame count mismatch for {basename}: showinfo reported {len(showinfo_entries)} " f"frames but {len(frame_files)} files on disk. Using {usable}." ) @@ -335,7 +344,7 @@ def _on_line(line: str) -> None: "frame_id": frame_number, } - if logger: + if provided_logger: logger.info(f"Extracted {len(mapping)} frames from {basename}") return mapping @@ -345,6 +354,7 @@ def probe_frame_timestamps( video_path: str, interruption: InterruptibleProcess | None = None, desc: str | None = None, + logger: logging.Logger | None = None, ) -> dict[int, dict]: """Probe all frame timestamps without writing image files. @@ -353,6 +363,7 @@ def probe_frame_timestamps( output so that frame numbering (``n:``) is guaranteed to match the ``n`` variable used by ffmpeg's ``select`` filter. """ + logger = logger or DEFAULT_LOGGER args = [ "-i", video_path, "-map", "0:v:0", @@ -364,7 +375,7 @@ def probe_frame_timestamps( basename = os.path.basename(video_path) bar_desc = desc or f"Probing frames: {basename}" - total_frames = get_video_frames_count(video_path) + total_frames = get_video_frames_count(video_path, logger=logger) frame_pattern = re.compile(r"n: *(\d+).*pts_time:([\d.]+)") entries: list[tuple[int, int]] = [] @@ -384,7 +395,7 @@ def _on_line(line: str) -> None: entries.append((frame_number, timestamp_ms)) pbar.update(1) - proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line) + proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line, logger=logger) pbar.close() if proc.returncode != 0: @@ -430,6 +441,7 @@ def extract_frames_at_ranges( scale: float | tuple[int, int] = 0.5, interruption: InterruptibleProcess | None = None, desc: str | None = None, + logger: logging.Logger | None = None, ) -> None: """Extract frames from specific frame-number ranges and update *probed_metadata* paths. @@ -449,6 +461,7 @@ def extract_frames_at_ranges( if not frame_ranges: return + logger = logger or DEFAULT_LOGGER select_expr = _balanced_select_expr(frame_ranges) scale_filter = "" @@ -516,7 +529,7 @@ def _clean_target_dir(): output_pattern, ] - proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line) + proc, stderr_lines = _start_ffmpeg_streaming(args, interruption, on_line=_on_line, logger=logger) last_stderr = stderr_lines if proc.returncode == 0: @@ -535,7 +548,7 @@ def _clean_target_dir(): usable = min(len(showinfo_entries), len(frame_files)) if len(showinfo_entries) != len(frame_files): - logging.warning( + logger.warning( f"Frame count mismatch for {basename}: showinfo reported " f"{len(showinfo_entries)} frames but {len(frame_files)} files " f"on disk. Using {usable}." @@ -547,24 +560,26 @@ def _clean_target_dir(): if timestamp_ms in probed_metadata: probed_metadata[timestamp_ms]["path"] = os.path.join(target_dir, fname) else: - logging.warning( + logger.warning( f"Extracted frame at {timestamp_ms}ms has no matching " f"entry in probed metadata — skipping." ) -def get_video_duration(video_file): +def get_video_duration(video_file, logger: logging.Logger | None = None): """Get the duration of a video in milliseconds.""" - result = process_utils.start_process("ffprobe", ["-v", "error", "-show_entries", "format=duration", "-of", "default=noprint_wrappers=1:nokey=1", video_file]) + logger = logger or DEFAULT_LOGGER + result = process_utils.start_process("ffprobe", ["-v", "error", "-show_entries", "format=duration", "-of", "default=noprint_wrappers=1:nokey=1", video_file], logger=logger) try: return int(float(result.stdout.strip())*1000) except ValueError: - logging.error(f"Failed to get duration for {video_file}") + logger.error(f"Failed to get duration for {video_file}") return None -def get_video_full_info(path: str) -> dict: +def get_video_full_info(path: str, logger: logging.Logger | None = None) -> dict: + logger = logger or DEFAULT_LOGGER args = [] args.extend(["-v", "quiet"]) args.extend(["-print_format", "json"]) @@ -572,7 +587,7 @@ def get_video_full_info(path: str) -> dict: args.append("-show_streams") args.append(path) - result = process_utils.start_process("ffprobe", args) + result = process_utils.start_process("ffprobe", args, logger=logger) if result.returncode != 0: raise RuntimeError(f"ffprobe exited with unexpected error:\n{result.stderr}") @@ -583,7 +598,8 @@ def get_video_full_info(path: str) -> dict: return output_json -def get_video_data(path: str) -> dict: +def get_video_data(path: str, logger: logging.Logger | None = None) -> dict: + logger = logger or DEFAULT_LOGGER def get_length(stream) -> int | None: """Return stream length in milliseconds if available.""" @@ -617,7 +633,7 @@ def get_language(stream) -> str | None: return language - output_json = get_video_full_info(path) + output_json = get_video_full_info(path, logger=logger) streams = defaultdict(list) for stream in output_json["streams"]: @@ -650,7 +666,7 @@ def get_language(stream) -> str | None: fps = stream["r_frame_rate"] length = get_length(stream) if length is None: - length = get_video_duration(path) + length = get_video_duration(path, logger=logger) width = stream["width"] height = stream["height"] @@ -681,10 +697,11 @@ def get_language(stream) -> str | None: return dict(streams) -def get_video_full_info_mkvmerge(path: str) -> dict: +def get_video_full_info_mkvmerge(path: str, logger: logging.Logger | None = None) -> dict: """Return file information using ``mkvmerge -J``.""" - result = process_utils.start_process("mkvmerge", ["-J", path]) + logger = logger or DEFAULT_LOGGER + result = process_utils.start_process("mkvmerge", ["-J", path], logger=logger) if result.returncode != 0: raise RuntimeError(f"mkvmerge exited with unexpected error:\n{result.stderr}") @@ -692,12 +709,17 @@ def get_video_full_info_mkvmerge(path: str) -> dict: return json.loads(result.stdout) -def get_video_data_mkvmerge(path: str, enrich: bool = False) -> dict: +def get_video_data_mkvmerge( + path: str, + enrich: bool = False, + logger: logging.Logger | None = None, +) -> dict: """ Return stream information parsed from ``mkvmerge -J`` output. For non mkv files, mkvmerge does not provide as much information as ffprobe. Set 'enrich' to True to enrich mkvmerge's outpput with data from ffprobe. """ + logger = logger or DEFAULT_LOGGER def find_ffprobe_track(track_id: int, ffprobe_info: dict | None) -> dict: for streams in (ffprobe_info or {}).values(): @@ -722,16 +744,16 @@ def merge_properties(initial: dict | None, update: dict) -> dict: elif value != base_value: if key != "codec" and key != "format": if key == "fps" and abs(fps_str_to_float(base_value) - fps_str_to_float(value)) > 0.001: - logging.warning(f"Inconsistent data provided by mkvmerge ({key}: {value}) and ffprobe ({key}: {base_value})") + logger.warning(f"Inconsistent data provided by mkvmerge ({key}: {value}) and ffprobe ({key}: {base_value})") output[key] = value return output - info = get_video_full_info_mkvmerge(path) + info = get_video_full_info_mkvmerge(path, logger=logger) # process streams/tracks streams = defaultdict(list) - ffprobe_info = get_video_data(path) if enrich else None + ffprobe_info = get_video_data(path, logger=logger) if enrich else None for track in info.get("tracks", []): track_type = track.get("type") @@ -886,9 +908,9 @@ def extract_subtitle_to_temp(video_path: str, tids: list[int], output_base_path: - Returns a mapping {tid: output_path} for all requested tids. """ + logger = logger or DEFAULT_LOGGER tids_list: list[int] = list(tids) - if logger: - logger.debug("Extracting subtitles from %s (tids=%s)", video_path, ",".join(str(t) for t in tids_list)) + logger.debug("Extracting subtitles from %s (tids=%s)", video_path, ",".join(str(t) for t in tids_list)) # Map formats to file extensions ext_map = { @@ -904,12 +926,11 @@ def extract_subtitle_to_temp(video_path: str, tids: list[int], output_base_path: # Discover formats using video_utils try: - info = get_video_data(video_path) + info = get_video_data(video_path, logger=logger) stream_fmt = {s.get("tid"): (s.get("format") or "").lower() for s in info.get("subtitle", [])} except Exception as e: stream_fmt = {} - if logger: - logger.debug(f"Failed to get stream info for '{video_path}': {e}") + logger.debug(f"Failed to get stream info for '{video_path}': {e}") # Build mkvextract options tid_to_path: dict[int, str] = {} @@ -920,37 +941,41 @@ def extract_subtitle_to_temp(video_path: str, tids: list[int], output_base_path: out_path = f"{output_base_path}.{tid}{suffix}" tid_to_path[tid] = out_path options.append(f"{tid}:{out_path}") - if logger: - logger.debug(" tid #%s -> %s (format=%s)", tid, out_path, fmt or "unknown") + logger.debug(" tid #%s -> %s (format=%s)", tid, out_path, fmt or "unknown") try: start = time.perf_counter() - status = process_utils.start_process("mkvextract", options) + status = process_utils.start_process("mkvextract", options, logger=logger) elapsed = time.perf_counter() - start - if logger: - logger.debug("mkvextract finished in %.3fs (rc=%s)", elapsed, status.returncode) - if status.returncode != 0 and logger: + logger.debug("mkvextract finished in %.3fs (rc=%s)", elapsed, status.returncode) + if status.returncode != 0: logger.error(f"mkvextract failed for {video_path}: {status.stderr}") except Exception as e: - if logger: - logger.error(f"Subtitle extraction failed for {video_path}: {e}") - - if logger: - for tid, out_path in tid_to_path.items(): - if os.path.exists(out_path): - try: - size = os.path.getsize(out_path) - except OSError: - size = -1 - logger.debug(" extracted tid #%s -> %s (%s bytes)", tid, out_path, size) - else: - logger.debug(" missing output for tid #%s -> %s", tid, out_path) + logger.error(f"Subtitle extraction failed for {video_path}: {e}") + + for tid, out_path in tid_to_path.items(): + if os.path.exists(out_path): + try: + size = os.path.getsize(out_path) + except OSError: + size = -1 + logger.debug(" extracted tid #%s -> %s (%s bytes)", tid, out_path, size) + else: + logger.debug(" missing output for tid #%s -> %s", tid, out_path) return tid_to_path -def generate_mkv(output_path: str, input_video: str, subtitles: list[SubtitleFile] | dict | None = None, audios: list[dict] | None = None, thumbnail: str | None = None): +def generate_mkv( + output_path: str, + input_video: str, + subtitles: list[SubtitleFile] | dict | None = None, + audios: list[dict] | None = None, + thumbnail: str | None = None, + logger: logging.Logger | None = None, +): + logger = logger or DEFAULT_LOGGER # RMVB/RM files cannot be reliably converted to MKV due to RealAudio "cook" codec issues. # mkvmerge produces broken files with audio sync problems. # See: https://gitlab.com/mbunkus/mkvtoolnix/-/issues/708 @@ -1008,19 +1033,19 @@ def generate_mkv(output_path: str, input_video: str, subtitles: list[SubtitleFil options.extend(["--attach-file", thumbnail]) cmd = "mkvmerge" - result = process_utils.start_process(cmd, options) + result = process_utils.start_process(cmd, options, logger=logger) # validate result and output file # mkvmerge returns: 0 = success, 1 = success with warnings, 2 = error if result.returncode == 1: warnings = (result.stdout or "") + (result.stderr or "") if warnings.strip(): - logging.warning(f"{cmd} completed with warnings: {warnings.strip()}") + logger.warning(f"{cmd} completed with warnings: {warnings.strip()}") elif result.returncode > 1: if os.path.exists(output_path): os.remove(output_path) raise RuntimeError(f"{cmd} exited with unexpected error:\n{result.stderr}\n\nAnd output: {result.stdout}") if not os.path.exists(output_path): - logging.error("Output file was not created") + logger.error("Output file was not created") raise RuntimeError(f"{cmd} did not create output file") diff --git a/twotone/twotone.py b/twotone/twotone.py index 10841ac0..93cf8e43 100644 --- a/twotone/twotone.py +++ b/twotone/twotone.py @@ -239,7 +239,7 @@ def execute(argv: list[str]) -> None: finally: shutil.rmtree(pid_wd, ignore_errors=True) else: - logging.error(f"Error: Unknown tool {args.tool}") + logger.error(f"Error: Unknown tool {args.tool}") sys.exit(1) @@ -275,7 +275,7 @@ def main() -> None: try: execute(sys.argv[1:]) except RuntimeError as e: - logging.error(f"Error occurred: {e}. Terminating") + logging.getLogger("TwoTone").error(f"Error occurred: {e}. Terminating") except ValueError as e: print(f"error: {e}")