rnhmjoj/qutebrowser
1
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity

bdd: Display milliseconds in log output

Browse Source
This commit is contained in:
Florian Bruhin 2016-09-06 16:22:31 +02:00
parent 52649aea70
commit c07ff15b9b
3 changed files with 49 additions and 38 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
qutebrowser/utils/log.py
View File

@ -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:

4
tests/end2end/fixtures/quteprocess.py
View File

@ -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:

79
tests/end2end/fixtures/test_quteprocess.py
View File

@ -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