Merge branch 'json-logging' of https://github.com/Kingdread/qutebrowser into Kingdread-json-logging

qutebrowser/qutebrowser.py

@@ -86,6 +86,8 @@ def get_argparser():
                        default=2000, type=int)
     debug.add_argument('--debug', help="Turn on debugging options.",
                        action='store_true')
+    debug.add_argument('--json-logging', action='store_true', help="Output log"
+                       " lines in JSON format (one object per line).")
     debug.add_argument('--nocolor', help="Turn off colored logging.",
                        action='store_false', dest='color')
     debug.add_argument('--force-color', help="Force colored logging",

qutebrowser/utils/log.py

@@ -28,6 +28,7 @@ import collections
 import faulthandler
 import traceback
 import warnings
+import json
 
 from PyQt5 import QtCore
 # Optional imports
@@ -142,7 +143,7 @@ def init_log(args):
         numeric_level = logging.DEBUG
 
     console, ram = _init_handlers(numeric_level, args.color, args.force_color,
-                                  args.loglines)
+                                  args.json_logging, args.loglines)
     root = logging.getLogger()
     if console is not None:
         if args.logfilter is not None:
@@ -166,17 +167,18 @@ def disable_qt_msghandler():
         QtCore.qInstallMessageHandler(old_handler)
 
 
-def _init_handlers(level, color, force_color, ram_capacity):
+def _init_handlers(level, color, force_color, json_logging, ram_capacity):
     """Init log handlers.
 
     Args:
         level: The numeric logging level.
         color: Whether to use color if available.
         force_color: Force colored output.
+        json_logging: Output log lines in JSON (this disables all colors).
     """
     global ram_handler
     console_fmt, ram_fmt, html_fmt, use_colorama = _init_formatters(
-        level, color, force_color)
+        level, color, force_color, json_logging)
 
     if sys.stderr is None:
         console_handler = None
@@ -201,13 +203,14 @@ def _init_handlers(level, color, force_color, ram_capacity):
     return console_handler, ram_handler
 
 
-def _init_formatters(level, color, force_color):
+def _init_formatters(level, color, force_color, json_logging):
     """Init log formatters.
 
     Args:
         level: The numeric logging level.
         color: Whether to use color if available.
         force_color: Force colored output.
+        json_logging: Format lines as JSON (disables all color).
 
     Return:
         A (console_formatter, ram_formatter, use_colorama) tuple.
@@ -222,6 +225,10 @@ def _init_formatters(level, color, force_color):
     if sys.stderr is None:
         return None, ram_formatter, html_formatter, False
 
+    if json_logging:
+        console_formatter = JSONFormatter()
+        return console_formatter, ram_formatter, html_formatter, False
+
     use_colorama = False
     color_supported = os.name == 'posix' or colorama
 
@@ -538,3 +545,18 @@ class HTMLFormatter(logging.Formatter):
     def formatTime(self, record, datefmt=None):
         out = super().formatTime(record, datefmt)
         return pyhtml.escape(out)
+
+
+class JSONFormatter(logging.Formatter):
+
+    """Formatter for JSON-encoded log messages."""
+
+    def format(self, record):
+        obj = {}
+        for field in ['created', 'levelname', 'name', 'module', 'funcName',
+                      'lineno', 'levelno']:
+            obj[field] = getattr(record, field)
+        obj['message'] = record.getMessage()
+        if record.exc_info is not None:
+            obj['traceback'] = super().formatException(record.exc_info)
+        return json.dumps(obj)

qutebrowser/utils/message.py

@@ -50,8 +50,8 @@ def _log_stack(typ, stack):
         stack = stack.splitlines()
     except AttributeError:
         pass
-    indented = '\n'.join('  ' + line.rstrip() for line in stack)
+    stack_text = '\n'.join(line.rstrip() for line in stack)
-    log.message.debug("Stack for {} message:\n{}".format(typ, indented))
+    log.message.debug("Stack for {} message:\n{}".format(typ, stack_text))
 
 
 def _wrapper(win_id, method_name, text, *args, **kwargs):

tests/end2end/fixtures/quteprocess.py

@@ -29,6 +29,7 @@ import logging
 import tempfile
 import contextlib
 import itertools
+import json
 
 import yaml
 import pytest
@@ -61,62 +62,65 @@ class LogLine(testprocess.Line):
     """A parsed line from the qutebrowser log output.
 
     Attributes:
