Repository: streamlink/streamlink
Pull request #3273 (2020-10-19 16:35:45)

logger: remove deprecated compat logger
Split into two commits, each with a description of the changes in the commit message bodies.

Things to note:

1. **BREAKING**: Due to the removal of the custom `LogRecord` class, log calls cannot use the curly bracket format style with custom LogRecord args anymore, like `log.info("foo {0}", bar)`. The default Python behavior is the percent format style, but that's not recommended here, as log messages should all be pre-formatted via f-strings or string.format calls, to make them independent of the logging implementation.
2. **BREAKING**: This will change the trace logging format from `[18:30:35,123]` to `[18:30:35.123456]`
3. **BREAKING**: The LogRecord's msecs won't get used for formatting the trace log and instead its `created` attribute gets used via `datetime.fromtimestamp(record.created)` and `datetime.strftime("%f")`, as it already contains the microseconds value. This also fixes a formatting bug that could result into logging something like this `[18:27:35,1000]`, which was supposed to be fixed by #3025.
4. I don't know why `ConsoleOutput` had the `set_level` method for changing the log level of the main logger class. `ConsoleOutput` is supposed to write to stdout/stderr directly and is thus unrelated to the logger.

bastimeyer: I will open a PR later that corrects all log calls in every Streamlink module. After that PR has been merged, I'm going to remove the custom `LogRecord` class and `makeRecord` method here, as they can be removed then.

Patch:
diff --git a/src/streamlink/logger.py b/src/streamlink/logger.py
index ceb1bc47..64985bec 100644
--- a/src/streamlink/logger.py
+++ b/src/streamlink/logger.py
@@ -1,6 +1,5 @@
+from datetime import datetime
 import logging
-import sys
-import warnings
 from logging import NOTSET, ERROR, WARN, INFO, DEBUG, CRITICAL
 from threading import Lock
 
@@ -17,93 +16,31 @@ levels = [name for _, name in _levelToName.items()]
 _config_lock = Lock()
 
 
-class _CompatLogRecord(logging.LogRecord):
-    """
-    LogRecord wrapper to include sinfo for Python 3 by not Python 2
-    """
-
-    def __init__(self, name, level, pathname, lineno, msg, args, exc_info, func=None, sinfo=None, **kwargs):
-        super(_CompatLogRecord, self).__init__(name, level, pathname, lineno, msg, args, exc_info, func=func,
-                                               sinfo=sinfo, **kwargs)
-
-
-class _LogRecord(_CompatLogRecord):
-    def getMessage(self):
-        """
-        Return the message for this LogRecord.
-
-        Return the message for this LogRecord after merging any user-supplied
-        arguments with the message.
-        """
-        msg = self.msg
-        if self.args:
-            msg = msg.format(*self.args)
-        return msg
-
-
-class StreamlinkLogger(logging.getLoggerClass(), object):
-    def __init__(self, name, level=logging.NOTSET):
-        super(StreamlinkLogger, self).__init__(name, level)
-
+class StreamlinkLogger(logging.getLoggerClass()):
     def trace(self, message, *args, **kws):
         if self.isEnabledFor(TRACE):
             self._log(TRACE, message, args, **kws)
 
-    def makeRecord(self, name, level, fn, lno, msg, args, exc_info,
-                   func=None, extra=None, sinfo=None):
-        """
-        A factory method which can be overridden in subclasses to create
-        specialized LogRecords.
-        """
-        if name.startswith("streamlink"):
-            rv = _LogRecord(name, level, fn, lno, msg, args, exc_info, func, sinfo)
-        else:
-            rv = _CompatLogRecord(name, level, fn, lno, msg, args, exc_info, func, sinfo)
-        if extra is not None:
-            for key in extra:
-                if (key in ["message", "asctime"]) or (key in rv.__dict__):
-                    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
-                rv.__dict__[key] = extra[key]
-        return rv
-
-    def set_level(self, level):
-        self.setLevel(level)
-
-    @staticmethod
-    def new_module(name):
-        warnings.warn("Logger.new_module has been deprecated, use the standard logging.getLogger method",
-                      category=DeprecationWarning, stacklevel=2)
-        return logging.getLogger("streamlink.{0}".format(name))
-
-    @staticmethod
-    def set_output(output):
-        """
-        No-op, must be set in the log handler
-        """
-        warnings.warn("Logger.set_output has been deprecated, use the standard logging module",
-                      category=DeprecationWarning, stacklevel=2)
-
-
-logging.setLoggerClass(StreamlinkLogger)
-root = logging.getLogger("streamlink")
-root.setLevel(logging.WARNING)
-
 
 class StringFormatter(logging.Formatter):
