From 3d7595cda92d12944cbdc34bf3e761bf0917ef8d Mon Sep 17 00:00:00 2001 From: Jesse Bannon Date: Wed, 8 Jun 2022 23:01:31 -0700 Subject: [PATCH] Configurable log levels (#71) --- Makefile | 12 +- src/ytdl_sub/cli/main_args_parser.py | 10 ++ src/ytdl_sub/downloaders/downloader.py | 6 +- src/ytdl_sub/main.py | 10 +- src/ytdl_sub/utils/logger.py | 174 +++++++++++++++++++++++-- tests/unit/main/__init__.py | 0 tests/unit/main/test_main.py | 63 +++++++++ tests/unit/utils/test_logger.py | 130 ++++++++++++++++++ 8 files changed, 391 insertions(+), 14 deletions(-) create mode 100644 tests/unit/main/__init__.py create mode 100644 tests/unit/main/test_main.py create mode 100644 tests/unit/utils/test_logger.py diff --git a/Makefile b/Makefile index 8d53d610..e650882e 100644 --- a/Makefile +++ b/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 diff --git a/src/ytdl_sub/cli/main_args_parser.py b/src/ytdl_sub/cli/main_args_parser.py index dff72a68..38c7ad41 100644 --- a/src/ytdl_sub/cli/main_args_parser.py +++ b/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") diff --git a/src/ytdl_sub/downloaders/downloader.py b/src/ytdl_sub/downloaders/downloader.py index 7b388dfe..06dddd08 100644 --- a/src/ytdl_sub/downloaders/downloader.py +++ b/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: - yield ytdl_downloader + with Logger.handle_external_logs(name="yt-dlp"): + with ytdl.YoutubeDL(ytdl_options) as ytdl_downloader: + yield ytdl_downloader def extract_info(self, ytdl_options_overrides: Optional[Dict] = None, **kwargs) -> Dict: """ diff --git a/src/ytdl_sub/main.py b/src/ytdl_sub/main.py index 8a6bbcb9..e1fa0e72 100644 --- a/src/ytdl_sub/main.py +++ b/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) diff --git a/src/ytdl_sub/utils/logger.py b/src/ytdl_sub/utils/logger.py index 24d8dc27..90dfc49b 100644 --- a/src/ytdl_sub/utils/logger.py +++ b/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" - if name: - logger_name += f":{name}" + return cls._get(name=name, stdout=True, debug_file=True) - logger = logging.Logger(name=logger_name) - logger.addHandler(cls._get_handler()) - return logger + @classmethod + @contextlib.contextmanager + 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:]. + 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()) diff --git a/tests/unit/main/__init__.py b/tests/unit/main/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/tests/unit/main/test_main.py b/tests/unit/main/test_main.py new file mode 100644 index 00000000..8a71597b --- /dev/null +++ b/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() diff --git a/tests/unit/utils/test_logger.py b/tests/unit/utils/test_logger.py new file mode 100644 index 00000000..e7a5fe51 --- /dev/null +++ b/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