Merge PR #1056: surface yt-dlp warning context on failed downloads

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()

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}")