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..ba01ad894 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,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) 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): diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py index ff5665d0d..9ee758775 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,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\d\d:\d\d:\d\d) - \ (?PVDEBUG|DEBUG|INFO|WARNING|ERROR) - \ +(?P[\w.]+) - \ +(?P(\w+|Unknown\ module)): - (?P[^"][^:]*|"[^"]+"): - (?P\d+) - \ (?P.+) - """, 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 ValueError: 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.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'] + if self.function is None and self.line == 0: self.line = None - else: - self.line = line + self.traceback = line.get('traceback') + self.full_message = line['message'] msg_match = re.match(r'^(\[(?P\d+s ago)\] )?(?P.*)', - 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(' '): - # 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 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. diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py index 06a020352..6ddff75f2 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 @@ -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, - hour=1, minute=2, second=3), + 'timestamp': datetime.datetime.fromtimestamp(0), '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 ' - '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(' @@ -130,10 +139,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*)', @@ -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 " - ".../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', @@ -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!") 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.' 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."""