-    def __init__(self, fmt, datefmt=None, style='%', remove_base=None):
-        super(StringFormatter, self).__init__(fmt, datefmt=datefmt, style=style)
+    def __init__(self, fmt, datefmt=None, style="%", remove_base=None):
         if style not in ("{", "%"):
             raise ValueError("Only {} and % formatting styles are supported")
+        super().__init__(fmt, datefmt=datefmt, style=style)
         self.style = style
         self.fmt = fmt
         self.remove_base = remove_base or []
+        self._usesTime = (style == "%" and "%(asctime)" in fmt) or (style == "{" and "{asctime}" in fmt)
 
     def usesTime(self):
-        return (self.style == "%" and "%(asctime)" in self.fmt) or (self.style == "{" and "{asctime}" in self.fmt)
+        return self._usesTime
+
+    def formatTime(self, record, datefmt=None):
+        tdt = datetime.fromtimestamp(record.created)
+
+        return tdt.strftime(datefmt or self.default_time_format)
 
     def formatMessage(self, record):
-        if self.usesTime():
-            record.asctime = self.formatTime(record, self.datefmt)
         if self.style == "{":
             return self.fmt.format(**record.__dict__)
         else:
@@ -114,92 +51,21 @@ class StringFormatter(logging.Formatter):
             record.name = record.name.replace(rbase + ".", "")
         record.levelname = record.levelname.lower()
 
-        record.message = record.getMessage()
-        if self.usesTime():
-            record.asctime = self.formatTime(record, self.datefmt)
-
-        s = self.formatMessage(record)
-
-        if record.exc_info:
-            # Cache the traceback text to avoid converting it multiple times
-            # (it's constant anyway)
-            if not record.exc_text:
-                record.exc_text = self.formatException(record.exc_info)
-        if record.exc_text:
-            s += "\n" if not s.endswith("\n") else "" + record.exc_text
-        return s
-
-
-class Logger(object):
-    Levels = levels
-    Format = "[{name}][{levelname}] {message}"
-    root_name = "streamlink_old"
-
-    def __init__(self):
-        warnings.warn("Logger class has been deprecated, use the standard logging module",
-                      category=DeprecationWarning, stacklevel=2)
-        self.root = logging.getLogger(self.root_name)
-        root.propagate = False
-        self.handler = logging.StreamHandler(sys.stdout)
-        self.handler.setFormatter(StringFormatter(self.Format, style="{", remove_base=[self.root_name]))
-        self.root.addHandler(self.handler)
-        self.set_level("info")
-
-    @classmethod
-    def get_logger(cls, name):
-        return logging.getLogger("{0}.{1}".format(cls.root_name, name))
-
-    def new_module(self, module):
-        return LoggerModule(self, module)
-
-    def set_level(self, level):
-        self.root.setLevel(level)
-
-    def set_output(self, output):
-        self.handler.stream = output
-
-    def msg(self, module, level, msg, *args, **kwargs):
-        log = self.get_logger(module)
-        log.log(level, msg, *args)
-
-
-class LoggerModule(object):
-    def __init__(self, manager, module):
-        warnings.warn("LoggerModule class has been deprecated, use the standard logging module",
-                      category=DeprecationWarning, stacklevel=2)
-        self.manager = manager
-        self.module = module
-
-    def error(self, msg, *args, **kwargs):
-        self.manager.msg(self.module, ERROR, msg, *args, **kwargs)
-
-    def warning(self, msg, *args, **kwargs):
-        self.manager.msg(self.module, WARN, msg, *args, **kwargs)
-
-    def info(self, msg, *args, **kwargs):
-        self.manager.msg(self.module, INFO, msg, *args, **kwargs)
-
-    def debug(self, msg, *args, **kwargs):
-        self.manager.msg(self.module, DEBUG, msg, *args, **kwargs)
-
-
-BASIC_FORMAT = "[{name}][{levelname}] {message}"
-FORMAT_STYLE = "{"
-REMOVE_BASE = ["streamlink", "streamlink_cli"]
+        return super().format(record)
 
 
 def basicConfig(**kwargs):
     with _config_lock:
         filename = kwargs.get("filename")
         if filename:
