From 4a59a1f112c028a0013a199d7b6d74fc2a7839f9 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 00:12:51 +0200
Subject: [PATCH 01/17] log: implement JSON as logging output

Fixes #1501

Enabled via the --json-logging parameter.
---
 qutebrowser/qutebrowser.py                 |  2 +
 qutebrowser/utils/log.py                   | 28 ++++++--
 tests/end2end/fixtures/quteprocess.py      | 82 +++++++++-------------
 tests/end2end/fixtures/test_quteprocess.py |  1 +
 4 files changed, 62 insertions(+), 51 deletions(-)

diff --git a/qutebrowser/qutebrowser.py b/qutebrowser/qutebrowser.py
index cd0283c53..39c6e7a31 100644
--- a/qutebrowser/qutebrowser.py
+++ b/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",
diff --git a/qutebrowser/utils/log.py b/qutebrowser/utils/log.py
index bbf2827f2..1a25176ea 100644
--- a/qutebrowser/utils/log.py
+++ b/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,16 @@ 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()
+        return json.dumps(obj)
diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index ff5665d0d..2dd5f17d7 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/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,53 @@ 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)
-        if match is None:
+        try:
+            line = json.loads(data)
+        except json.decoder.JSONDecodeError:
             raise testprocess.InvalidLine(data)
 
-        self.timestamp = datetime.datetime.strptime(match.group('timestamp'),
-                                                    '%H:%M:%S')
-        loglevel = match.group('loglevel')
-        if loglevel == 'VDEBUG':
-            self.loglevel = log.VDEBUG_LEVEL
-        else:
-            self.loglevel = getattr(logging, loglevel)
-
-        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.line = line
+        self.timestamp = datetime.datetime.fromtimestamp(line['created'])
+        self.loglevel = line['levelno']
+        self.levelname = line['levelname']
+        self.category = line['name']
+        self.module = line['module']
+        self.function = line['funcName']
+        self.line = line['lineno']
 
+        self.full_message = line['message']
         msg_match = re.match(r'^(\[(?P<prefix>\d+s ago)\] )?(?P<message>.*)',
-                             match.group('message'))
+                             self.full_message)
         self.prefix = msg_match.group('prefix')
         self.message = msg_match.group('message')
 
         self.expected = is_ignored_qt_message(self.message)
 
+    def formatted_str(self):
+        """Return a formatted colorized line.strip()
+
+        This returns a line like qute without --json-logging would produce.
+        """
+        format_dict = {
+            'asctime': self.timestamp.strftime(log.DATEFMT),
+            'log_color': log.LOG_COLORS[self.levelname],
+            'levelname': self.levelname,
+            'reset': log.ColoredFormatter.RESET_ESCAPE,
+            'name': self.category,
+            'module': self.module,
+            'funcName': self.function,
+            'lineno': self.line,
+            'message': self.full_message,
+        }
+        format_dict.update(log.ColoredFormatter.COLOR_ESCAPES)
+        return log.EXTENDED_FMT.format_map(format_dict)
+
 
 class QuteProc(testprocess.Process):
 
@@ -169,11 +161,6 @@ 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:
@@ -187,6 +174,7 @@ class QuteProc(testprocess.Process):
             else:
                 raise
 
