Configurable log levels (#71)

Makefile

@@ -1,10 +1,18 @@
 
-wheel:
+wheel: clean
 	python setup.py bdist_wheel
 docker: wheel
 	cp dist/*.whl docker/root/
 	sudo docker build --no-cache -t ytdl-sub:0.1 docker/
 docs:
 	sphinx-build -a -b html docs docs/_html
+clean:
+	rm -rf \
+		.pytest_cache/ \
+		build/ \
+		dist/ \
+		src/ytdl_sub.egg-info/ \
+		.coverage \
+		coverage.xml
 
-.PHONY: wheel docker docs
+.PHONY: wheel docker docs clean

src/ytdl_sub/cli/main_args_parser.py

@@ -2,6 +2,8 @@ import argparse
 
 ###################################################################################################
 # GLOBAL PARSER
+from ytdl_sub.utils.logger import LoggerLevels
+
 parser = argparse.ArgumentParser(
     description="ytdl-sub: Automate download and adding metadata with YoutubeDL"
 )
@@ -13,6 +15,14 @@ parser.add_argument(
     help="path to the config yaml, uses config.yaml if not provided",
     default="config.yaml",
 )
+parser.add_argument(
+    "--log-level",
+    metavar="|".join(LoggerLevels.names()),
+    type=str,
+    help="level of logs to print to console, defaults to info",
+    default=LoggerLevels.INFO.name,
+    choices=LoggerLevels.names(),
+)
 ###################################################################################################
 # SUBSCRIPTION PARSER
 subparsers = parser.add_subparsers(dest="subparser")

src/ytdl_sub/downloaders/downloader.py

@@ -18,6 +18,7 @@ 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.utils.logger import Logger
 from ytdl_sub.validators.strict_dict_validator import StrictDictValidator
 
 
@@ -115,8 +116,9 @@ class Downloader(Generic[DownloaderOptionsT, DownloaderEntryT], ABC):
         if ytdl_options_overrides is not None:
             ytdl_options = dict(ytdl_options, **ytdl_options_overrides)
 
-        with ytdl.YoutubeDL(ytdl_options) as ytdl_downloader:
+        with Logger.handle_external_logs(name="yt-dlp"):
-            yield ytdl_downloader
+            with ytdl.YoutubeDL(ytdl_options) as ytdl_downloader:
+                yield ytdl_downloader
 
     def extract_info(self, ytdl_options_overrides: Optional[Dict] = None, **kwargs) -> Dict:
         """

src/ytdl_sub/main.py

@@ -72,6 +72,8 @@ def _main():
     args, extra_args = parser.parse_known_args()
 
     config: ConfigFile = ConfigFile.from_file_path(args.config).initialize()
+    Logger.set_log_level(log_level_name=args.log_level)
+
     if args.subparser == "sub":
         _download_subscriptions_from_yaml_files(config=config, args=args)
         logger.info("Subscription download complete!")
@@ -81,6 +83,9 @@ def _main():
         _download_subscription_from_cli(config=config, extra_args=extra_args)
         logger.info("Download complete!")
 
+    # Ran successfully, so we can delete the debug file
+    Logger.cleanup(delete_debug_file=True)
+
 
 def main():
     """
@@ -94,9 +99,10 @@ def main():
     except Exception:  # pylint: disable=broad-except
         logger.exception("An uncaught error occurred:")
         logger.error(
-            "Please copy and paste the stacktrace above and make a Github "
+            "Please upload the error log file '%s' and make a Github "
             "issue at https://github.com/jmbannon/ytdl-sub/issues with your config and "
-            "command/subscription yaml file to reproduce. Thanks for trying ytdl-sub!"
+            "command/subscription yaml file to reproduce. Thanks for trying ytdl-sub!",
+            Logger.debug_log_filename(),
         )
         sys.exit(1)
 

src/ytdl_sub/utils/logger.py

@@ -1,9 +1,113 @@
+import contextlib
+import io
 import logging
+import os
 import sys
+import tempfile
+from dataclasses import dataclass
+from typing import List
 from typing import Optional
 
 
+@dataclass
+class LoggerLevel:
+    name: str
+    level: int
+    logging_level: int
+
+
+class LoggerLevels:
+    """
+    Custom log levels
+    """
+
+    QUIET = LoggerLevel(name="quiet", level=0, logging_level=logging.WARNING)  # Only warnings
+    INFO = LoggerLevel(name="info", level=10, logging_level=logging.INFO)  # ytdl-sub info logs
+    VERBOSE = LoggerLevel(name="verbose", level=20, logging_level=logging.INFO)  # ytdl-sub + yt-dlp
+    DEBUG = LoggerLevel(
+        name="debug", level=30, logging_level=logging.DEBUG
+    )  # ytdl-sub + yt-dlp debug logs
+
+    @classmethod
+    def all(cls) -> List[LoggerLevel]:
+        """
+        Returns
+        -------
+        All log levels
+        """
+        return [cls.QUIET, cls.INFO, cls.VERBOSE, cls.DEBUG]
+
+    @classmethod
+    def from_str(cls, name: str) -> LoggerLevel:
+        """
+        Parameters
+        ----------
+        name
+            The log level name
+
+        Raises
+        ------
+        ValueError
+            Name is not a valid logger level
+        """
+        for logger_level in cls.all():
+            if name == logger_level.name:
+                return logger_level
+        raise ValueError("Invalid logger level name")
+
+    @classmethod
+    def names(cls) -> List[str]:
+        """
+        Returns
+        -------
+        All log level names
+        """
+        return [logger_level.name for logger_level in cls.all()]
+
+
+class StreamToLogger(io.StringIO):
+    def __init__(self, logger: logging.Logger, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self._logger = logger
+
+    def write(self, __s: str) -> int:
+        """
+        Writes to the logger and stream
+        """
+        if __s != "\n":
+            self._logger.info(__s.removesuffix("\n"))
+        return super().write(__s)
+
+
 class Logger:
+
+    # The level set via CLI arguments
+    _LOGGER_LEVEL: LoggerLevel = LoggerLevels.DEBUG
+
+    # Ignore 'using with' warning since this will be cleaned up later
+    # pylint: disable=R1732
+    _DEBUG_LOGGER_FILE = tempfile.NamedTemporaryFile(prefix="ytdl-sub.", delete=False)
+    # pylint: enable=R1732
+
+    @classmethod
+    def debug_log_filename(cls) -> str:
+        """
+        Returns
+        -------
+        File name of the debug log file
+        """
+        return cls._DEBUG_LOGGER_FILE.name
+
+    @classmethod
+    def set_log_level(cls, log_level_name: str):
+        """
+        Parameters
+        ----------
+        log_level_name
+            Name of the log level to set
+        """
+        cls._LOGGER_LEVEL = LoggerLevels.from_str(name=log_level_name)
+
     @classmethod
     def _get_formatter(cls) -> logging.Formatter:
         """
@@ -14,17 +118,40 @@ class Logger:
         return logging.Formatter("[%(name)s] %(message)s")
 
     @classmethod
-    def _get_handler(cls) -> logging.StreamHandler:
+    def _get_stdout_handler(cls) -> logging.StreamHandler:
         """
         Returns
         -------
         Logger handler
         """
         handler = logging.StreamHandler(sys.stdout)
-        handler.setLevel(logging.INFO)
+        handler.setLevel(cls._LOGGER_LEVEL.logging_level)
         handler.setFormatter(cls._get_formatter())
         return handler
 
+    @classmethod
+    def _get_debug_file_handler(cls) -> logging.FileHandler:
+        handler = logging.FileHandler(filename=cls.debug_log_filename(), encoding="utf-8")
+        handler.setLevel(logging.DEBUG)
+        handler.setFormatter(cls._get_formatter())
+        return handler
+
+    @classmethod
+    def _get(
+        cls, name: Optional[str] = None, stdout: bool = True, debug_file: bool = True
+    ) -> logging.Logger:
+        logger_name = "ytdl-sub"
+        if name:
+            logger_name += f":{name}"
+
+        logger = logging.Logger(name=logger_name, level=logging.DEBUG)
+        if stdout and cls._LOGGER_LEVEL.level >= LoggerLevels.INFO.level:
+            logger.addHandler(cls._get_stdout_handler())
+        if debug_file:
+            logger.addHandler(cls._get_debug_file_handler())
+
+        return logger
+
     @classmethod
     def get(cls, name: Optional[str] = None) -> logging.Logger:
         """
@@ -38,10 +165,41 @@ class Logger:
         -------
         A configured logger
         """
-        logger_name = "ytdl-sub"
+        return cls._get(name=name, stdout=True, debug_file=True)
-        if name:
-            logger_name += f":{name}"
 
-        logger = logging.Logger(name=logger_name)
+    @classmethod
-        logger.addHandler(cls._get_handler())
+    @contextlib.contextmanager
-        return logger
+    def handle_external_logs(cls, name: Optional[str] = None) -> None:
+        """
+        Suppresses all stdout and stderr logs. Intended to suppress other packages logs.
+        Will always write these logs to the debug logger file.
+
+        Parameters
+        ----------
+        name
+            Optional. Name of the logger which is included in the prefix like [ytdl-sub:<name>].
+            If None, the prefix is just [ytdl-sub]mak
+        """
+        logger = cls._get(
+            name=name, stdout=cls._LOGGER_LEVEL.level >= LoggerLevels.VERBOSE.level, debug_file=True
+        )
+
+        with StreamToLogger(logger=logger) as redirect_stream:
+            with contextlib.redirect_stdout(new_target=redirect_stream):
+                with contextlib.redirect_stderr(new_target=redirect_stream):
+                    yield
+
+    @classmethod
+    def cleanup(cls, delete_debug_file: bool = True):
+        """
+        Cleans up any log files left behind.
+
+        Parameters
+        ----------
+        delete_debug_file
+            Whether to delete the debug log file. Defaults to True.
+        """
+        cls._DEBUG_LOGGER_FILE.close()
+
+        if delete_debug_file and os.path.isfile(cls.debug_log_filename()):
+            os.remove(cls.debug_log_filename())

tests/unit/main/test_main.py

@@ -0,0 +1,63 @@
+import contextlib
+import sys
+from unittest.mock import patch
+
+import pytest
+
+from src.ytdl_sub.main import main
+from ytdl_sub.utils.exceptions import ValidationException
+from ytdl_sub.utils.logger import Logger
+
+
+@pytest.fixture
+def expected_uncaught_error_message():
+    return (
+        f"Please upload the error log file '%s' and make a "
+        f"Github issue at https://github.com/jmbannon/ytdl-sub/issues with your config and "
+        f"command/subscription yaml file to reproduce. Thanks for trying ytdl-sub!"
+    )
+
+
+@pytest.fixture
+def mock_sys_exit():
+    @contextlib.contextmanager
+    def _mock_sys_exit(expected_exit_code: int):
+        with patch.object(sys, "exit") as mock_exit:
+            yield mock_exit
+
+        assert mock_exit.called
+        assert mock_exit.call_args_list[0].args[0] == expected_exit_code
+
+    return _mock_sys_exit
+
+
+def test_main_success(mock_sys_exit):
+    with mock_sys_exit(expected_exit_code=0):
+        with patch("src.ytdl_sub.main._main"):
+            main()
+
+
+def test_main_validation_error(capsys, mock_sys_exit):
+    validation_exception = ValidationException("test")
+    with mock_sys_exit(expected_exit_code=1):
+        with patch("src.ytdl_sub.main._main", side_effect=validation_exception):
+            with patch("src.ytdl_sub.main.logger") as mock_logger:
+                main()
+
+    assert mock_logger.error.call_count == 1
+    assert mock_logger.error.call_args.args[0] == validation_exception
+
+
+def test_main_uncaught_error(capsys, mock_sys_exit, expected_uncaught_error_message):
+    uncaught_error = ValueError("test")
+    with mock_sys_exit(expected_exit_code=1):
+        with patch("src.ytdl_sub.main._main", side_effect=uncaught_error):
+            with patch("src.ytdl_sub.main.logger") as mock_logger:
+                main()
+
+    assert mock_logger.exception.call_count == 1
+    assert mock_logger.exception.call_args.args[0] == "An uncaught error occurred:"
+
+    assert mock_logger.error.call_count == 1
+    assert mock_logger.error.call_args.args[0] == expected_uncaught_error_message
+    assert mock_logger.error.call_args.args[1] == Logger.debug_log_filename()

tests/unit/utils/test_logger.py

@@ -0,0 +1,130 @@
+import os.path
+
+import pytest
+
+from ytdl_sub.utils.logger import Logger
+from ytdl_sub.utils.logger import LoggerLevels
+
+
+@pytest.fixture(autouse=True)
+def cleanup_debug_file():
+    Logger.set_log_level(log_level_name=LoggerLevels.DEBUG.name)
+    yield
+    Logger.cleanup(delete_debug_file=True)
+
+
+class TestLogger:
+    @pytest.mark.parametrize(
+        "log_level",
+        [
+            LoggerLevels.QUIET,
+            LoggerLevels.INFO,
+            LoggerLevels.VERBOSE,
+            LoggerLevels.DEBUG,
+        ],
+    )
+    def test_logger_level_set(self, log_level):
+        Logger.set_log_level(log_level_name=log_level.name)
+        assert Logger._LOGGER_LEVEL == log_level
+
+    def test_logger_level_invalid_name(self):
+        with pytest.raises(ValueError):
+            Logger.set_log_level("nope")
+
+    @pytest.mark.parametrize(
+        "log_level, outputs_to_stdout",
+        [
+            (LoggerLevels.QUIET, False),
+            (LoggerLevels.INFO, True),
+            (LoggerLevels.VERBOSE, True),
+            (LoggerLevels.DEBUG, True),
+        ],
+    )
+    def test_logger_info_stdout(self, capsys, log_level, outputs_to_stdout):
+        Logger._LOGGER_LEVEL = log_level
+        logger = Logger.get(name="name_test")
+
+        logger.info("test")
+        captured = capsys.readouterr()
+
+        if outputs_to_stdout:
+            assert captured.out == "[ytdl-sub:name_test] test\n"
+        else:
+            assert not captured.out
+
+    @pytest.mark.parametrize(
+        "log_level, outputs_to_stdout",
+        [
+            (LoggerLevels.QUIET, False),
+            (LoggerLevels.INFO, False),
+            (LoggerLevels.VERBOSE, False),
+            (LoggerLevels.DEBUG, True),
+        ],
+    )
+    def test_logger_debug_stdout(self, capsys, log_level, outputs_to_stdout):
+        Logger._LOGGER_LEVEL = log_level
+        logger = Logger.get(name="name_test")
+
+        logger.debug("test")
+        captured = capsys.readouterr()
+
+        if outputs_to_stdout:
+            assert captured.out == "[ytdl-sub:name_test] test\n"
+        else:
+            assert not captured.out
+
+    @pytest.mark.parametrize(
+        "log_level",
+        [
+            LoggerLevels.QUIET,
+            LoggerLevels.INFO,
+            LoggerLevels.VERBOSE,
+            LoggerLevels.DEBUG,
+        ],
+    )
+    def test_logger_always_outputs_to_debug_file(self, log_level):
+        Logger._LOGGER_LEVEL = log_level
+        logger = Logger.get(name="name_test")
+
+        logger.info("info test")
+        logger.debug("debug test")
+
+        with open(Logger._DEBUG_LOGGER_FILE.name, "r", encoding="utf-8") as log_file:
+            lines = log_file.readlines()
+
+        assert lines == ["[ytdl-sub:name_test] info test\n", "[ytdl-sub:name_test] debug test\n"]
+
+        # Ensure the file cleans up too
+        Logger.cleanup(delete_debug_file=True)
+        assert not os.path.isfile(Logger._DEBUG_LOGGER_FILE.name)
+
+    @pytest.mark.parametrize(
+        "log_level, expected_stdout",
+        [
+            (LoggerLevels.QUIET, False),
+            (LoggerLevels.INFO, False),
+            (LoggerLevels.VERBOSE, True),
+            (LoggerLevels.DEBUG, True),
+        ],
+    )
+    def test_handle_external_logs(self, capsys, log_level, expected_stdout):
+        Logger._LOGGER_LEVEL = log_level
+        expected_lines = [
+            "[ytdl-sub:name_test] test line 1\n",
+            "[ytdl-sub:name_test] test line 2\n",
+        ]
+        with Logger.handle_external_logs(name="name_test"):
+            print("test line 1")
+            print("test line 2")
+
+        # Ensure it goes to stdout only if it is expected to
+        captured = capsys.readouterr()
+        if expected_stdout:
+            assert captured.out == "".join(expected_lines)
+        else:
+            assert not captured.out
+
+        # Ensure it always go to the debug file
+        with open(Logger._DEBUG_LOGGER_FILE.name, "r", encoding="utf-8") as log_file:
+            lines = log_file.readlines()
+        assert lines == expected_lines