-            mode = kwargs.get("filemode", 'a')
+            mode = kwargs.get("filemode", "a")
             handler = logging.FileHandler(filename, mode)
         else:
             stream = kwargs.get("stream")
             handler = logging.StreamHandler(stream)
         fs = kwargs.get("format", BASIC_FORMAT)
         style = kwargs.get("style", FORMAT_STYLE)
-        dfs = kwargs.get("datefmt", None)
+        dfs = kwargs.get("datefmt", FORMAT_DATE)
         remove_base = kwargs.get("remove_base", REMOVE_BASE)
 
         formatter = StringFormatter(fs, dfs, style=style, remove_base=remove_base)
@@ -211,4 +77,15 @@ def basicConfig(**kwargs):
             root.setLevel(level)
 
 
-__all__ = ["StreamlinkLogger", "Logger", "basicConfig", "root", "levels"]
+BASIC_FORMAT = "[{name}][{levelname}] {message}"
+FORMAT_STYLE = "{"
+FORMAT_DATE = "%H:%M:%S"
+REMOVE_BASE = ["streamlink", "streamlink_cli"]
+
+
+logging.setLoggerClass(StreamlinkLogger)
+root = logging.getLogger("streamlink")
+root.setLevel(logging.WARNING)
+
+
+__all__ = ["StreamlinkLogger", "basicConfig", "root", "levels"]
diff --git a/src/streamlink/session.py b/src/streamlink/session.py
index 1d969a84..4d773689 100644
--- a/src/streamlink/session.py
+++ b/src/streamlink/session.py
@@ -8,7 +8,7 @@ import requests
 
 from collections import OrderedDict
 
-from streamlink.logger import StreamlinkLogger, Logger
+from streamlink.logger import StreamlinkLogger
 from streamlink.utils import update_scheme, memoize
 from streamlink.utils.l10n import Localization
 from . import plugins, __version__
@@ -89,17 +89,6 @@ class Streamlink(object):
             self.options.update(options)
         self.plugins = OrderedDict({})
         self.load_builtin_plugins()
-        self._logger = None
-
-    @property
-    def logger(self):
-        """
-        Backwards compatible logger property
-        :return: Logger instance
-        """
-        if not self._logger:
-            self._logger = Logger()
-        return self._logger
 
     def set_option(self, key, value):
         """Sets general options used by plugins and streams originating
@@ -367,25 +356,6 @@ class Streamlink(object):
             plugin = self.plugins[plugin]
             return plugin.get_option(key)
 
-    def set_loglevel(self, level):
-        """Sets the log level used by this session.
-
-        Valid levels are: "none", "error", "warning", "info"
-        and "debug".
-
-        :param level: level of logging to output
-
-        """
-        self.logger.set_level(level)
-
-    def set_logoutput(self, output):
-        """Sets the log output used by this session.
-
-        :param output: a file-like object with a write method
-
-        """
-        self.logger.set_output(output)
-
     @memoize
     def resolve_url(self, url, follow_redirect=True):
         """Attempts to find a plugin that can use this URL.
diff --git a/src/streamlink_cli/console.py b/src/streamlink_cli/console.py
index 6765e571..4cc8770b 100644
--- a/src/streamlink_cli/console.py
+++ b/src/streamlink_cli/console.py
@@ -30,15 +30,10 @@ class ConsoleUserInputRequester(UserInputRequester):
 
 
 class ConsoleOutput(object):
-    def __init__(self, output, streamlink, json=False):
-        self.streamlink = streamlink
-
+    def __init__(self, output, json=False):
         self.json = json
         self.output = output
 
-    def set_level(self, level):
-        self.streamlink.set_loglevel(level)
-
     def set_output(self, output):
         self.output = output
 
diff --git a/src/streamlink_cli/main.py b/src/streamlink_cli/main.py
index a8e33bae..b1038708 100644
--- a/src/streamlink_cli/main.py
+++ b/src/streamlink_cli/main.py
@@ -691,8 +691,7 @@ def setup_console(output):
     global console
 
     # All console related operations is handled via the ConsoleOutput class
-    console = ConsoleOutput(output, streamlink)
-    console.json = args.json
+    console = ConsoleOutput(output, args.json)
 
     # Handle SIGTERM just like SIGINT
     signal.signal(signal.SIGTERM, signal.default_int_handler)