+        colored_line = log_line.formatted_str()
         self._log(colored_line)
 
         start_okay_message_load = (
@@ -243,7 +231,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.
diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py
index 06a020352..1ef5398ba 100644
--- a/tests/end2end/fixtures/test_quteprocess.py
+++ b/tests/end2end/fixtures/test_quteprocess.py
@@ -85,6 +85,7 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
         quteproc_process.after_test(did_fail=False)
 
 
+@pytest.mark.skip
 @pytest.mark.parametrize('data, attrs', [
     (
         # Normal message

From 49419bc4296badf186d7aac21dfe8ab7571ec405 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 13:13:36 +0200
Subject: [PATCH 02/17] tests: update test_invocations for --json-logging

---
 tests/end2end/test_invocations.py | 11 ++++++-----
 1 file changed, 6 insertions(+), 5 deletions(-)

diff --git a/tests/end2end/test_invocations.py b/tests/end2end/test_invocations.py
index bb6cc8b07..676c09bab 100644
--- a/tests/end2end/test_invocations.py
+++ b/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',
-                             '--loglines=0', 'about:blank'])
+    quteproc_new.start(args=['--temp-basedir', '--loglines=0'] + BASE_ARGS)
     quteproc_new.open_path('qute:log')
     assert quteproc_new.get_content() == 'Log output was disabled.'

From cf3930f9254360b948bf42149fbb531f9094bd6b Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 13:26:32 +0200
Subject: [PATCH 03/17] quteproc: except ValueError

There is no json.decoder.JSONDecodeError, it was a lie all along...
---
 tests/end2end/fixtures/quteprocess.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index 2dd5f17d7..47ab6fd1b 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -71,7 +71,7 @@ class LogLine(testprocess.Line):
         super().__init__(data)
         try:
             line = json.loads(data)
-        except json.decoder.JSONDecodeError:
+        except ValueError:
             raise testprocess.InvalidLine(data)
 
         self.timestamp = datetime.datetime.fromtimestamp(line['created'])

From d4a295b22ee52ee88d6f06842c1c7b4b99edaf17 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 13:31:37 +0200
Subject: [PATCH 04/17] tests: update test_log with json_logging namespace

---
 tests/unit/utils/test_log.py | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tests/unit/utils/test_log.py b/tests/unit/utils/test_log.py
index 49b1ac567..27332efdf 100644
--- a/tests/unit/utils/test_log.py
+++ b/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."""

From ae16240d41e5a39e6495caeb21ec65bf822e48c2 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 13:33:51 +0200
Subject: [PATCH 05/17] quteproc: fix docstring in formatted_str

Autocomplete was faster and inserted .strip() after line
---
 tests/end2end/fixtures/quteprocess.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index 47ab6fd1b..aace5374e 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -91,7 +91,7 @@ class LogLine(testprocess.Line):
         self.expected = is_ignored_qt_message(self.message)
 
     def formatted_str(self):
-        """Return a formatted colorized line.strip()
+        """Return a formatted colorized line.
 
         This returns a line like qute without --json-logging would produce.
         """

From b4022b9795c39b956fcb105f034fef9d16d5b8c5 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 20:55:16 +0200
Subject: [PATCH 06/17] quteproc: fix log_color in log message

This actually uses the escape code, not just the color name.
---
 tests/end2end/fixtures/quteprocess.py | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index aace5374e..7581fc232 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -95,9 +95,10 @@ class LogLine(testprocess.Line):
 
         This returns a line like qute without --json-logging would produce.
         """
+        log_color = log.LOG_COLORS[self.levelname]
         format_dict = {
             'asctime': self.timestamp.strftime(log.DATEFMT),
-            'log_color': log.LOG_COLORS[self.levelname],
+            'log_color': log.ColoredFormatter.COLOR_ESCAPES[log_color],
             'levelname': self.levelname,
             'reset': log.ColoredFormatter.RESET_ESCAPE,
             'name': self.category,

From 96b299a1fc90c80976ca4332186326ebd1e896ed Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 21:23:07 +0200
Subject: [PATCH 07/17] quteproc: Nicer output for unexpected errors

Instead of
    LogLine('{"levelname": "ERROR", ...}')
we get
    21:22:34 ERROR    downloads  mhtml ...
---
 tests/end2end/fixtures/quteprocess.py | 25 +++++++++++++++++++------
 1 file changed, 19 insertions(+), 6 deletions(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index 7581fc232..ab26e68ca 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -90,24 +90,37 @@ class LogLine(testprocess.Line):
 
         self.expected = is_ignored_qt_message(self.message)
 
-    def formatted_str(self):
-        """Return a formatted colorized line.
+    def __str__(self):
+        return self.formatted_str(colorized=False)
+
+    def formatted_str(self, colorized=True):
+        """Return a formatted colorized line.strip()
 
         This returns a line like qute without --json-logging would produce.
+
+        Args:
+            colorized: If True, ANSI color codes will be embedded.
         """
-        log_color = log.LOG_COLORS[self.levelname]
         format_dict = {
             'asctime': self.timestamp.strftime(log.DATEFMT),
-            'log_color': log.ColoredFormatter.COLOR_ESCAPES[log_color],
             'levelname': self.levelname,
-            'reset': log.ColoredFormatter.RESET_ESCAPE,
             'name': self.category,
             'module': self.module,
             'funcName': self.function,
             'lineno': self.line,
             'message': self.full_message,
         }
-        format_dict.update(log.ColoredFormatter.COLOR_ESCAPES)
+        if colorized:
+            log_color_name = log.LOG_COLORS[self.levelname]
+            log_color = log.ColoredFormatter.COLOR_ESCAPES[log_color_name]
+            format_dict['log_color'] = log_color
+            format_dict['reset'] = log.ColoredFormatter.RESET_ESCAPE
+            format_dict.update(log.ColoredFormatter.COLOR_ESCAPES)
+        else:
+            color_names = log.ColoredFormatter.COLOR_ESCAPES.keys()
+            format_dict['log_color'] = ''
+            format_dict['reset'] = ''
+            format_dict.update({color: '' for color in color_names})
         return log.EXTENDED_FMT.format_map(format_dict)
 
 

From cea32ea333799f9c2943be963c8972c2004a1c56 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 21:57:55 +0200
Subject: [PATCH 08/17] log: embed traceback in json object

---
 qutebrowser/utils/log.py              | 2 ++
 tests/end2end/fixtures/quteprocess.py | 6 +++++-
 2 files changed, 7 insertions(+), 1 deletion(-)

diff --git a/qutebrowser/utils/log.py b/qutebrowser/utils/log.py
index 1a25176ea..ba01ad894 100644
--- a/qutebrowser/utils/log.py
+++ b/qutebrowser/utils/log.py
@@ -557,4 +557,6 @@ class JSONFormatter(logging.Formatter):
                       '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)
diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index ab26e68ca..bf671c5fb 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -81,6 +81,7 @@ class LogLine(testprocess.Line):
         self.module = line['module']
         self.function = line['funcName']
         self.line = line['lineno']
+        self.traceback = line.get('traceback')
 
         self.full_message = line['message']
         msg_match = re.match(r'^(\[(?P<prefix>\d+s ago)\] )?(?P<message>.*)',
@@ -121,7 +122,10 @@ class LogLine(testprocess.Line):
             format_dict['log_color'] = ''
             format_dict['reset'] = ''
             format_dict.update({color: '' for color in color_names})
-        return log.EXTENDED_FMT.format_map(format_dict)
+        result = log.EXTENDED_FMT.format_map(format_dict)
+        if self.traceback is not None:
+            result += '\n' + self.traceback
+        return result
 
 
 class QuteProc(testprocess.Process):

From 6a6f396f8573e9fcac05df0d667da62e6615563f Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 22:44:07 +0200
Subject: [PATCH 09/17] quteproc: set lineno to None if function is None

---
 tests/end2end/fixtures/quteprocess.py | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index bf671c5fb..05e5a2e76 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -81,6 +81,8 @@ class LogLine(testprocess.Line):
         self.module = line['module']
         self.function = line['funcName']
         self.line = line['lineno']
+        if self.function is None and self.line == 0:
+            self.line = None
         self.traceback = line.get('traceback')
 
         self.full_message = line['message']

From cc7c477e3e979b6dd3cc794ca6e8fed22dcdc1ec Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 23:16:03 +0200
Subject: [PATCH 10/17] tests: add update tests for LogLine with json logs

---
 tests/end2end/fixtures/test_quteprocess.py | 91 +++++++++++++++++-----
 1 file changed, 72 insertions(+), 19 deletions(-)

diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py
index 1ef5398ba..348faf705 100644
--- a/tests/end2end/fixtures/test_quteprocess.py
+++ b/tests/end2end/fixtures/test_quteprocess.py
@@ -21,6 +21,7 @@
 
 import logging
 import datetime
+import json
 
 import pytest
 
@@ -85,14 +86,15 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
         quteproc_process.after_test(did_fail=False)
 
 
-@pytest.mark.skip
 @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,
-                                           hour=1, minute=2, second=3),
+            'timestamp': datetime.datetime(year=1970, month=1, day=1,
+                                           hour=1, minute=0, second=0),
             'loglevel': logging.DEBUG,
             'category': 'init',
             'module': 'earlyinit',
@@ -104,25 +106,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 '
-        'QNetworkReplyHttpImplPrivate::error(QNetworkReply::NetworkError, '
-        'const QString&)":1929 QNetworkReplyImplPrivate::error: Internal '
-        'problem, this method must only be called once.',
+        '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": '
+        '"qnetworkreplyhttpimpl", "funcName": '
+        '"void QNetworkReplyHttpImplPrivate::error('
+        '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('
@@ -131,10 +140,11 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
         }
     ),
     (
-        '00:00:00 WARNING  qt         qxcbxsettings:"QXcbXSettings::'
-        'QXcbXSettings(QXcbScreen*)":233 '
-        'QXcbXSettings::QXcbXSettings(QXcbScreen*) Failed to get selection '
-        'owner for XSETTINGS_S atom ',
+        '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": '
+        '"qxcbxsettings", "funcName": "QXcbXSettings::QXcbXSettings('
+        'QXcbScreen*)", "lineno": 233, "levelno": 10, "message": '
+        '"QXcbXSettings::QXcbXSettings(QXcbScreen*) Failed to get selection '
+        'owner for XSETTINGS_S atom"}',
         {
             'module': 'qxcbxsettings',
             'function': 'QXcbXSettings::QXcbXSettings(QXcbScreen*)',
@@ -143,14 +153,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 "
-        ".../app.py:121: ResourceWarning: unclosed file <_io.TextIOWrapper "
-        "name=18 mode='r' encoding='UTF-8'>",
+        '{"created": 0, "levelname": "WARNING", "name": "py.warnings", '
+        '"module": "app", "funcName": "qt_mainloop", "lineno": 121, "levelno":'
+        ' 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',
@@ -163,6 +177,45 @@ def test_log_line_parse(data, attrs):
         assert actual == expected, name
 
 
+COLORS = ['black', 'red', 'green', 'yellow', 'blue', 'purple', 'cyan', 'white']
+EXTENDED_FMT = ('{green}{asctime:8}{reset} '
+                '{log_color}{levelname:8}{reset} '
+                '{cyan}{name:10} {module}:{funcName}:{lineno}{reset} '
+                '{log_color}{message}{reset}')
+
+@pytest.mark.parametrize('data, colorized, expected', [
+    (
+        {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
+         'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
+        False,
+        '01:00:00 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,
+        '01:00:00 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[32m01:00:00\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)
+    assert record.formatted_str(colorized=colorized) == expected
+
+
 def test_log_line_no_match():
     with pytest.raises(testprocess.InvalidLine):
         quteprocess.LogLine("Hello World!")

From db240e294e003773cd312c59c30bf5f003d35e9e Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 23:28:13 +0200
Subject: [PATCH 11/17] quteproc: delegate LogLine to log.ColoredFormatter

---
 tests/end2end/fixtures/quteprocess.py | 34 ++++++++++-----------------
 1 file changed, 13 insertions(+), 21 deletions(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index 05e5a2e76..91818f185 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -104,27 +104,19 @@ class LogLine(testprocess.Line):
         Args:
             colorized: If True, ANSI color codes will be embedded.
         """
-        format_dict = {
-            'asctime': self.timestamp.strftime(log.DATEFMT),
-            'levelname': self.levelname,
-            'name': self.category,
-            'module': self.module,
-            'funcName': self.function,
-            'lineno': self.line,
-            'message': self.full_message,
-        }
-        if colorized:
-            log_color_name = log.LOG_COLORS[self.levelname]
-            log_color = log.ColoredFormatter.COLOR_ESCAPES[log_color_name]
-            format_dict['log_color'] = log_color
-            format_dict['reset'] = log.ColoredFormatter.RESET_ESCAPE
-            format_dict.update(log.ColoredFormatter.COLOR_ESCAPES)
-        else:
-            color_names = log.ColoredFormatter.COLOR_ESCAPES.keys()
-            format_dict['log_color'] = ''
-            format_dict['reset'] = ''
-            format_dict.update({color: '' for color in color_names})
-        result = log.EXTENDED_FMT.format_map(format_dict)
+        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

From 484320ac1954b90b79bcd1b2203e5e0abbe65bc0 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 23:32:35 +0200
Subject: [PATCH 12/17] quteproc: see lines starting with '  ' as error

Now that json logging is used, multiple lines should be correctly
escaped (and parsed), even in tracebacks, so this check should now be
obsolete.
---
 tests/end2end/fixtures/quteprocess.py | 5 +----
 1 file changed, 1 insertion(+), 4 deletions(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index 91818f185..df74279d3 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -176,10 +176,7 @@ class QuteProc(testprocess.Process):
         try:
             log_line = LogLine(line)
         except testprocess.InvalidLine:
-            if line.startswith('  '):
-                # Multiple lines in some log output...
-                return None
-            elif not line.strip():
+            if not line.strip():
                 return None
             elif is_ignored_qt_message(line):
                 return None

From f676a599a266beb504240406ddf6ff48446c8215 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Wed, 25 May 2016 23:50:04 +0200
Subject: [PATCH 13/17] tests: remove leftover lines from writing the code

Those lines are not needed.
---
 tests/end2end/fixtures/test_quteprocess.py | 6 ------
 1 file changed, 6 deletions(-)

diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py
index 348faf705..0c8bfef65 100644
--- a/tests/end2end/fixtures/test_quteprocess.py
+++ b/tests/end2end/fixtures/test_quteprocess.py
@@ -177,12 +177,6 @@ def test_log_line_parse(data, attrs):
         assert actual == expected, name
 
 
-COLORS = ['black', 'red', 'green', 'yellow', 'blue', 'purple', 'cyan', 'white']
-EXTENDED_FMT = ('{green}{asctime:8}{reset} '
-                '{log_color}{levelname:8}{reset} '
-                '{cyan}{name:10} {module}:{funcName}:{lineno}{reset} '
-                '{log_color}{message}{reset}')
-
 @pytest.mark.parametrize('data, colorized, expected', [
     (
         {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',

From 65e5a3fe09b2197c247f42f2c1e29819c8d414a5 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Thu, 26 May 2016 15:15:53 +0200
Subject: [PATCH 14/17] quteproc: match message with re.DOTALL

Since they may now contain newlines, we need to get the whole message,
which are otherwise not included in .
---
 tests/end2end/fixtures/quteprocess.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index df74279d3..c8768a926 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -87,7 +87,7 @@ class LogLine(testprocess.Line):
 
         self.full_message = line['message']
         msg_match = re.match(r'^(\[(?P<prefix>\d+s ago)\] )?(?P<message>.*)',
-                             self.full_message)
+                             self.full_message, re.DOTALL)
         self.prefix = msg_match.group('prefix')
         self.message = msg_match.group('message')
 

From 5f2d5feb58221bf135ef68fcef37d9f67c380493 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Thu, 26 May 2016 15:28:29 +0200
Subject: [PATCH 15/17] message: don't indent the traceback

This shouldn't be needed anymore with json-logging.
---
 qutebrowser/utils/message.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/qutebrowser/utils/message.py b/qutebrowser/utils/message.py
index 21f6bccfc..811e5a055 100644
--- a/qutebrowser/utils/message.py
+++ b/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)
-    log.message.debug("Stack for {} message:\n{}".format(typ, indented))
+    stack_text = '\n'.join(line.rstrip() for line in stack)
+    log.message.debug("Stack for {} message:\n{}".format(typ, stack_text))
 
 
 def _wrapper(win_id, method_name, text, *args, **kwargs):

From fa2636c2f6eb1d68b16061d13522447dc26b1364 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Thu, 26 May 2016 15:39:14 +0200
Subject: [PATCH 16/17] tests: fix timezone issues for test_quteprocess

Depending on the timezone, you may either get 00:00 as time or 01:00,
which is bad for testing on different machines.
---
 tests/end2end/fixtures/test_quteprocess.py | 11 ++++++-----
 1 file changed, 6 insertions(+), 5 deletions(-)

diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py
index 0c8bfef65..a1d93ad9e 100644
--- a/tests/end2end/fixtures/test_quteprocess.py
+++ b/tests/end2end/fixtures/test_quteprocess.py
@@ -93,8 +93,7 @@ def test_quteprocess_quitting(qtbot, quteproc_process):
         '"earlyinit", "funcName": "init_log", "lineno": 280, "levelno": 10, '
         '"message": "Log initialized."}',
         {
-            'timestamp': datetime.datetime(year=1970, month=1, day=1,
-                                           hour=1, minute=0, second=0),
+            'timestamp': datetime.datetime.fromtimestamp(0),
             'loglevel': logging.DEBUG,
             'category': 'init',
             'module': 'earlyinit',
@@ -182,7 +181,7 @@ def test_log_line_parse(data, attrs):
         {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
          'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
         False,
-        '01:00:00 DEBUG    foo        bar:qux:10 quux',
+        '{timestamp} DEBUG    foo        bar:qux:10 quux',
     ),
     # Traceback attached
     (
@@ -191,7 +190,7 @@ def test_log_line_parse(data, attrs):
          'traceback': 'Traceback (most recent call last):\n    here be '
          'dragons'},
         False,
-        '01:00:00 DEBUG    foo        bar:qux:10 quux\n'
+        '{timestamp} DEBUG    foo        bar:qux:10 quux\n'
         'Traceback (most recent call last):\n'
         '    here be dragons',
     ),
@@ -200,13 +199,15 @@ def test_log_line_parse(data, attrs):
         {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar',
          'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'},
         True,
-        '\033[32m01:00:00\033[0m \033[37mDEBUG   \033[0m \033[36mfoo        '
+        '\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
 
 

From a6b47a7c09f90ca2aa1d4cc3340640a91ff2e994 Mon Sep 17 00:00:00 2001
From: Daniel Schadt <kingdread@gmx.de>
Date: Thu, 26 May 2016 16:09:59 +0200
Subject: [PATCH 17/17] fix lint

---
 tests/end2end/fixtures/quteprocess.py      | 2 +-
 tests/end2end/fixtures/test_quteprocess.py | 4 ++--
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py
index c8768a926..9ee758775 100644
--- a/tests/end2end/fixtures/quteprocess.py
+++ b/tests/end2end/fixtures/quteprocess.py
@@ -97,7 +97,7 @@ class LogLine(testprocess.Line):
         return self.formatted_str(colorized=False)
 
     def formatted_str(self, colorized=True):
-        """Return a formatted colorized line.strip()
+        """Return a formatted colorized line.
 
         This returns a line like qute without --json-logging would produce.
 
diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py
index a1d93ad9e..6ddff75f2 100644
--- a/tests/end2end/fixtures/test_quteprocess.py
+++ b/tests/end2end/fixtures/test_quteprocess.py
@@ -199,8 +199,8 @@ def test_log_line_parse(data, attrs):
         {'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',
+        '\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):