From 232b1ac75a94d8758392f41a0bef2aa031e9c122 Mon Sep 17 00:00:00 2001 From: Jesse Bannon Date: Fri, 29 Jul 2022 00:03:02 -0700 Subject: [PATCH] [BACKEND] Improve info logger messages (#129) --- src/ytdl_sub/downloaders/downloader.py | 52 ++++++++++++++++--- .../soundcloud/albums_and_singles.py | 23 +++++--- src/ytdl_sub/downloaders/youtube/channel.py | 27 +++++----- src/ytdl_sub/downloaders/youtube/playlist.py | 19 +++---- src/ytdl_sub/entries/soundcloud.py | 2 +- src/ytdl_sub/subscriptions/subscription.py | 20 ------- .../thread/log_entries_downloaded_listener.py | 16 ++++-- src/ytdl_sub/utils/ffmpeg.py | 3 +- .../youtube/test_channel_as_kodi_tv_show.py | 8 +-- .../test_playlist_as_kodi_music_videos.py | 2 +- 10 files changed, 105 insertions(+), 67 deletions(-) diff --git a/src/ytdl_sub/downloaders/downloader.py b/src/ytdl_sub/downloaders/downloader.py index a7f2f0a0..740e56ab 100644 --- a/src/ytdl_sub/downloaders/downloader.py +++ b/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() diff --git a/src/ytdl_sub/downloaders/soundcloud/albums_and_singles.py b/src/ytdl_sub/downloaders/soundcloud/albums_and_singles.py index f6a06d9e..f3a044b6 100644 --- a/src/ytdl_sub/downloaders/soundcloud/albums_and_singles.py +++ b/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} diff --git a/src/ytdl_sub/downloaders/youtube/channel.py b/src/ytdl_sub/downloaders/youtube/channel.py index b86365d5..ab8b473e 100644 --- a/src/ytdl_sub/downloaders/youtube/channel.py +++ b/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( - {"skip_download": True, "write_thumbnail": False}, **ytdl_options_overrides - ), + ytdl_options_overrides=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: - if entry_dict.get("extractor") == "youtube": + for idx, entry_dict in enumerate(entry_dicts, start=1): + 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( diff --git a/src/ytdl_sub/downloaders/youtube/playlist.py b/src/ytdl_sub/downloaders/youtube/playlist.py index 21fe2f9e..24c64674 100644 --- a/src/ytdl_sub/downloaders/youtube/playlist.py +++ b/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={ - "skip_download": True, - "writethumbnail": False, - }, + only_info_json=True, + log_prefix_on_info_json_dl="Downloading metadata for", url=self.download_options.playlist_url, ) - for entry_dict in entry_dicts: - if entry_dict.get("extractor") == "youtube": + for idx, entry_dict in enumerate(entry_dicts, start=1): + 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( - entry_dict=entry_dict, working_directory=self.working_directory - ) + yield video diff --git a/src/ytdl_sub/entries/soundcloud.py b/src/ytdl_sub/entries/soundcloud.py index 0c234b05..7149b39e 100644 --- a/src/ytdl_sub/entries/soundcloud.py +++ b/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: diff --git a/src/ytdl_sub/subscriptions/subscription.py b/src/ytdl_sub/subscriptions/subscription.py index 3b3174ae..12aa3b94 100644 --- a/src/ytdl_sub/subscriptions/subscription.py +++ b/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 diff --git a/src/ytdl_sub/thread/log_entries_downloaded_listener.py b/src/ytdl_sub/thread/log_entries_downloaded_listener.py index 246bf023..a20038b5 100644 --- a/src/ytdl_sub/thread/log_entries_downloaded_listener.py +++ b/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: - file_json = json.load(file) + try: + 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): """ diff --git a/src/ytdl_sub/utils/ffmpeg.py b/src/ytdl_sub/utils/ffmpeg.py index e028fda0..e4213a14 100644 --- a/src/ytdl_sub/utils/ffmpeg.py +++ b/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]: diff --git a/tests/e2e/youtube/test_channel_as_kodi_tv_show.py b/tests/e2e/youtube/test_channel_as_kodi_tv_show.py index 9fe5257f..f689a94d 100644 --- a/tests/e2e/youtube/test_channel_as_kodi_tv_show.py +++ b/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() diff --git a/tests/e2e/youtube/test_playlist_as_kodi_music_videos.py b/tests/e2e/youtube/test_playlist_as_kodi_music_videos.py index 035adbf2..ae47b24c 100644 --- a/tests/e2e/youtube/test_playlist_as_kodi_music_videos.py +++ b/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()