@@ -959,10 +958,13 @@ def check_version(force=False):
 
 
 def setup_logging(stream=sys.stdout, level="info"):
-    fmt = ("[{asctime},{msecs:03.0f}]" if level == "trace" else "") + "[{name}][{levelname}] {message}"
-    logger.basicConfig(stream=stream, level=level,
-                       format=fmt, style="{",
-                       datefmt="%H:%M:%S")
+    logger.basicConfig(
+        stream=stream,
+        level=level,
+        style="{",
+        format=("[{asctime}]" if level == "trace" else "") + "[{name}][{levelname}] {message}",
+        datefmt="%H:%M:%S" + (".%f" if level == "trace" else "")
+    )
 
 
 def main():


Test patch:
diff --git a/tests/test_console.py b/tests/test_console.py
index 2bc7e711..43e300f7 100644
--- a/tests/test_console.py
+++ b/tests/test_console.py
@@ -1,6 +1,6 @@
 from io import StringIO
 import unittest
-from unittest.mock import Mock, patch
+from unittest.mock import patch
 
 from streamlink_cli.console import ConsoleOutput
 
@@ -13,41 +13,41 @@ class _TestObj(object):
 class TestConsole(unittest.TestCase):
     def test_msg_format(self):
         output = StringIO()
-        console = ConsoleOutput(output, Mock())
+        console = ConsoleOutput(output)
         console.msg("{0} - {1}", 1, 2)
 
         self.assertEqual("1 - 2\n", output.getvalue())
 
     def test_msg_format_kw(self):
         output = StringIO()
-        console = ConsoleOutput(output, Mock())
+        console = ConsoleOutput(output)
         console.msg("{test} - {what}", test=1, what=2)
 
         self.assertEqual("1 - 2\n", output.getvalue())
 
     def test_msg_json_not_set(self):
         output = StringIO()
-        console = ConsoleOutput(output, Mock())
+        console = ConsoleOutput(output)
         self.assertEqual(None, console.msg_json({"test": 1}))
         self.assertEqual("", output.getvalue())
 
     def test_msg_json(self):
         output = StringIO()
-        console = ConsoleOutput(output, Mock(), json=True)
+        console = ConsoleOutput(output, json=True)
         console.msg_json({"test": 1})
         self.assertEqual('''{\n  "test": 1\n}\n''', output.getvalue())
 
     def test_msg_json_object(self):
         output = StringIO()
         test_obj = _TestObj()
-        console = ConsoleOutput(output, Mock(), json=True)
+        console = ConsoleOutput(output, json=True)
         console.msg_json(test_obj)
         self.assertEqual('''{\n  "test": 1\n}\n''', output.getvalue())
 
     @patch('streamlink_cli.console.sys.exit')
     def test_msg_json_error(self, mock_exit):
         output = StringIO()
-        console = ConsoleOutput(output, Mock(), json=True)
+        console = ConsoleOutput(output, json=True)
         console.msg_json({"error": "bad"})
         self.assertEqual('''{\n  "error": "bad"\n}\n''', output.getvalue())
         mock_exit.assert_called_with(1)
@@ -55,7 +55,7 @@ class TestConsole(unittest.TestCase):
     @patch('streamlink_cli.console.sys.exit')
     def test_exit(self, mock_exit):
         output = StringIO()
-        console = ConsoleOutput(output, Mock())
+        console = ConsoleOutput(output)
         console.exit("error")
         self.assertEqual("error: error\n", output.getvalue())
         mock_exit.assert_called_with(1)
@@ -63,17 +63,11 @@ class TestConsole(unittest.TestCase):
     @patch('streamlink_cli.console.sys.exit')
     def test_exit_json(self, mock_exit):
         output = StringIO()
-        console = ConsoleOutput(output, Mock(), json=True)
+        console = ConsoleOutput(output, json=True)
         console.exit("error")
         self.assertEqual('''{\n  "error": "error"\n}\n''', output.getvalue())
         mock_exit.assert_called_with(1)
 
-    def test_set_level(self):
-        session = Mock()
-        console = ConsoleOutput(Mock(), session)
-        console.set_level("debug")
-        session.set_loglevel.assert_called_with("debug")
-
     @patch('streamlink_cli.console.sys.stderr')
     @patch('streamlink_cli.console.input')
     @patch('streamlink_cli.console.sys.stdin.isatty')
