diff --git a/app/tests/test_ytdl_utils.py b/app/tests/test_ytdl_utils.py index b671733..0a71a22 100644 --- a/app/tests/test_ytdl_utils.py +++ b/app/tests/test_ytdl_utils.py @@ -450,6 +450,65 @@ class DownloadLoggerTests(unittest.TestCase): 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): @@ -508,13 +567,72 @@ class DownloadResultTests(unittest.TestCase): self.assertEqual(statuses[-1], {'status': 'finished'}) - def test_youtube_dl_error_message_takes_precedence_over_warnings(self): + 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=['Earlier warning'], - error=ytdl.yt_dlp.utils.YoutubeDLError('extractor failed'), + 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': 'extractor failed'}) + 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): diff --git a/app/ytdl.py b/app/ytdl.py index e086617..851883e 100644 --- a/app/ytdl.py +++ b/app/ytdl.py @@ -33,23 +33,53 @@ 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 = [] + 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()): - self.warnings.append(warning) + 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 @@ -683,10 +713,12 @@ 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() - ytdl_logger = _DownloadYtdlLogger() def put_status_postprocessor(d): if d['postprocessor'] == 'MoveFiles' and d['status'] == 'finished': @@ -730,6 +762,8 @@ 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 @@ -761,7 +795,7 @@ class Download: 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}")