diff --git a/app/tests/test_ytdl_utils.py b/app/tests/test_ytdl_utils.py index 858a2aa..0a71a22 100644 --- a/app/tests/test_ytdl_utils.py +++ b/app/tests/test_ytdl_utils.py @@ -50,6 +50,7 @@ class _YoutubeDL: fake_utils.DownloadError = type("DownloadError", (Exception,), {}) +fake_utils.YoutubeDLError = fake_utils.DownloadError fake_yt_dlp.YoutubeDL = _YoutubeDL fake_impersonate.ImpersonateTarget = _ImpersonateTarget fake_networking.impersonate = fake_impersonate @@ -434,6 +435,206 @@ def _make_test_download() -> Download: return Download("/tmp", "/tmp", "%(title)s.%(ext)s", "%(title)s.%(ext)s", "best", "any", {}, info) +class DownloadLoggerTests(unittest.TestCase): + def test_routes_messages_and_retains_only_non_empty_warnings(self): + logger = ytdl._DownloadYtdlLogger() + + with self.assertLogs('ytdl', level='DEBUG') as logs: + logger.debug('debug detail') + logger.warning(' useful warning ') + logger.warning(' ') + logger.error('error detail') + + self.assertEqual(logger.warnings, ['useful warning']) + self.assertIn('DEBUG:ytdl:debug detail', logs.output) + self.assertIn('WARNING:ytdl: useful warning ', logs.output) + self.assertIn('ERROR:ytdl:error detail', logs.output) + + def test_retains_only_the_last_distinct_warnings(self): + logger = ytdl._DownloadYtdlLogger() + cap = ytdl._MAX_RETAINED_WARNINGS + + with self.assertLogs('ytdl', level='WARNING') as logs: + for index in range(cap + 3): + logger.warning(f'fragment {index} not found') + + self.assertEqual( + logger.warnings, + [f'fragment {index} not found' for index in range(3, cap + 3)], + ) + # Every warning still reaches the log; only the retained list is bounded. + self.assertEqual(len(logs.output), cap + 3) + + def test_repeated_warning_is_retained_once(self): + logger = ytdl._DownloadYtdlLogger() + + with self.assertLogs('ytdl', level='WARNING'): + logger.warning('Requested format is not available') + logger.warning('Only images are available for download') + logger.warning('Requested format is not available') + + self.assertEqual( + logger.warnings, + ['Requested format is not available', 'Only images are available for download'], + ) + + def test_failure_message_puts_the_error_last(self): + logger = ytdl._DownloadYtdlLogger() + + with self.assertLogs('ytdl', level='WARNING'): + logger.warning('Only images are available for download') + + self.assertEqual( + logger.failure_message('ERROR: [youtube] u2HSc2Ym1Vk: No video formats found!'), + 'Only images are available for download\n' + 'ERROR: [youtube] u2HSc2Ym1Vk: No video formats found!', + ) + + def test_failure_message_skips_a_last_warning_that_repeats_the_error(self): + logger = ytdl._DownloadYtdlLogger() + + with self.assertLogs('ytdl', level='WARNING'): + logger.warning('Video unavailable') + # yt-dlp labels errors but hands warnings to the logger unlabelled, + # so the same text can arrive through both routes. + logger.warning('Requested format is not available') + + self.assertEqual( + logger.failure_message('ERROR: Requested format is not available'), + 'Video unavailable\nERROR: Requested format is not available', + ) + + def test_failure_message_without_warnings_is_the_error_alone(self): + logger = ytdl._DownloadYtdlLogger() + + self.assertEqual(logger.failure_message('ERROR: boom'), 'ERROR: boom') + + +class DownloadResultTests(unittest.TestCase): + def _run_download(self, result=0, warnings=(), error=None): + download = _make_test_download() + statuses = [] + download.status_queue = types.SimpleNamespace(put=statuses.append) + captured_params = {} + + class FakeYoutubeDL: + def download(self, urls): + self.urls = urls + for warning in warnings: + captured_params['logger'].warning(warning) + if error is not None: + raise error + return result + + def make_youtube_dl(params): + captured_params.update(params) + return FakeYoutubeDL() + + with patch.object(download, '_make_youtube_dl', side_effect=make_youtube_dl), \ + patch('ytdl.install_socket_guard'), \ + patch('ytdl.os.setpgrp'): + download._download() + + return statuses, captured_params + + def test_nonzero_result_includes_warning_context_and_forwards_logs(self): + warnings = [ + 'The uploader has blocked this video in your country', + 'No video formats found', + ] + + with self.assertLogs('ytdl', level='WARNING') as logs: + statuses, params = self._run_download(result=1, warnings=warnings) + + self.assertEqual( + statuses[-1], + {'status': 'error', 'msg': '\n'.join(warnings)}, + ) + self.assertIs(params['logger'].__class__, ytdl._DownloadYtdlLogger) + for warning in warnings: + self.assertTrue(any(warning in entry for entry in logs.output)) + + def test_nonzero_result_without_warning_uses_fallback_message(self): + statuses, _ = self._run_download(result=2) + + self.assertEqual( + statuses[-1], + {'status': 'error', 'msg': 'yt-dlp failed with exit code 2'}, + ) + + def test_warning_does_not_change_success_status(self): + statuses, _ = self._run_download(result=0, warnings=['A recoverable warning']) + + self.assertEqual(statuses[-1], {'status': 'finished'}) + + def test_youtube_dl_error_carries_the_warnings_that_explain_it(self): + # The sequence from issue #1047: yt-dlp raises DownloadError, so the + # warnings naming the real cause only reach the user if the exception + # branch carries them too. + statuses, _ = self._run_download( + warnings=[ + '[youtube] Video unavailable. This video contains content from bryhuangpub,' + ' who has blocked it from display on this website or application', + 'Only images are available for download. use --list-formats to see them', + 'Requested format is not available', + ], + error=ytdl.yt_dlp.utils.YoutubeDLError( + 'ERROR: [youtube] u2HSc2Ym1Vk: No video formats found!' + ), + ) + + self.assertEqual( + statuses[-1], + { + 'status': 'error', + 'msg': '[youtube] Video unavailable. This video contains content from bryhuangpub,' + ' who has blocked it from display on this website or application\n' + 'Only images are available for download. use --list-formats to see them\n' + 'Requested format is not available\n' + 'ERROR: [youtube] u2HSc2Ym1Vk: No video formats found!', + }, + ) + + def test_youtube_dl_error_drops_a_last_warning_that_repeats_it(self): + statuses, _ = self._run_download( + warnings=['Earlier warning', 'Requested format is not available'], + error=ytdl.yt_dlp.utils.YoutubeDLError('ERROR: Requested format is not available'), + ) + + self.assertEqual( + statuses[-1], + { + 'status': 'error', + 'msg': 'Earlier warning\nERROR: Requested format is not available', + }, + ) + + def test_youtube_dl_error_message_is_bounded(self): + cap = ytdl._MAX_RETAINED_WARNINGS + statuses, _ = self._run_download( + warnings=[f'fragment {index} not found' for index in range(cap + 4)], + error=ytdl.yt_dlp.utils.YoutubeDLError('ERROR: giving up'), + ) + + msg = statuses[-1]['msg'] + self.assertEqual( + msg.split('\n'), + [f'fragment {index} not found' for index in range(4, cap + 4)] + ['ERROR: giving up'], + ) + + def test_nonzero_result_message_is_bounded(self): + cap = ytdl._MAX_RETAINED_WARNINGS + statuses, _ = self._run_download( + result=1, + warnings=[f'fragment {index} not found' for index in range(cap + 4)], + ) + + self.assertEqual( + statuses[-1]['msg'].split('\n'), + [f'fragment {index} not found' for index in range(4, cap + 4)], + ) + + class ProgressThrottleTests(unittest.TestCase): def test_downloading_ticks_are_throttled(self): dl = _make_test_download() diff --git a/app/ytdl.py b/app/ytdl.py index a33b94f..060152a 100644 --- a/app/ytdl.py +++ b/app/ytdl.py @@ -32,6 +32,55 @@ from urllib.parse import urlsplit log = logging.getLogger('ytdl') + +# Fragmented and live downloads can emit a warning per fragment, and the joined +# text is persisted with the completed queue and broadcast to every client, so +# only the last few distinct warnings are kept. +_MAX_RETAINED_WARNINGS = 5 + +_REPORT_LABEL_RE = re.compile(r'^(?:ERROR|WARNING):\s*') + + +def _report_body(message): + """yt-dlp labels errors with an ``ERROR:`` prefix but hands warnings to the + logger unlabelled, so compare the two with any such label removed.""" + return _REPORT_LABEL_RE.sub('', message).strip() + + +class _DownloadYtdlLogger: + """Forward yt-dlp output while retaining warnings for failed downloads.""" + + def __init__(self): + self._warnings = collections.deque(maxlen=_MAX_RETAINED_WARNINGS) + + @property + def warnings(self): + return list(self._warnings) + + def debug(self, msg): + log.debug('%s', msg) + + def warning(self, msg): + log.warning('%s', msg) + if msg is not None and (warning := str(msg).strip()) and warning not in self._warnings: + self._warnings.append(warning) + + def error(self, msg): + log.error('%s', msg) + + def failure_message(self, error_text): + """Retained warnings followed by *error_text*, kept last so the actual + error stays prominent under the context that explains it.""" + lines = self.warnings + error_text = (error_text or '').strip() + if not error_text: + return '\n'.join(lines) + if lines and _report_body(lines[-1]) == _report_body(error_text): + lines.pop() + lines.append(error_text) + return '\n'.join(lines) + + # Python 3.14 switches the default multiprocessing start method on Linux # (this app's only supported deployment target, per the Dockerfile) from fork # to forkserver. Download._download relies on inheriting process state the @@ -664,6 +713,9 @@ class Download: # anything else. Skipped when ALLOW_PRIVATE_ADDRESSES trusts the environment. install_socket_guard(self.allow_private, proxy_urls=(self.ytdl_opts.get('proxy'),)) log.info(f"Starting download for: {self.info.title} ({self.info.url})") + # Bound outside the try so the except branch can read what was captured + # before the error was raised. + ytdl_logger = _DownloadYtdlLogger() try: debug_logging = logging.getLogger().isEnabledFor(logging.DEBUG) put_status = self._make_progress_hook() @@ -710,6 +762,9 @@ class Download: 'postprocessor_hooks': [put_status_postprocessor], **self.ytdl_opts, } + # Set after the ytdl_opts merge: the failure messages below depend on + # this logger, so a user-supplied one must not replace it. + ytdl_params['logger'] = ytdl_logger # Add chapter splitting options if enabled if self.info.split_by_chapters: @@ -732,11 +787,15 @@ class Download: ) ret = self._make_youtube_dl(ytdl_params).download([self.info.url]) - self.status_queue.put({'status': 'finished' if ret == 0 else 'error'}) + if ret == 0: + self.status_queue.put({'status': 'finished'}) + else: + msg = '\n'.join(ytdl_logger.warnings) or f'yt-dlp failed with exit code {ret}' + self.status_queue.put({'status': 'error', 'msg': msg}) log.info(f"Finished download for: {self.info.title}") except yt_dlp.utils.YoutubeDLError as exc: log.error(f"Download error for {self.info.title}: {str(exc)}") - self.status_queue.put({'status': 'error', 'msg': str(exc)}) + self.status_queue.put({'status': 'error', 'msg': ytdl_logger.failure_message(str(exc))}) async def start(self, notifier, executor=None): log.info(f"Preparing download for: {self.info.title}")