diff --git a/tests/test_log.py b/tests/test_log.py
index 53eb582b..900f6a54 100644
--- a/tests/test_log.py
+++ b/tests/test_log.py
@@ -1,17 +1,18 @@
+from datetime import datetime
 from io import StringIO
 import logging
 import unittest
-import warnings
 
-from streamlink import logger, Streamlink
-from tests import catch_warnings
+import freezegun
+
+from streamlink import logger
 
 
 class TestLogging(unittest.TestCase):
     @classmethod
-    def _new_logger(cls):
+    def _new_logger(cls, format="[{name}][{levelname}] {message}", style="{", **params):
         output = StringIO()
-        logger.basicConfig(stream=output, format="[{name}][{levelname}] {message}", style="{")
+        logger.basicConfig(stream=output, format=format, style=style, **params)
         return logging.getLogger("streamlink.test"), output
 
     def test_level(self):
@@ -48,59 +49,27 @@ class TestLogging(unittest.TestCase):
         log.debug("test")
         self.assertEqual(output.getvalue(), "[test][debug] test\n")
 
-    def test_log_unicode(self):
-        log, output = self._new_logger()
+    def test_style_percent(self):
+        log, output = self._new_logger(style="%", format="[%(name)s][%(levelname)s] %(message)s")
         logger.root.setLevel("info")
-        log.info(u"Special Character: Ѩ")
-        self.assertEqual(output.getvalue(), u"[test][info] Special Character: Ѩ\n")
-
-
-class TestDeprecatedLogger(unittest.TestCase):
-    def setUp(self):
-        warnings.resetwarnings()
-        warnings.simplefilter('always', DeprecationWarning)  # turn off filter
-
-    def tearDown(self):
-        warnings.simplefilter('default', DeprecationWarning)  # restore filter
-
-    def _new_logger(self):
-        output = StringIO()
-        manager = logger.Logger()
-        manager.set_output(output)
-        return manager, output
-
-    @catch_warnings()
-    def test_deprecated_level(self):
-        manager, output = self._new_logger()
-
-        with warnings.catch_warnings(record=True):
-            log = manager.new_module("test_level")
-            log.debug("test")
-            self.assertEqual(output.tell(), 0)
-            manager.set_level("debug")
-            log.debug("test")
-            self.assertNotEqual(output.tell(), 0)
-
-    @catch_warnings()
-    def test_deprecated_output(self):
-        manager, output = self._new_logger()
-
-        log = manager.new_module("test_output")
-        manager.set_level("debug")
-        log.debug("test")
-        self.assertEqual(output.getvalue(), "[test_output][debug] test\n")
-
-    @catch_warnings()
-    def test_deprecated_session_logger(self):
-        session = Streamlink()
-        output = StringIO()
-
-        new_log = session.logger.new_module("test")
-        session.set_logoutput(output)
-        session.set_loglevel("info")
-
-        new_log.info("test1")
-
-        # regular python loggers shouldn't log here
-        logging.getLogger("streamlink.test").critical("should not log")
-        self.assertEqual(output.getvalue(), "[test][info] test1\n")
+        log.info("test")
+        self.assertEqual(output.getvalue(), "[test][info] test\n")
+
+    def test_style_invalid(self):
+        with self.assertRaises(ValueError) as cm:
+            self._new_logger(style="invalid")
+        self.assertEqual(str(cm.exception), "Only {} and % formatting styles are supported")
+
+    def test_datefmt_default(self):
+        with freezegun.freeze_time(datetime(2000, 1, 2, 3, 4, 5, 123456)):
+            log, output = self._new_logger(format="[{asctime}][{name}][{levelname}] {message}")
+            logger.root.setLevel("info")
+            log.info("test")
+            self.assertEqual(output.getvalue(), "[03:04:05][test][info] test\n")
+
+    def test_datefmt_custom(self):
+        with freezegun.freeze_time(datetime(2000, 1, 2, 3, 4, 5, 123456)):
+            log, output = self._new_logger(format="[{asctime}][{name}][{levelname}] {message}", datefmt="%H:%M:%S.%f")
+            logger.root.setLevel("info")
+            log.info("test")
+            self.assertEqual(output.getvalue(), "[03:04:05.123456][test][info] test\n")