-        timestamp/loglevel/category/module/function/line/message:
+        timestamp/loglevel/category/module/function/line/message/levelname:
             Parsed from the log output.
         expected: Whether the message was expected or not.
     """
 
-    LOG_RE = re.compile(r"""
-        (?P<timestamp>\d\d:\d\d:\d\d)
-        \ (?P<loglevel>VDEBUG|DEBUG|INFO|WARNING|ERROR)
-        \ +(?P<category>[\w.]+)
-        \ +(?P<module>(\w+|Unknown\ module)):
-           (?P<function>[^"][^:]*|"[^"]+"):
-           (?P<line>\d+)
-        \ (?P<message>.+)
-    """, re.VERBOSE)
-
     def __init__(self, data):
         super().__init__(data)
-        match = self.LOG_RE.match(data)
+        try:
-        if match is None:
+            line = json.loads(data)
+        except ValueError:
             raise testprocess.InvalidLine(data)
 
-        self.timestamp = datetime.datetime.strptime(match.group('timestamp'),
+        self.timestamp = datetime.datetime.fromtimestamp(line['created'])
-                                                    '%H:%M:%S')
+        self.loglevel = line['levelno']
-        loglevel = match.group('loglevel')
+        self.levelname = line['levelname']
-        if loglevel == 'VDEBUG':
+        self.category = line['name']
-            self.loglevel = log.VDEBUG_LEVEL
+        self.module = line['module']
-        else:
+        self.function = line['funcName']
-            self.loglevel = getattr(logging, loglevel)
+        self.line = line['lineno']
-
+        if self.function is None and self.line == 0:
-        self.category = match.group('category')
-
-        module = match.group('module')
-        if module == 'Unknown module':
-            self.module = None
-        else:
-            self.module = module
-
-        function = match.group('function')
-        if function == 'none':
-            self.function = None
-        else:
-            self.function = function.strip('"')
-
-        line = int(match.group('line'))
-        if self.function is None and line == 0:
             self.line = None
-        else:
+        self.traceback = line.get('traceback')
-            self.line = line
 
+        self.full_message = line['message']
         msg_match = re.match(r'^(\[(?P<prefix>\d+s ago)\] )?(?P<message>.*)',
-                             match.group('message'))
+                             self.full_message, re.DOTALL)
         self.prefix = msg_match.group('prefix')
         self.message = msg_match.group('message')
 
         self.expected = is_ignored_qt_message(self.message)
 
+    def __str__(self):
+        return self.formatted_str(colorized=False)
+
+    def formatted_str(self, colorized=True):
+        """Return a formatted colorized line.
+
+        This returns a line like qute without --json-logging would produce.
+
+        Args:
+            colorized: If True, ANSI color codes will be embedded.
+        """
+        r = logging.LogRecord(self.category, self.loglevel, '', self.line,
+                              self.message, (), None)
+        # Patch some attributes of the LogRecord
+        if self.line is None:
+            r.line = 0
+        r.created = self.timestamp.timestamp()
+        r.module = self.module
+        r.funcName = self.function
+
+        formatter = log.ColoredFormatter(log.EXTENDED_FMT, log.DATEFMT, '{',
+                                         use_colors=colorized)
+        result = formatter.format(r)
+        # Manually append the stringified traceback if one is present
+        if self.traceback is not None:
+            result += '\n' + self.traceback
+        return result
+
 
 class QuteProc(testprocess.Process):
 
@@ -169,24 +173,17 @@ class QuteProc(testprocess.Process):
             self.ready.emit()
 
     def _parse_line(self, line):
-        # http://stackoverflow.com/a/14693789/2085149
-        colored_line = line
-        ansi_escape = re.compile(r'\x1b[^m]*m')
-        line = ansi_escape.sub('', line)
-
         try:
             log_line = LogLine(line)
         except testprocess.InvalidLine:
-            if line.startswith('  '):
+            if not line.strip():
-                # Multiple lines in some log output...
-                return None
-            elif not line.strip():
                 return None
             elif is_ignored_qt_message(line):
                 return None
             else:
                 raise
 
+        colored_line = log_line.formatted_str()
         self._log(colored_line)
 
         start_okay_message_load = (
@@ -243,7 +240,7 @@ class QuteProc(testprocess.Process):
 
     def _default_args(self):
         return ['--debug', '--no-err-windows', '--temp-basedir',
-                '--force-color', 'about:blank']
+                '--json-logging', 'about:blank']
 
     def path_to_url(self, path, *, port=None, https=False):
         """Get a URL based on a filename for the localhost webserver.

tests/end2end/fixtures/test_quteprocess.py

@@ -21,6 +21,7 @@
 
 import logging
 import datetime
+import json
 
 import pytest
 
@@ -88,10 +89,11 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
 @pytest.mark.parametrize('data, attrs', [
     (
         # Normal message
-        '01:02:03 DEBUG    init       earlyinit:init_log:280 Log initialized.',
+        '{"created": 0, "levelname": "DEBUG", "name": "init", "module": '
+        '"earlyinit", "funcName": "init_log", "lineno": 280, "levelno": 10, '
+        '"message": "Log initialized."}',
         {
-            'timestamp': datetime.datetime(year=1900, month=1, day=1,
+            'timestamp': datetime.datetime.fromtimestamp(0),
-                                           hour=1, minute=2, second=3),
             'loglevel': logging.DEBUG,
             'category': 'init',
             'module': 'earlyinit',
@@ -103,25 +105,32 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
     ),
     (
         # VDEBUG
-        '00:00:00 VDEBUG    foo       foo:foo:0 test',
+        '{"created": 0, "levelname": "VDEBUG", "name": "foo", "module": '
+        '"foo", "funcName": "foo", "lineno": 0, "levelno": 9, "message": ""}',
         {'loglevel': log.VDEBUG_LEVEL}
     ),
     (
         # Unknown module
-        '00:00:00 WARNING  qt         Unknown module:none:0 test',
+        '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": '
+        'null, "funcName": null, "lineno": 0, "levelno": 10, "message": '
+        '"test"}',
         {'module': None, 'function': None, 'line': None},
     ),
     (
         # Expected message
-        '00:00:00 VDEBUG    foo       foo:foo:0 SpellCheck: test',
+        '{"created": 0, "levelname": "VDEBUG", "name": "foo", "module": '
+        '"foo", "funcName": "foo", "lineno": 0, "levelno": 9, "message": '
+        '"SpellCheck: test"}',
         {'expected': True},
     ),
     (
         # Weird Qt location
-        '00:00:00 DEBUG    qt         qnetworkreplyhttpimpl:"void '
+        '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": '
-        'QNetworkReplyHttpImplPrivate::error(QNetworkReply::NetworkError, '
+        '"qnetworkreplyhttpimpl", "funcName": '
-        'const QString&)":1929 QNetworkReplyImplPrivate::error: Internal '
+        '"void QNetworkReplyHttpImplPrivate::error('
-        'problem, this method must only be called once.',
+        'QNetworkReply::NetworkError, const QString&)", "lineno": 1929, '
+        '"levelno": 10, "message": "QNetworkReplyImplPrivate::error: '
+        'Internal problem, this method must only be called once."}',
         {
             'module': 'qnetworkreplyhttpimpl',
             'function': 'void QNetworkReplyHttpImplPrivate::error('
@@ -130,10 +139,11 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
         }
     ),
     (
-        '00:00:00 WARNING  qt         qxcbxsettings:"QXcbXSettings::'
+        '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": '
-        'QXcbXSettings(QXcbScreen*)":233 '
+        '"qxcbxsettings", "funcName": "QXcbXSettings::QXcbXSettings('
-        'QXcbXSettings::QXcbXSettings(QXcbScreen*) Failed to get selection '
+        'QXcbScreen*)", "lineno": 233, "levelno": 10, "message": '
-        'owner for XSETTINGS_S atom ',
+        '"QXcbXSettings::QXcbXSettings(QXcbScreen*) Failed to get selection '
+        'owner for XSETTINGS_S atom"}',
         {
             'module': 'qxcbxsettings',
             'function': 'QXcbXSettings::QXcbXSettings(QXcbScreen*)',
@@ -142,14 +152,18 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
     ),
     (
         # With [2s ago] marker
-        '00:00:00 DEBUG    foo       foo:foo:0 [2s ago] test',
+        '{"created": 0, "levelname": "DEBUG", "name": "foo", "module": '
+        '"foo", "funcName": "foo", "lineno": 0, "levelno": 10, "message": '
+        '"[2s ago] test"}',
         {'prefix': '2s ago', 'message': 'test'}
     ),
     (
         # ResourceWarning
-        "00:00:00 WARNING  py.warnings app:qt_mainloop:121 "
+        '{"created": 0, "levelname": "WARNING", "name": "py.warnings", '
-        ".../app.py:121: ResourceWarning: unclosed file <_io.TextIOWrapper "
+        '"module": "app", "funcName": "qt_mainloop", "lineno": 121, "levelno":'
-        "name=18 mode='r' encoding='UTF-8'>",
+        ' 30, "message": '
+        '".../app.py:121: ResourceWarning: unclosed file <_io.TextIOWrapper '
+        'name=18 mode=\'r\' encoding=\'UTF-8\'>"}',
         {'category': 'py.warnings'}
     ),
 ], ids=['normal', 'vdebug', 'unknown module', 'expected message',
@@ -162,6 +176,41 @@ def test_log_line_parse(data, attrs):
         assert actual == expected, name
 
 
+@pytest.mark.parametrize('data, colorized, expected', [
+    (
+        {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
+        False,
+        '{timestamp} DEBUG    foo        bar:qux:10 quux',
+    ),
+    # Traceback attached
+    (
+        {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux',
+         'traceback': 'Traceback (most recent call last):\n    here be '
+         'dragons'},
+        False,
+        '{timestamp} DEBUG    foo        bar:qux:10 quux\n'
+        'Traceback (most recent call last):\n'
+        '    here be dragons',
+    ),
+    # Colorized
+    (
+        {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
+        True,
+        '\033[32m{timestamp}\033[0m \033[37mDEBUG   \033[0m \033[36mfoo     '
+        '   bar:qux:10\033[0m \033[37mquux\033[0m',
+    ),
+], ids=['normal', 'traceback', 'colored'])
+def test_log_line_formatted(data, colorized, expected):
+    line = json.dumps(data)
+    record = quteprocess.LogLine(line)
+    ts = datetime.datetime.fromtimestamp(data['created']).strftime('%H:%M:%S')
+    expected = expected.format(timestamp=ts)
+    assert record.formatted_str(colorized=colorized) == expected
+
+
 def test_log_line_no_match():
     with pytest.raises(testprocess.InvalidLine):
         quteprocess.LogLine("Hello World!")

tests/end2end/test_invocations.py

@@ -21,6 +21,8 @@
 
 import pytest
 
+BASE_ARGS = ['--debug', '--json-logging', '--no-err-windows', 'about:blank']
+
 
 @pytest.fixture
 def temp_basedir_env(tmpdir):
@@ -52,7 +54,7 @@ def temp_basedir_env(tmpdir):
 @pytest.mark.linux
 def test_no_config(temp_basedir_env, quteproc_new):
     """Test starting with -c ""."""
-    args = ['--debug', '--no-err-windows', '-c', '', 'about:blank']
+    args = ['-c', ''] + BASE_ARGS
     quteproc_new.start(args, env=temp_basedir_env)
     quteproc_new.send_cmd(':quit')
     quteproc_new.wait_for_quit()
@@ -61,7 +63,7 @@ def test_no_config(temp_basedir_env, quteproc_new):
 @pytest.mark.linux
 def test_no_cache(temp_basedir_env, quteproc_new):
     """Test starting with --cachedir=""."""
-    args = ['--debug', '--no-err-windows', '--cachedir=', 'about:blank']
+    args = ['--cachedir='] + BASE_ARGS
     quteproc_new.start(args, env=temp_basedir_env)
     quteproc_new.send_cmd(':quit')
     quteproc_new.wait_for_quit()
@@ -73,7 +75,7 @@ def test_ascii_locale(httpbin, tmpdir, quteproc_new):
 
     https://github.com/The-Compiler/qutebrowser/issues/908
     """
-    args = ['--debug', '--no-err-windows', '--temp-basedir', 'about:blank']
+    args = ['--temp-basedir'] + BASE_ARGS
     quteproc_new.start(args, env={'LC_ALL': 'C'})
     quteproc_new.set_setting('storage', 'download-directory', str(tmpdir))
     quteproc_new.set_setting('storage', 'prompt-download-directory', 'false')
@@ -89,7 +91,6 @@ def test_ascii_locale(httpbin, tmpdir, quteproc_new):
 
 def test_no_loglines(quteproc_new):
     """Test qute:log with --loglines=0."""
-    quteproc_new.start(args=['--debug', '--no-err-windows', '--temp-basedir',
+    quteproc_new.start(args=['--temp-basedir', '--loglines=0'] + BASE_ARGS)
-                             '--loglines=0', 'about:blank'])
     quteproc_new.open_path('qute:log')
     assert quteproc_new.get_content() == 'Log output was disabled.'

tests/unit/utils/test_log.py

@@ -218,7 +218,8 @@ class TestInitLog:
     def args(self):
         """Fixture providing an argparse namespace for init_log."""
         return argparse.Namespace(debug=True, loglevel='debug', color=True,
-                                  loglines=10, logfilter="", force_color=False)
+                                  loglines=10, logfilter="", force_color=False,
+                                  json_logging=False)
 
     def test_stderr_none(self, args):
         """Test init_log with sys.stderr = None."""