[BACKEND] Improve info logger messages (#129)

src/ytdl_sub/downloaders/downloader.py

@@ -1,4 +1,5 @@
 import abc
+import contextlib
 import json
 import os
 from abc import ABC
@@ -20,13 +21,14 @@ from yt_dlp.utils import RejectedVideoReached
 from ytdl_sub.config.preset_options import Overrides
 from ytdl_sub.entries.base_entry import BaseEntry
 from ytdl_sub.entries.entry import Entry
+from ytdl_sub.thread.log_entries_downloaded_listener import LogEntriesDownloadedListener
 from ytdl_sub.utils.file_handler import FileMetadata
 from ytdl_sub.utils.logger import Logger
 from ytdl_sub.validators.strict_dict_validator import StrictDictValidator
 from ytdl_sub.ytdl_additions.enhanced_download_archive import DownloadArchiver
 from ytdl_sub.ytdl_additions.enhanced_download_archive import EnhancedDownloadArchive
 
-logger = Logger.get(name="downloader")
+download_logger = Logger.get(name="downloader")
 
 
 class DownloaderValidator(StrictDictValidator, ABC):
@@ -167,8 +169,35 @@ class Downloader(DownloadArchiver, Generic[DownloaderOptionsT, DownloaderEntryT]
 
         return entry_dicts
 
+    @contextlib.contextmanager
+    def _listen_and_log_downloaded_info_json(self, log_prefix: Optional[str]):
+        """
+        Context manager that starts a separate thread that listens for new .info.json files,
+        prints their titles as they appear
+        """
+        if not log_prefix:
+            yield
+            return
+
+        info_json_listener = LogEntriesDownloadedListener(
+            working_directory=self.working_directory,
+            info_json_extractor=self.downloader_entry_type.entry_extractor,
+            log_prefix=log_prefix,
+        )
+
+        info_json_listener.start()
+
+        try:
+            yield
+        finally:
+            info_json_listener.complete = True
+
     def extract_info_via_info_json(
-        self, ytdl_options_overrides: Optional[Dict] = None, **kwargs
+        self,
+        ytdl_options_overrides: Optional[Dict] = None,
+        only_info_json: bool = False,
+        log_prefix_on_info_json_dl: Optional[str] = None,
+        **kwargs
     ) -> List[Dict]:
         """
         Wrapper around yt_dlp.YoutubeDL.YoutubeDL.extract_info with infojson enabled. Entry dicts
@@ -182,20 +211,31 @@ class Downloader(DownloadArchiver, Generic[DownloaderOptionsT, DownloaderEntryT]
         ----------
         ytdl_options_overrides
             Optional. Dict containing ytdl args to override other predefined ytdl args
+        only_info_json
+            Default false. Skip download and thumbnail download if True.
+        log_prefix_on_info_json_dl
+            Optional. Spin a new thread to listen for new info.json files. Log
+            f'{log_prefix_on_info_json_dl} {title}' when a new one appears
         **kwargs
             arguments passed directory to YoutubeDL extract_info
         """
         if ytdl_options_overrides is None:
             ytdl_options_overrides = {}
 
-        ytdl_options_overrides = dict(ytdl_options_overrides, **{"writeinfojson": True})
+        extract_info_ytdl_options = {"writeinfojson": True}
+        if only_info_json:
+            extract_info_ytdl_options["skip_download"] = True
+            extract_info_ytdl_options["writethumbnail"] = False
+
+        ytdl_options_overrides = dict(ytdl_options_overrides, **extract_info_ytdl_options)
 
         try:
-            _ = self.extract_info(ytdl_options_overrides=ytdl_options_overrides, **kwargs)
+            with self._listen_and_log_downloaded_info_json(log_prefix=log_prefix_on_info_json_dl):
+                _ = self.extract_info(ytdl_options_overrides=ytdl_options_overrides, **kwargs)
         except RejectedVideoReached:
-            logger.debug("RejectedVideoReached, stopping additional downloads")
+            download_logger.debug("RejectedVideoReached, stopping additional downloads")
         except ExistingVideoReached:
-            logger.debug("ExistingVideoReached, stopping additional downloads")
+            download_logger.debug("ExistingVideoReached, stopping additional downloads")
 
         return self._get_entry_dicts_from_info_json_files()
 

src/ytdl_sub/downloaders/soundcloud/albums_and_singles.py

@@ -2,6 +2,7 @@ from typing import Dict
 from typing import Generator
 from typing import List
 
+from ytdl_sub.downloaders.downloader import download_logger
 from ytdl_sub.downloaders.soundcloud.abc import SoundcloudDownloader
 from ytdl_sub.downloaders.soundcloud.abc import SoundcloudDownloaderOptions
 from ytdl_sub.entries.soundcloud import SoundcloudAlbum
@@ -119,11 +120,9 @@ class SoundcloudAlbumsAndSinglesDownloader(
         # Dry-run to get the info json files
         artist_albums_url = self.artist_albums_url(artist_url=self.download_options.url)
         album_entry_dicts = self.extract_info_via_info_json(
+            only_info_json=True,
+            log_prefix_on_info_json_dl="Downloading metadata for",
             url=artist_albums_url,
-            ytdl_options_overrides={
-                "skip_download": True,
-                "writethumbnail": False,
-            },
         )
 
         albums = self._get_albums_from_entry_dicts(entry_dicts=album_entry_dicts)
@@ -133,10 +132,19 @@ class SoundcloudAlbumsAndSinglesDownloader(
         self, albums: List[SoundcloudAlbum]
     ) -> Generator[SoundcloudAlbumTrack, None, None]:
         for album in albums:
+            if len(album.album_tracks()) > 0:
+                download_logger.info("Downloading album %s", album.title)
+
             for track in album.album_tracks():
                 if self.download_options.skip_premiere_tracks and track.is_premiere():
                     continue
 
+                download_logger.info(
+                    "Downloading album track %d/%d %s",
+                    track.track_number,
+                    track.track_count,
+                    track.title,
+                )
                 if not self.is_dry_run:
                     _ = self.extract_info(
                         url=album.kwargs("webpage_url"),
@@ -153,11 +161,9 @@ class SoundcloudAlbumsAndSinglesDownloader(
     ) -> Generator[SoundcloudTrack, None, None]:
         artist_tracks_url = self.artist_tracks_url(artist_url=self.download_options.url)
         tracks_entry_dicts = self.extract_info_via_info_json(
+            only_info_json=True,
+            log_prefix_on_info_json_dl="Downloading metadata for",
             url=artist_tracks_url,
-            ytdl_options_overrides={
-                "skip_download": True,
-                "writethumbnail": False,
-            },
         )
 
         # Then, get all singles
@@ -167,6 +173,7 @@ class SoundcloudAlbumsAndSinglesDownloader(
             if self.download_options.skip_premiere_tracks and track.is_premiere():
                 continue
 
+            download_logger.info("Downloading single track %s", track.title)
             if not self.is_dry_run:
                 _ = self.extract_info(
                     url=track.kwargs("webpage_url"), ytdl_options_overrides={"writeinfojson": False}

src/ytdl_sub/downloaders/youtube/channel.py

@@ -6,19 +6,17 @@ from typing import Optional
 
 from ytdl_sub.config.preset_options import Overrides
 from ytdl_sub.downloaders.downloader import DownloaderOptionsT
+from ytdl_sub.downloaders.downloader import download_logger
 from ytdl_sub.downloaders.youtube.abc import YoutubeDownloader
 from ytdl_sub.downloaders.youtube.abc import YoutubeDownloaderOptions
 from ytdl_sub.entries.youtube import YoutubeChannel
 from ytdl_sub.entries.youtube import YoutubeVideo
-from ytdl_sub.utils.logger import Logger
 from ytdl_sub.utils.thumbnail import convert_url_thumbnail
 from ytdl_sub.validators.date_range_validator import DateRangeValidator
 from ytdl_sub.validators.string_formatter_validators import OverridesStringFormatterValidator
 from ytdl_sub.validators.url_validator import YoutubeChannelUrlValidator
 from ytdl_sub.ytdl_additions.enhanced_download_archive import EnhancedDownloadArchive
 
-logger = Logger.get()
-
 
 class YoutubeChannelDownloaderOptions(YoutubeDownloaderOptions, DateRangeValidator):
     """
@@ -149,27 +147,30 @@ class YoutubeChannelDownloader(YoutubeDownloader[YoutubeChannelDownloaderOptions
         # dry-run the entire channel download first, this will get the
         # videos that will be downloaded. Afterwards, download each video one-by-one
         entry_dicts = self.extract_info_via_info_json(
-            ytdl_options_overrides=dict(
+            ytdl_options_overrides=ytdl_options_overrides,
-                {"skip_download": True, "write_thumbnail": False}, **ytdl_options_overrides
+            only_info_json=True,
-            ),
+            log_prefix_on_info_json_dl="Downloading metadata for",
             url=self.download_options.channel_url,
         )
         self.channel = self._get_channel_from_entry_dicts(entry_dicts=entry_dicts)
 
-        for entry_dict in entry_dicts:
+        for idx, entry_dict in enumerate(entry_dicts, start=1):
-            if entry_dict.get("extractor") == "youtube":
+            if entry_dict.get("extractor") == self.downloader_entry_type.entry_extractor:
+                video = YoutubeVideo(
+                    entry_dict=entry_dict, working_directory=self.working_directory
+                )
+                download_logger.info("Downloading %d/%d %s", idx, len(entry_dicts), video.title)
+
                 # Only do the individual download if it is not dry-run
-                # TODO: Respect the Reject/Exist exceptions
                 if not self.is_dry_run:
-                    ytdl_options_overrides["playlist_items"] = str(entry_dict.get("playlist_index"))
                     _ = self.extract_info(
                         ytdl_options_overrides={
-                            "playlist_items": str(entry_dict.get("playlist_index")),
+                            "playlist_items": str(video.kwargs("playlist_index")),
                             "writeinfojson": False,
                         },
                         url=self.download_options.channel_url,
                     )
-                yield YoutubeVideo(entry_dict=entry_dict, working_directory=self.working_directory)
+                yield video
 
     def _download_thumbnail(
         self,
@@ -187,7 +188,7 @@ class YoutubeChannelDownloader(YoutubeDownloader[YoutubeChannelDownloaderOptions
             Path to store the thumbnail after downloading
         """
         if not thumbnail_url:
-            logger.warning("Could not find a thumbnail for %s", self.channel.uid)
+            download_logger.warning("Could not find a thumbnail for %s", self.channel.uid)
             return
 
         convert_url_thumbnail(

src/ytdl_sub/downloaders/youtube/playlist.py

@@ -1,6 +1,7 @@
 from typing import Dict
 from typing import Generator
 
+from ytdl_sub.downloaders.downloader import download_logger
 from ytdl_sub.downloaders.youtube.abc import YoutubeDownloader
 from ytdl_sub.downloaders.youtube.abc import YoutubeDownloaderOptions
 from ytdl_sub.entries.youtube import YoutubePlaylistVideo
@@ -75,15 +76,17 @@ class YoutubePlaylistDownloader(
         downloaded. Afterwards, download each video one-by-one
         """
         entry_dicts = self.extract_info_via_info_json(
-            ytdl_options_overrides={
+            only_info_json=True,
-                "skip_download": True,
+            log_prefix_on_info_json_dl="Downloading metadata for",
-                "writethumbnail": False,
-            },
             url=self.download_options.playlist_url,
         )
 
-        for entry_dict in entry_dicts:
+        for idx, entry_dict in enumerate(entry_dicts, start=1):
-            if entry_dict.get("extractor") == "youtube":
+            if entry_dict.get("extractor") == self.downloader_entry_type.entry_extractor:
+                video = YoutubePlaylistVideo(
+                    entry_dict=entry_dict, working_directory=self.working_directory
+                )
+                download_logger.info("Downloading %d/%d %s", idx, len(entry_dicts), video.title)
 
                 # Only do the individual download if it is not dry-run and downloading individually
                 if not self.is_dry_run:
@@ -95,6 +98,4 @@ class YoutubePlaylistDownloader(
                         url=self.download_options.playlist_url,
                     )
 
-                yield YoutubePlaylistVideo(
+                yield video
-                    entry_dict=entry_dict, working_directory=self.working_directory
-                )

src/ytdl_sub/entries/soundcloud.py

@@ -119,7 +119,7 @@ class SoundcloudAlbum(Entry):
             for track in self.tracks
         ]
 
-        return album_tracks
+        return sorted(album_tracks, key=lambda track: track.track_number)
 
     @property
     def album_year(self) -> int:

src/ytdl_sub/subscriptions/subscription.py

@@ -20,7 +20,6 @@ from ytdl_sub.downloaders.downloader import DownloaderValidator
 from ytdl_sub.entries.entry import Entry
 from ytdl_sub.plugins.plugin import Plugin
 from ytdl_sub.plugins.plugin import PluginOptions
-from ytdl_sub.thread.log_entries_downloaded_listener import LogEntriesDownloadedListener
 from ytdl_sub.utils.file_handler import FileHandlerTransactionLog
 from ytdl_sub.utils.file_handler import FileMetadata
 from ytdl_sub.utils.thumbnail import convert_download_thumbnail
@@ -226,30 +225,11 @@ class Subscription:
 
             self._enhanced_download_archive.save_download_mappings()
 
-    @contextlib.contextmanager
-    def _listen_and_log_downloaded_entries(self):
-        """
-        Context manager that starts a separate thread that listens for new .info.json files,
-        prints their titles as they appear
-        """
-        info_json_listener = LogEntriesDownloadedListener(
-            working_directory=self.working_directory,
-            info_json_extractor=self.downloader_class.downloader_entry_type.entry_extractor,
-        )
-
-        info_json_listener.start()
-
-        try:
-            yield
-        finally:
-            info_json_listener.complete = True
-
     @contextlib.contextmanager
     def _subscription_download_context_managers(self) -> None:
         with (
             self._prepare_working_directory(),
             self._maintain_archive_file(),
-            self._listen_and_log_downloaded_entries(),
         ):
             yield
 

src/ytdl_sub/thread/log_entries_downloaded_listener.py

@@ -2,6 +2,7 @@ import json
 import os.path
 import threading
 import time
+from json import JSONDecodeError
 from pathlib import Path
 from typing import Optional
 from typing import Set
@@ -12,7 +13,7 @@ logger = Logger.get(name="downloader")
 
 
 class LogEntriesDownloadedListener(threading.Thread):
-    def __init__(self, working_directory, info_json_extractor):
+    def __init__(self, working_directory: str, info_json_extractor: str, log_prefix: str):
         """
         To be ran in a thread while download via ytdl-sub. Listens for new .info.json files in the
         working directory, checks the extractor value, and if it matches the input arg, log the
@@ -24,17 +25,24 @@ class LogEntriesDownloadedListener(threading.Thread):
             subscription download working directory
         info_json_extractor
             print the titles of the info.json file with this extractor
+        log_prefix
+            The message to print prefixed to the title, i.e. '{log_prefix} {title}'
         """
         threading.Thread.__init__(self)
         self.working_directory = working_directory
         self.info_json_extractor = info_json_extractor
+        self.log_prefix = log_prefix
         self.complete = False
 
         self._files_read: Set[str] = set()
 
     def _get_title_from_info_json(self, path: Path) -> Optional[str]:
-        with open(path, "r", encoding="utf-8") as file:
+        try:
-            file_json = json.load(file)
+            with open(path, "r", encoding="utf-8") as file:
+                file_json = json.load(file)
+        except JSONDecodeError:
+            # swallow the error since this is only printing logs
+            return None
 
         if file_json.get("extractor") == self.info_json_extractor:
             return file_json.get("title")
@@ -57,7 +65,7 @@ class LogEntriesDownloadedListener(threading.Thread):
                 title = self._get_title_from_info_json(path)
                 self._files_read.add(path.name)
                 if title:
-                    logger.info("Downloading %s", title)
+                    logger.info("%s %s", self.log_prefix, title)
 
     def run(self):
         """

src/ytdl_sub/utils/ffmpeg.py

@@ -46,7 +46,8 @@ class FFMPEG:
         cmd = ["ffmpeg"]
         cmd.extend(ffmpeg_args)
         logger.debug("Running %s", " ".join(cmd))
-        subprocess.run(cmd, check=True)
+        with Logger.handle_external_logs(name="ffmpeg"):
+            subprocess.run(cmd, check=True, capture_output=True)
 
 
 def _create_metadata_chapter_entry(start_sec: int, end_sec: int, title: str) -> List[str]:

tests/e2e/youtube/test_channel_as_kodi_tv_show.py

@@ -267,7 +267,7 @@ class TestChannelAsKodiTvShow:
 
             # try downloading again, ensure nothing more was downloaded
             with assert_debug_log(
-                logger=ytdl_sub.downloaders.downloader.logger,
+                logger=ytdl_sub.downloaders.downloader.download_logger,
                 expected_message="ExistingVideoReached, stopping additional downloads",
             ):
                 transaction_log = recent_channel_subscription.download()
@@ -330,7 +330,7 @@ class TestChannelAsKodiTvShow:
         # First, download recent vids. Always download since we want to test dry-run
         # on the rolling recent portion.
         with assert_debug_log(
-            logger=ytdl_sub.downloaders.downloader.logger,
+            logger=ytdl_sub.downloaders.downloader.download_logger,
             expected_message="RejectedVideoReached, stopping additional downloads",
         ):
             transaction_log = recent_channel_subscription.download()
@@ -345,7 +345,7 @@ class TestChannelAsKodiTvShow:
         # Then, download the rolling recent vids subscription. This should remove one of the
         # two videos
         with assert_debug_log(
-            logger=ytdl_sub.downloaders.downloader.logger,
+            logger=ytdl_sub.downloaders.downloader.download_logger,
             expected_message="ExistingVideoReached, stopping additional downloads",
         ):
             transaction_log = rolling_recent_channel_subscription.download(dry_run=dry_run)
@@ -365,7 +365,7 @@ class TestChannelAsKodiTvShow:
         # existing
         if not dry_run:
             with assert_debug_log(
-                logger=ytdl_sub.downloaders.downloader.logger,
+                logger=ytdl_sub.downloaders.downloader.download_logger,
                 expected_message="ExistingVideoReached, stopping additional downloads",
             ):
                 transaction_log = rolling_recent_channel_subscription.download()

tests/e2e/youtube/test_playlist_as_kodi_music_videos.py

@@ -118,7 +118,7 @@ class TestPlaylistAsKodiMusicVideo:
 
             # Ensure another invocation will hit ExistingVideoReached
             with assert_debug_log(
-                logger=ytdl_sub.downloaders.downloader.logger,
+                logger=ytdl_sub.downloaders.downloader.download_logger,
                 expected_message="ExistingVideoReached, stopping additional downloads",
             ):
                 playlist_subscription.download()