From c07ff15b9b7a45e9e02eb9c37b1c2e4bf3479eff Mon Sep 17 00:00:00 2001 From: Florian Bruhin Date: Tue, 6 Sep 2016 16:22:31 +0200 Subject: [PATCH] bdd: Display milliseconds in log output --- qutebrowser/utils/log.py | 4 +- tests/end2end/fixtures/quteprocess.py | 4 ++ tests/end2end/fixtures/test_quteprocess.py | 79 ++++++++++++---------- 3 files changed, 49 insertions(+), 38 deletions(-) diff --git a/qutebrowser/utils/log.py b/qutebrowser/utils/log.py index 17c0d5e5d..18b4e2dc9 100644 --- a/qutebrowser/utils/log.py +++ b/qutebrowser/utils/log.py @@ -637,8 +637,8 @@ class JSONFormatter(logging.Formatter): def format(self, record): obj = {} - for field in ['created', 'levelname', 'name', 'module', 'funcName', - 'lineno', 'levelno']: + for field in ['created', 'msecs', 'levelname', 'name', 'module', + 'funcName', 'lineno', 'levelno']: obj[field] = getattr(record, field) obj['message'] = record.getMessage() if record.exc_info is not None: diff --git a/tests/end2end/fixtures/quteprocess.py b/tests/end2end/fixtures/quteprocess.py index 57aa6a5b1..037587ba8 100644 --- a/tests/end2end/fixtures/quteprocess.py +++ b/tests/end2end/fixtures/quteprocess.py @@ -73,6 +73,7 @@ class LogLine(testprocess.Line): raise testprocess.InvalidLine(data) self.timestamp = datetime.datetime.fromtimestamp(line['created']) + self.msecs = line['msecs'] self.loglevel = line['levelno'] self.levelname = line['levelname'] self.category = line['name'] @@ -109,10 +110,13 @@ class LogLine(testprocess.Line): if self.line is None: r.line = 0 r.created = self.timestamp.timestamp() + r.msecs = self.msecs r.module = self.module r.funcName = self.function format_str = log.EXTENDED_FMT + format_str = format_str.replace('{asctime:8}', + '{asctime:8}.{msecs:03.0f}') # Mark expected errors with (expected) so it's less confusing for tests # which expect errors but fail due to other errors. if self.expected and self.loglevel > logging.INFO: diff --git a/tests/end2end/fixtures/test_quteprocess.py b/tests/end2end/fixtures/test_quteprocess.py index 800ac687e..0ceb90cd6 100644 --- a/tests/end2end/fixtures/test_quteprocess.py +++ b/tests/end2end/fixtures/test_quteprocess.py @@ -148,9 +148,9 @@ def test_quteprocess_quitting(qtbot, quteproc_process): @pytest.mark.parametrize('data, attrs', [ ( # Normal message - '{"created": 0, "levelname": "DEBUG", "name": "init", "module": ' - '"earlyinit", "funcName": "init_log", "lineno": 280, "levelno": 10, ' - '"message": "Log initialized."}', + '{"created": 0, "msecs": 0, "levelname": "DEBUG", "name": "init", ' + '"module": "earlyinit", "funcName": "init_log", "lineno": 280, ' + '"levelno": 10, "message": "Log initialized."}', { 'timestamp': datetime.datetime.fromtimestamp(0), 'loglevel': logging.DEBUG, @@ -164,28 +164,29 @@ def test_quteprocess_quitting(qtbot, quteproc_process): ), ( # VDEBUG - '{"created": 0, "levelname": "VDEBUG", "name": "foo", "module": ' - '"foo", "funcName": "foo", "lineno": 0, "levelno": 9, "message": ""}', + '{"created": 0, "msecs": 0, "levelname": "VDEBUG", "name": "foo", ' + '"module": "foo", "funcName": "foo", "lineno": 0, "levelno": 9, ' + '"message": ""}', {'loglevel': log.VDEBUG_LEVEL} ), ( # Unknown module - '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": ' - 'null, "funcName": null, "lineno": 0, "levelno": 10, "message": ' - '"test"}', + '{"created": 0, "msecs": 0, "levelname": "DEBUG", "name": "qt", ' + '"module": null, "funcName": null, "lineno": 0, "levelno": 10, ' + '"message": "test"}', {'module': None, 'function': None, 'line': None}, ), ( # Expected message - '{"created": 0, "levelname": "VDEBUG", "name": "foo", "module": ' - '"foo", "funcName": "foo", "lineno": 0, "levelno": 9, "message": ' - '"SpellCheck: test"}', + '{"created": 0, "msecs": 0, "levelname": "VDEBUG", "name": "foo", ' + '"module": "foo", "funcName": "foo", "lineno": 0, "levelno": 9, ' + '"message": "SpellCheck: test"}', {'expected': True}, ), ( # Weird Qt location - '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": ' - '"qnetworkreplyhttpimpl", "funcName": ' + '{"created": 0, "msecs": 0, "levelname": "DEBUG", "name": "qt", ' + '"module": "qnetworkreplyhttpimpl", "funcName": ' '"void QNetworkReplyHttpImplPrivate::error(' 'QNetworkReply::NetworkError, const QString&)", "lineno": 1929, ' '"levelno": 10, "message": "QNetworkReplyImplPrivate::error: ' @@ -198,8 +199,8 @@ def test_quteprocess_quitting(qtbot, quteproc_process): } ), ( - '{"created": 0, "levelname": "DEBUG", "name": "qt", "module": ' - '"qxcbxsettings", "funcName": "QXcbXSettings::QXcbXSettings(' + '{"created": 0, "msecs": 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"}', @@ -211,16 +212,16 @@ def test_quteprocess_quitting(qtbot, quteproc_process): ), ( # With [2s ago] marker - '{"created": 0, "levelname": "DEBUG", "name": "foo", "module": ' - '"foo", "funcName": "foo", "lineno": 0, "levelno": 10, "message": ' - '"[2s ago] test"}', + '{"created": 0, "msecs": 0, "levelname": "DEBUG", "name": "foo", ' + '"module": "foo", "funcName": "foo", "lineno": 0, "levelno": 10, ' + '"message": "[2s ago] test"}', {'prefix': '2s ago', 'message': 'test'} ), ( # ResourceWarning - '{"created": 0, "levelname": "WARNING", "name": "py.warnings", ' - '"module": "app", "funcName": "qt_mainloop", "lineno": 121, "levelno":' - ' 30, "message": ' + '{"created": 0, "msecs": 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'} @@ -237,48 +238,53 @@ def test_log_line_parse(data, attrs): @pytest.mark.parametrize('data, colorized, expect_error, expected', [ ( - {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar', - 'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'}, + {'created': 0, 'msecs': 0, 'levelname': 'DEBUG', 'name': 'foo', + 'module': 'bar', 'funcName': 'qux', 'lineno': 10, 'levelno': 10, + 'message': 'quux'}, False, 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'}, + {'created': 0, 'msecs': 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, False, '{timestamp} DEBUG foo bar:qux:10 quux\n' 'Traceback (most recent call last):\n' - ' here be dragons', + ' here be dragons', ), # Colorized ( - {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar', - 'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'}, + {'created': 0, 'msecs': 0, 'levelname': 'DEBUG', 'name': 'foo', + 'module': 'bar', 'funcName': 'qux', 'lineno': 10, 'levelno': 10, + 'message': 'quux'}, True, False, '\033[32m{timestamp}\033[0m \033[37mDEBUG \033[0m \033[36mfoo ' ' bar:qux:10\033[0m \033[37mquux\033[0m', ), # Expected error ( - {'created': 0, 'levelname': 'ERROR', 'name': 'foo', 'module': 'bar', - 'funcName': 'qux', 'lineno': 10, 'levelno': 40, 'message': 'quux'}, + {'created': 0, 'msecs': 0, 'levelname': 'ERROR', 'name': 'foo', + 'module': 'bar', 'funcName': 'qux', 'lineno': 10, 'levelno': 40, + 'message': 'quux'}, False, True, '{timestamp} ERROR (expected) foo bar:qux:10 quux', ), # Expected other message (i.e. should make no difference) ( - {'created': 0, 'levelname': 'DEBUG', 'name': 'foo', 'module': 'bar', - 'funcName': 'qux', 'lineno': 10, 'levelno': 10, 'message': 'quux'}, + {'created': 0, 'msecs': 0, 'levelname': 'DEBUG', 'name': 'foo', + 'module': 'bar', 'funcName': 'qux', 'lineno': 10, 'levelno': 10, + 'message': 'quux'}, False, True, '{timestamp} DEBUG foo bar:qux:10 quux', ), # Expected error colorized (shouldn't be red) ( - {'created': 0, 'levelname': 'ERROR', 'name': 'foo', 'module': 'bar', - 'funcName': 'qux', 'lineno': 10, 'levelno': 40, 'message': 'quux'}, + {'created': 0, 'msecs': 0, 'levelname': 'ERROR', 'name': 'foo', + 'module': 'bar', 'funcName': 'qux', 'lineno': 10, 'levelno': 40, + 'message': 'quux'}, True, True, '\033[32m{timestamp}\033[0m \033[37mERROR (expected)\033[0m ' '\033[36mfoo bar:qux:10\033[0m \033[37mquux\033[0m', @@ -290,6 +296,7 @@ def test_log_line_formatted(data, colorized, expect_error, expected): record = quteprocess.LogLine(line) record.expected = expect_error ts = datetime.datetime.fromtimestamp(data['created']).strftime('%H:%M:%S') + ts += '.{:03.0f}'.format(data['msecs']) expected = expected.format(timestamp=ts) assert record.formatted_str(colorized=colorized) == expected