Add debug log statements

spotdl/authorize/services/spotify.py

@@ -4,6 +4,9 @@ from spotdl.authorize.exceptions import SpotifyAuthorizationError
 import spotipy
 import spotipy.oauth2 as oauth2
 
+import logging
+logger = logging.getLogger(__name__)
+
 # This masterclient is used to keep the last logged-in client
 # object in memory for for persistence. If credentials aren't
 # provided when creating further objects, the last authenticated
@@ -26,10 +29,12 @@ class AuthorizeSpotify(spotipy.Spotify):
             )
 
         if masterclient:
+            logger.debug("Reading cached master Spotify credentials.")
             # Use cached client instead of authorizing again
             # and thus wasting time.
             self.__dict__.update(masterclient.__dict__)
         else:
+            logger.debug("Setting master Spotify credentials.")
             credential_manager = oauth2.SpotifyClientCredentials(
                 client_id=client_id,
                 client_secret=client_secret

spotdl/command_line/arguments.py

@@ -291,11 +291,17 @@ class Arguments:
 
         encoder_exists = shutil.which(self.parsed.encoder)
         if not self.parsed.encoder == "null" and not encoder_exists:
-            logger.warn(
+            logger.warn('Specified encoder "{}" was not found in PATH.')
-                'Specified encoder "{}" was not found in PATH. Will not encode to specified '
-                'output format.'.format(self.parsed.encoder))
             self.parsed.encoder = "null"
 
+        if self.parsed.encoder == "null":
+            self.parsed.output_ext = self.parsed.input_ext
+            logger.warn(
+                "Encoder is null. Will not re-encode to specified output format.".format(
+                    self.parsed.encoder
+                )
+            )
+
         if self.parsed.output_file == "-" and self.parsed.no_metadata is False:
             logger.warn(
                 "Cannot write metadata when target file is STDOUT. Pass "

spotdl/command_line/exceptions.py

@@ -1,4 +1,11 @@
-class NoYouTubeVideoError(Exception):
+class NoYouTubeVideoFoundError(Exception):
+    __module__ = Exception.__module__
+
+    def __init__(self, message=None):
+        super().__init__(message)
+
+
+class NoYouTubeVideoMatchError(Exception):
     __module__ = Exception.__module__
 
     def __init__(self, message=None):

spotdl/command_line/lib.py

@@ -18,7 +18,8 @@ from spotdl.track import Track
 import spotdl.util
 import spotdl.config
 
-from spotdl.command_line.exceptions import NoYouTubeVideoError
+from spotdl.command_line.exceptions import NoYouTubeVideoFoundError
+from spotdl.command_line.exceptions import NoYouTubeVideoMatchError
 
 import sys
 import os
@@ -69,6 +70,7 @@ def search_metadata(track, search_format="{artist} - {track-name} lyrics", manua
     youtube_searcher = YouTubeSearch()
 
     if spotdl.util.is_spotify(track):
+        logger.debug("Input track is a Spotify URL.")
         spotify = ProviderSpotify()
         spotify_metadata = spotify.from_url(track)
         lyric_query = spotdl.metadata.format_string(
@@ -78,23 +80,29 @@ def search_metadata(track, search_format="{artist} - {track-name} lyrics", manua
         search_query = spotdl.metadata.format_string(search_format, spotify_metadata)
         youtube_videos = youtube_searcher.search(search_query)
         if not youtube_videos:
-            raise NoYouTubeVideoError(
+            raise NoYouTubeVideoFoundError(
-                'No videos found for the search query: "{}"'.format(search_query)
+                'YouTube returned no videos for the search query "{}".'.format(search_query)
             )
         if manual:
             youtube_video = prompt_for_youtube_search_result(youtube_videos)
         else:
             youtube_video = youtube_videos.bestmatch()
+
         if youtube_video is None:
-            metadata = spotify_metadata
+            raise NoYouTubeVideoMatchError(
-        else:
+                'No matching videos found on YouTube for the search query "{}".'.format(
-            youtube_metadata = youtube.from_url(youtube_video["url"])
+                    search_query
-            metadata = spotdl.util.merge(
+                )
-                youtube_metadata,
-                spotify_metadata
             )
 
+        youtube_metadata = youtube.from_url(youtube_video["url"])
+        metadata = spotdl.util.merge(
+            youtube_metadata,
+            spotify_metadata
+        )
+
     elif spotdl.util.is_youtube(track):
+        logger.debug("Input track is a YouTube URL.")
         metadata = youtube.from_url(track)
         lyric_query = spotdl.metadata.format_string(
             "{artist} - {track-name}",
@@ -102,37 +110,36 @@ def search_metadata(track, search_format="{artist} - {track-name} lyrics", manua
         )
 
     else:
-        lyric_query = track
+        logger.debug("Input track is a search query.")
+        search_query = track
+        lyric_query = search_query
         spotify_metadata = spotdl.util.ThreadWithReturnValue(
             target=search_metadata_on_spotify,
-            args=(track,)
+            args=(search_query,)
         )
         spotify_metadata.start()
-        youtube_videos = youtube_searcher.search(track)
+        youtube_videos = youtube_searcher.search(search_query)
         if not youtube_videos:
-            raise NoYouTubeVideoError(
+            raise NoYouTubeVideoFoundError(
-                'No videos found for the search query: "{}"'.format(track)
+                'YouTube returned no videos for the search query "{}"'.format(search_query)
             )
         if manual:
             youtube_video = prompt_for_youtube_search_result(youtube_videos)
-            if youtube_video is None:
-                return
         else:
             youtube_video = youtube_videos.bestmatch()
+
         if youtube_video is None:
-            metadata = spotify_metadata
+            raise NoYouTubeVideoMatchError(
-        else:
+                'No matching videos found on YouTube for the search query "{}"'.format(
-            youtube_metadata = youtube.from_url(youtube_video["url"])
+                    search_query
-            metadata = spotdl.util.merge(
+                )
-                youtube_metadata,
-                spotify_metadata.join()
             )
 
-    logger.debug("Matched with: {title} ({url}) [{duration}]".format(
+        youtube_metadata = youtube.from_url(youtube_video["url"])
-        title=youtube_video["title"],
+        metadata = spotdl.util.merge(
-        url=youtube_video["url"],
+            youtube_metadata,
-        duration=youtube_video["duration"]
+            spotify_metadata.join()
-    ))
+        )
 
     metadata["lyrics"] = spotdl.util.ThreadWithReturnValue(
         target=search_lyrics,
@@ -170,7 +177,7 @@ class Spotdl:
             client_id=self.arguments["spotify_client_id"],
             client_secret=self.arguments["spotify_client_secret"]
         )
-        logger.debug("Received arguments: {}".format(self.arguments))
+        logger.debug("Received arguments:\n{}".format(self.arguments))
 
         # youtube_tools.set_api_key()
         if self.arguments["song"]:
@@ -215,15 +222,19 @@ class Spotdl:
             )
 
     def download_track(self, track):
+        logger.info('Downloading "{}"'.format(track))
         track_splits = track.split(":")
         if len(track_splits) == 2:
             youtube_track, spotify_track = track_splits
-        metadata = search_metadata(
+        try:
-            track,
+            metadata = search_metadata(
-            search_format=self.arguments["search_format"],
+                track,
-            manual=self.arguments["manual"],
+                search_format=self.arguments["search_format"],
-        )
+                manual=self.arguments["manual"],
-        if "streams" in metadata:
+            )
+        except (NoYouTubeVideoFoundError, NoYouTubeVideoMatchError) as e:
+            logger.error(e.args[0])
+        else:
             self.download_track_from_metadata(metadata)
 
     def download_track_from_metadata(self, metadata):
@@ -233,7 +244,6 @@ class Spotdl:
             quality=self.arguments["quality"],
             preftype=self.arguments["input_ext"],
         )
-        logger.debug("Stream information: {}".format(stream))
 
         Encoder = {
             "ffmpeg": EncoderFFmpeg,
@@ -253,23 +263,29 @@ class Spotdl:
                 s, spaces_to_underscores=self.arguments["no_spaces"]
             )
         )
-        logger.info('Downloading to "{filename}"'.format(filename=filename))
 
         to_skip = self.arguments["dry_run"]
         if not to_skip and os.path.isfile(filename):
+            msg_already_exists = 'A file with name "{filename}" already exists.'.format(
+                filename=filename
+            )
             if self.arguments["overwrite"] == "force":
+                force_overwrite_msg = msg_already_exists + " Forcing overwrite."
                 to_skip = False
-                logger.info("A file with target filename already exists. Forcing overwrite.")
+                logger.info(force_overwrite_msg)
             elif self.arguments["overwrite"] == "prompt":
-                overwrite_msg = "A file with target filename already exists. Overwrite? (y/N): "
+                prompt_overwrite_msg = msg_already_exists + " Overwrite? (y/N): "
-                to_skip = not input(overwrite_msg).lower() == "y"
+                to_skip = not input(prompt_overwrite_msg).lower() == "y"
             else:
-                logger.info("A file with target filename already exists. Skipping download.")
+                skip_overwrite_msg = msg_already_exists + " Skipping download."
                 to_skip = True
+                logger.info(skip_overwrite_msg)
 
         if to_skip:
+            logger.debug("Skip track download.")
             return
 
+        logger.info('Downloading to "{filename}".'.format(filename=filename))
         if Encoder is None:
             track.download(stream, filename)
         else:
@@ -318,7 +334,7 @@ class Spotdl:
                 logger.exception(e.args[0])
                 logger.warning("Failed. Will retry after other songs\n")
                 tracks.append(track)
-            except NoYouTubeVideoError:
+            except NoYouTubeVideoFoundError:
                 logger.warning("Failed. No YouTube video found.\n")
                 pass
             else:

spotdl/encode/encoders/ffmpeg.py

@@ -1,13 +1,16 @@
 import subprocess
 import os
-# from logzero import logger as log
-import logging
-logger = logging.getLogger(__name__)
 
 from spotdl.encode import EncoderBase
 from spotdl.encode.exceptions import EncoderNotFoundError
 from spotdl.encode.exceptions import FFmpegNotFoundError
 
+import logging
+logger = logging.getLogger(__name__)
+
+
+# Key: from format
+# Subkey: to format
 RULES = {
     "m4a": {
         "mp3": "-codec:v copy -codec:a libmp3lame -ar 48000",
@@ -84,6 +87,9 @@ class EncoderFFmpeg(EncoderBase):
             target_path,
             target_encoding=target_encoding
         )
+        logger.debug("Calling FFmpeg with:\n{command}".format(
+            command=encode_command,
+        ))
         process = subprocess.Popen(encode_command)
         process.wait()
         encode_successful = process.returncode == 0
@@ -98,6 +104,9 @@ class EncoderFFmpeg(EncoderBase):
             input_encoding=input_encoding,
             target_encoding=target_encoding,
         )
+        logger.debug("Calling FFmpeg with:\n{command}".format(
+            command=encode_command,
+        ))
         process = subprocess.Popen(encode_command, stdin=subprocess.PIPE)
         return process
 

spotdl/metadata/embedders/default_embedder.py

@@ -7,6 +7,9 @@ import urllib.request
 
 from spotdl.metadata import EmbedderBase
 
+import logging
+logger = logging.getLogger(__name__)
+
 # Apple has specific tags - see mutagen docs -
 # http://mutagen.readthedocs.io/en/latest/api/mp4.html
 M4A_TAG_PRESET = {
@@ -47,6 +50,7 @@ class EmbedderDefault(EmbedderBase):
 
     def as_mp3(self, path, metadata, cached_albumart=None):
         """ Embed metadata to MP3 files. """
+        logger.debug('Writing MP3 metadata to "{path}"'.format(path=path))
         # EasyID3 is fun to use ;)
         # For supported easyid3 tags:
         # https://github.com/quodlibet/mutagen/blob/master/mutagen/easyid3.py
@@ -104,6 +108,7 @@ class EmbedderDefault(EmbedderBase):
 
     def as_m4a(self, path, metadata, cached_albumart=None):
         """ Embed metadata to M4A files. """
+        logger.debug('Writing M4A metadata to "{path}"'.format(path=path))
         audiofile = MP4(path)
         self._embed_basic_metadata(audiofile, metadata, "m4a", preset=M4A_TAG_PRESET)
         if metadata["year"]:
@@ -127,6 +132,7 @@ class EmbedderDefault(EmbedderBase):
         audiofile.save()
 
     def as_flac(self, path, metadata, cached_albumart=None):
+        logger.debug('Writing FLAC metadata to "{path}"'.format(path=path))
         audiofile = FLAC(path)
         self._embed_basic_metadata(audiofile, metadata, "flac")
         if metadata["year"]:

spotdl/metadata/providers/spotify.py

@@ -6,6 +6,10 @@ from spotdl.metadata.exceptions import SpotifyMetadataNotFoundError
 
 from spotdl.authorize.services import AuthorizeSpotify
 
+import logging
+logger = logging.getLogger(__name__)
+
+
 class ProviderSpotify(ProviderBase):
     def __init__(self, spotify=None):
         if spotify is None:
@@ -17,6 +21,7 @@ class ProviderSpotify(ProviderBase):
         self.spotify = spotipy.Spotify(auth=token)
 
     def from_url(self, url):
+        logger.debug('Fetching Spotify metadata for "{url}".'.format(url=url))
         metadata = self.spotify.track(url)
         return self.metadata_to_standard_form(metadata)
 
@@ -33,7 +38,6 @@ class ProviderSpotify(ProviderBase):
     def _generate_token(self, client_id, client_secret):
         """ Generate the token. """
         credentials = oauth2.SpotifyClientCredentials(
-            client_id=client_id,
             client_secret=client_secret,
         )
         token = credentials.get_access_token()

spotdl/metadata/providers/youtube.py

@@ -33,7 +33,13 @@ class YouTubeVideos(Sequence):
         return self.videos[index]
 
     def bestmatch(self):
-        return self.videos[0]
+        video = self.videos[0]
+        logger.debug("Matched with: {title} ({url}) [{duration}]".format(
+            title=video["title"],
+            url=video["url"],
+            duration=video["duration"]
+        ))
+        return video
 
 
 class YouTubeSearch:
@@ -96,13 +102,16 @@ class YouTubeSearch:
         video = not not_video
         return video
 
-    def search(self, query, limit=10):
+    def search(self, query, limit=5):
         """ Search and scrape YouTube to return a list of matching videos. """
         search_url = self.generate_search_url(query)
-        logger.debug("Fetching YouTube results for search URL: {0}".format(search_url))
+        logger.debug('Fetching YouTube results for "{}".'.format(search_url))
         html = self._fetch_response_html(search_url)
-
         videos = self._fetch_search_results(html)
+        # print(html)
+        # print("")
+        # print(videos)
+        # exit()
         return YouTubeVideos(videos)
 
 
@@ -157,18 +166,34 @@ class YouTubeStreams(StreamsBase):
             return None
 
     def getbest(self, preftype="automatic"):
+        selected_stream = None
         if preftype == "automatic":
-            return self.all[0]
+            selected_stream = self.all[0]
-        for stream in self.all:
+        else:
-            if stream["encoding"] == preftype:
+            for stream in self.all:
-                return stream
+                if stream["encoding"] == preftype:
+                    selected_stream = stream
+                    break
+        logger.debug('Selected best quality stream for "{preftype}" format:\n{stream}'.format(
+            preftype=preftype,
+            stream=selected_stream,
+        ))
+        return selected_stream
 
     def getworst(self, preftype="automatic"):
+        selected_stream = None
         if preftype == "automatic":
-            return self.all[-1]
+            selected_stream = self.all[-1]
-        for stream in self.all[::-1]:
+        else:
-            if stream["encoding"] == preftype:
+            for stream in self.all[::-1]:
-                return stream
+                if stream["encoding"] == preftype:
+                    selected_stream = stream
+                    break
+        logger.debug('Selected worst quality stream for "{preftype}" format:\n'.format(
+            preftype=preftype,
+            stream=selected_stream,
+        ))
+        return selected_stream
 
 
 class ProviderYouTube(ProviderBase):
@@ -182,6 +207,7 @@ class ProviderYouTube(ProviderBase):
         return self.from_url(watch_urls[0])
 
     def from_url(self, url):
+        logger.debug('Fetching YouTube metadata for "{url}".'.format(url=url))
         content = pytube.YouTube(url)
         return self.from_pytube_object(content)
 

spotdl/track.py

@@ -8,7 +8,7 @@ from spotdl.metadata.embedders import EmbedderDefault
 
 import spotdl.util
 
-CHUNK_SIZE= 16 * 1024
+CHUNK_SIZE = 16 * 1024
 
 class Track:
     def __init__(self, metadata, cache_albumart=False):
@@ -28,19 +28,32 @@ class Track:
         albumart_thread.start()
         return albumart_thread
 
-    def _calculate_total_chunks(self, filesize):
+    def calculate_total_chunks(self, filesize):
         return (filesize // self._chunksize) + 1
 
+    def make_progress_bar(self, total_chunks):
+        progress_bar = tqdm.trange(
+            total_chunks,
+            unit_scale=(self._chunksize // 1024),
+            unit="KiB",
+            dynamic_ncols=True,
+            bar_format='{desc}: {percentage:3.0f}%|{bar}| {n_fmt}/{total_fmt}KiB '
+                '[{elapsed}<{remaining}, {rate_fmt}{postfix}]',
+        )
+        return progress_bar
+
     def download_while_re_encoding(self, stream, target_path, target_encoding=None,
                                    encoder=EncoderFFmpeg(), show_progress=True):
-        total_chunks = self._calculate_total_chunks(stream["filesize"])
+        total_chunks = self.calculate_total_chunks(stream["filesize"])
         process = encoder.re_encode_from_stdin(
             stream["encoding"],
             target_path,
             target_encoding=target_encoding
         )
         response = stream["connection"]
-        for _ in tqdm.trange(total_chunks):
+
+        progress_bar = self.make_progress_bar(total_chunks)
+        for _ in progress_bar:
             chunk = response.read(self._chunksize)
             process.stdin.write(chunk)
 
@@ -48,17 +61,18 @@ class Track:
         process.wait()
 
     def download(self, stream, target_path, show_progress=True):
-        total_chunks = self._calculate_total_chunks(stream["filesize"])
+        total_chunks = self.calculate_total_chunks(stream["filesize"])
+        progress_bar = self.make_progress_bar(total_chunks)
         response = stream["connection"]
         with open(target_path, "wb") as fout:
-            for _ in tqdm.trange(total_chunks):
+            for _ in progress_bar:
                 chunk = response.read(self._chunksize)
                 fout.write(chunk)
 
     def re_encode(self, input_path, target_path, target_encoding=None,
                   encoder=EncoderFFmpeg(), show_progress=True):
         stream = self.metadata["streams"].getbest()
-        total_chunks = self._calculate_total_chunks(stream["filesize"])
+        total_chunks = self.calculate_total_chunks(stream["filesize"])
         process = encoder.re_encode_from_stdin(
             stream["encoding"],
             target_path,