diff --git a/HISTORY.rst b/HISTORY.rst index 5b73c500..1c6bca3c 100644 --- a/HISTORY.rst +++ b/HISTORY.rst @@ -7,6 +7,7 @@ History ------------------- * fix tests for python 3.7, #218 * fix tests for aiohttp >= 3.5, #223 +* rebuild logging with coloured tracebacks and request & response details, #221 0.11.0 (2018-12-07) ------------------- diff --git a/aiohttp_devtools/logs.py b/aiohttp_devtools/logs.py index a99b098a..7fdbf24f 100644 --- a/aiohttp_devtools/logs.py +++ b/aiohttp_devtools/logs.py @@ -1,8 +1,15 @@ +import json import logging import logging.config import re +import traceback +from io import StringIO -import click +import pygments +from devtools import pformat +from devtools.ansi import isatty, sformat +from pygments.formatters import Terminal256Formatter +from pygments.lexers import Python3TracebackLexer rs_dft_logger = logging.getLogger('adev.server.dft') rs_aux_logger = logging.getLogger('adev.server.aux') @@ -11,26 +18,76 @@ main_logger = logging.getLogger('adev.main') LOG_FORMATS = { - logging.DEBUG: {'fg': 'white', 'dim': True}, - logging.INFO: {'fg': 'green'}, - logging.WARN: {'fg': 'yellow'}, + logging.DEBUG: sformat.dim, + logging.INFO: sformat.green, + logging.WARN: sformat.yellow, } +pyg_lexer = Python3TracebackLexer() +pyg_formatter = Terminal256Formatter(style='vim') +split_log = re.compile(r'^(\[.*?\])') -def get_log_format(record): - return LOG_FORMATS.get(record.levelno, {'fg': 'red'}) +class HighlightStreamHandler(logging.StreamHandler): + def setFormatter(self, fmt): + self.formatter = fmt + self.formatter.stream_is_tty = isatty(self.stream) -class DefaultHandler(logging.Handler): - def emit(self, record): - log_entry = self.format(record) - m = re.match(r'^(\[.*?\])', log_entry) +class DefaultFormatter(logging.Formatter): + def __init__(self, fmt=None, datefmt=None, style='%'): + super().__init__(fmt, datefmt, style) + self.stream_is_tty = False + + def format(self, record): + msg = super().format(record) + if not self.stream_is_tty: + return msg + m = split_log.match(msg) + log_color = LOG_FORMATS.get(record.levelno, sformat.red) if m: - time = click.style(m.groups()[0], fg='magenta') - msg = click.style(log_entry[m.end():], **get_log_format(record)) - click.echo(time + msg) + time = sformat(m.groups()[0], sformat.magenta) + return time + sformat(msg[m.end():], log_color) else: - click.secho(log_entry, **get_log_format(record)) + return sformat(msg, log_color) + + +class AccessFormatter(logging.Formatter): + """ + Used to log aiohttp_access and aiohttp_server + """ + def __init__(self, fmt=None, datefmt=None, style='%'): + super().__init__(fmt, datefmt, style) + self.stream_is_tty = False + + def formatMessage(self, record): + msg = super().formatMessage(record) + if msg[0] != '{': + return msg + # json from AccessLogger + obj = json.loads(msg) + if self.stream_is_tty: + # in future we can do clever things about colouring the message based on status code + msg = '{} {} {}'.format( + sformat(obj['time'], sformat.magenta), + sformat(obj['prefix'], sformat.blue), + sformat(obj['msg'], sformat.dim if obj['dim'] else sformat.reset), + ) + else: + msg = '{time} {prefix} {msg}'.format(**obj) + details = getattr(record, 'details', None) + if details: + msg = 'details: {}\n{}'.format(pformat(details, highlight=self.stream_is_tty), msg) + return msg + + def formatException(self, ei): + sio = StringIO() + traceback.print_exception(*ei, file=sio) + stack = sio.getvalue() + sio.close() + if self.stream_is_tty and pyg_lexer: + return pygments.highlight(stack, lexer=pyg_lexer, formatter=pyg_formatter).rstrip('\n') + else: + return stack def log_config(verbose: bool) -> dict: @@ -47,31 +104,36 @@ def log_config(verbose: bool) -> dict: 'default': { 'format': '[%(asctime)s] %(message)s', 'datefmt': '%H:%M:%S', + 'class': 'aiohttp_devtools.logs.DefaultFormatter', }, 'no_ts': { - 'format': '%(message)s' + 'format': '%(message)s', + 'class': 'aiohttp_devtools.logs.DefaultFormatter', + }, + 'aiohttp': { + 'format': '%(message)s', + 'class': 'aiohttp_devtools.logs.AccessFormatter', }, }, 'handlers': { 'default': { 'level': log_level, - 'class': 'aiohttp_devtools.logs.DefaultHandler', + 'class': 'aiohttp_devtools.logs.HighlightStreamHandler', 'formatter': 'default' }, 'no_ts': { 'level': log_level, - 'class': 'aiohttp_devtools.logs.DefaultHandler', + 'class': 'aiohttp_devtools.logs.HighlightStreamHandler', 'formatter': 'no_ts' }, - 'rs_aux': { - 'level': log_level, - 'class': 'aiohttp_devtools.runserver.log_handlers.AuxiliaryHandler', - 'formatter': 'default' - }, 'aiohttp_access': { 'level': log_level, - 'class': 'logging.StreamHandler', - 'formatter': 'no_ts' + 'class': 'aiohttp_devtools.logs.HighlightStreamHandler', + 'formatter': 'aiohttp' + }, + 'aiohttp_server': { + 'class': 'aiohttp_devtools.logs.HighlightStreamHandler', + 'formatter': 'aiohttp' }, }, 'loggers': { @@ -80,11 +142,7 @@ def log_config(verbose: bool) -> dict: 'level': log_level, }, rs_aux_logger.name: { - 'handlers': ['rs_aux'], - 'level': log_level, - }, - 'aiohttp.access': { - 'handlers': ['aiohttp_access'], + 'handlers': ['default'], 'level': log_level, }, tools_logger.name: { @@ -95,6 +153,15 @@ def log_config(verbose: bool) -> dict: 'handlers': ['no_ts'], 'level': log_level, }, + 'aiohttp.access': { + 'handlers': ['aiohttp_access'], + 'level': log_level, + 'propagate': False, + }, + 'aiohttp.server': { + 'handlers': ['aiohttp_server'], + 'level': log_level, + }, }, } diff --git a/aiohttp_devtools/runserver/log_handlers.py b/aiohttp_devtools/runserver/log_handlers.py index 2fd98cac..f4498b76 100644 --- a/aiohttp_devtools/runserver/log_handlers.py +++ b/aiohttp_devtools/runserver/log_handlers.py @@ -1,55 +1,78 @@ -import logging -import re +import json +import warnings from datetime import datetime, timedelta -import click from aiohttp.abc import AbstractAccessLogger -from ..logs import get_log_format - - -class AuxiliaryHandler(logging.Handler): - prefix = click.style('◆', fg='blue') - - def emit(self, record): - log_entry = self.format(record) - m = re.match(r'^(\[.*?\] )', log_entry) - time = click.style(m.groups()[0], fg='magenta') - msg = log_entry[m.end():] - if record.levelno in {logging.INFO, logging.DEBUG} and msg.startswith('>'): - if msg.endswith(' 304 0B'): - msg = '{} {}'.format(self.prefix, click.style(msg[2:], dim=True)) - else: - msg = '{} {}'.format(self.prefix, msg[2:]) - else: - msg = click.style(msg, **get_log_format(record)) - click.echo(time + msg) - - dbtb = '/_debugtoolbar/' check = '?_checking_alive=1' -class AccessLogger(AbstractAccessLogger): - prefix = click.style('●', fg='blue') +class _AccessLogger(AbstractAccessLogger): + prefix = NotImplemented + + def get_msg(self, request, response, time): + raise NotImplementedError() + + def extra(self, request, response, time): + pass def log(self, request, response, time): + msg = self.get_msg(request, response, time) + if not msg: + return now = datetime.now() start_time = now - timedelta(seconds=time) - time_str = click.style(start_time.strftime('[%H:%M:%S]'), fg='magenta') + pqs = request.path_qs + # log messages are encoded to JSON, so they can be easily coloured or not by the logger which knows whether + # the stream "isatty" + msg = json.dumps({ + 'time': start_time.strftime('[%H:%M:%S]'), + 'prefix': self.prefix, + 'msg': msg, + 'dim': (response.status, response.body_length) == (304, 0) or pqs.startswith(dbtb) or pqs.endswith(check) + }) + self.logger.info(msg, extra=self.extra(request, response, time)) + - path = request.path - msg = '{method} {path} {code} {size} {ms:0.0f}ms'.format( +class AccessLogger(_AccessLogger): + prefix = '●' + + def get_msg(self, request, response, time): + return '{method} {path} {code} {size} {ms:0.0f}ms'.format( method=request.method, - path=path, + path=request.path_qs, code=response.status, size=fmt_size(response.body_length), ms=time * 1000, ) - if (response.status, response.body_length) == ('304', 0) or path.startswith(dbtb) or path.endswith(check): - msg = click.style(msg, dim=True) - msg = '{} {}'.format(self.prefix, msg) - self.logger.info(time_str + msg) + + def extra(self, request, response, time: float): + if response.status > 310: + request_body = request._read_bytes + details = dict( + request_duration_ms=round(time * 1000, 3), + request_headers=dict(request.headers), + request_body=parse_body(request_body, 'request body'), + request_size=fmt_size(0 if request_body is None else len(request_body)), + response_headers=dict(response.headers), + response_body=parse_body(response.text or response.body, 'response body'), + ) + return dict(details=details) + + +class AuxAccessLogger(_AccessLogger): + prefix = '◆' + + def get_msg(self, request, response, time): + # don't log livereload + if request.path not in {'/livereload', '/livereload.js'}: + return '{method} {path} {code} {size}'.format( + method=request.method, + path=request.path_qs, + code=response.status, + size=fmt_size(response.body_length), + ) def fmt_size(num): @@ -59,3 +82,16 @@ def fmt_size(num): return '{:0.0f}B'.format(num) else: return '{:0.1f}KB'.format(num / 1024) + + +def parse_body(v, name): + if isinstance(v, (str, bytes)): + try: + return json.loads(v) + except UnicodeDecodeError: + warnings.warn('UnicodeDecodeError parsing ' + name, UserWarning) + # bytes which cause UnicodeDecodeError can cause problems later on + return v.decode(errors='ignore') + except (ValueError, TypeError): + pass + return v diff --git a/aiohttp_devtools/runserver/main.py b/aiohttp_devtools/runserver/main.py index 4c9938c7..dc088f15 100644 --- a/aiohttp_devtools/runserver/main.py +++ b/aiohttp_devtools/runserver/main.py @@ -7,12 +7,13 @@ from ..logs import rs_dft_logger as logger from .config import Config +from .log_handlers import AuxAccessLogger from .serve import HOST, check_port_open, create_auxiliary_app from .watch import AppTask, LiveReloadTask -def run_app(app, port, loop): - runner = AppRunner(app, access_log=None) +def run_app(app, port, loop, access_log_class): + runner = AppRunner(app, access_log_class=access_log_class) loop.run_until_complete(runner.setup()) site = TCPSite(runner, HOST, port, shutdown_timeout=0.01) @@ -69,7 +70,7 @@ def runserver(**config_kwargs): rel_path = config.static_path.relative_to(os.getcwd()) logger.info('serving static files from ./%s/ at %s%s', rel_path, url, config.static_url) - return aux_app, config.aux_port, loop + return aux_app, config.aux_port, loop, AuxAccessLogger def serve_static(*, static_path: str, livereload: bool = True, port: int = 8000): diff --git a/aiohttp_devtools/runserver/serve.py b/aiohttp_devtools/runserver/serve.py index f5da9621..b74cb181 100644 --- a/aiohttp_devtools/runserver/serve.py +++ b/aiohttp_devtools/runserver/serve.py @@ -18,7 +18,7 @@ from ..logs import rs_dft_logger as dft_logger from ..logs import setup_logging from .config import Config -from .log_handlers import AccessLogger, fmt_size +from .log_handlers import AccessLogger from .utils import MutableValue try: @@ -222,11 +222,9 @@ def create_auxiliary_app(*, static_path: str, static_url='/', livereload=True): async def livereload_js(request): if request.if_modified_since: - aux_logger.debug('> %s %s %s 0B', request.method, request.path, 304) raise HTTPNotModified() lr_script = request.app['livereload_script'] - aux_logger.debug('> %s %s %s %s', request.method, request.path, 200, fmt_size(len(lr_script))) return web.Response(body=lr_script, content_type='application/javascript', headers={LAST_MODIFIED: 'Fri, 01 Jan 2016 00:00:00 GMT'}) @@ -333,24 +331,16 @@ def _insert_footer(self, response): async def _handle(self, request): self.modify_request(request) - status, length = 'unknown', '' try: response = await super()._handle(request) response = self._insert_footer(response) except HTTPNotModified: - status, length = 304, 0 raise except HTTPNotFound: # TODO include list of files in 404 body _404_msg = '404: Not Found\n' response = web.Response(body=_404_msg.encode(), status=404, content_type='text/plain') - status, length = response.status, response.content_length else: # Inject CORS headers to allow webfonts to load correctly response.headers['Access-Control-Allow-Origin'] = '*' - - status, length = response.status, response.content_length - finally: - logger = aux_logger.info if status in {200, 304} else aux_logger.warning - logger('> %s %s %s %s', request.method, request.path, status, fmt_size(length)) return response diff --git a/setup.py b/setup.py index d76694b7..33b03339 100644 --- a/setup.py +++ b/setup.py @@ -76,8 +76,10 @@ install_requires=[ 'aiohttp>=3.5.0', 'click>=6.6', + 'devtools>=0.5', 'isort>=4.3.3', 'Jinja2>=2.10', + 'Pygments>=2.2.0', 'watchgod>=0.2', ], python_requires='>=3.5', diff --git a/tests/test_runserver_logs.py b/tests/test_runserver_logs.py index 77641b31..4f189cac 100644 --- a/tests/test_runserver_logs.py +++ b/tests/test_runserver_logs.py @@ -1,82 +1,223 @@ +import json import logging import re +import sys from unittest.mock import MagicMock -from aiohttp_devtools.runserver.log_handlers import AccessLogger, AuxiliaryHandler +import pytest +from aiohttp_devtools.logs import AccessFormatter, DefaultFormatter +from aiohttp_devtools.runserver.log_handlers import AccessLogger, AuxAccessLogger, parse_body -def _get_record(msg, level=logging.INFO): - record = MagicMock() - record.levelno = level - record.exc_info = None - record.exc_text = None - record.stack_info = None - record.getMessage = MagicMock(return_value=msg) - return record - -def test_aux_std(capsys): - handler = AuxiliaryHandler() - record = _get_record('[foo] bar') - handler.emit(record) - out, err = capsys.readouterr() - assert '[foo] bar\n' == out - - -def test_aux_request(capsys): - handler = AuxiliaryHandler() - record = _get_record('[foo] > bar') - handler.emit(record) - out, err = capsys.readouterr() - assert '[foo] ◆ bar\n' == out - - -def test_aux_request_304(capsys): - handler = AuxiliaryHandler() - record = _get_record('[foo] > bar 304 0B') - handler.emit(record) - out, err = capsys.readouterr() - # no difference, could do better - assert '[foo] ◆ bar 304 0B\n' == out +def test_aiohttp_std(): + info = MagicMock() + logger = type('Logger', (), {'info': info}) + logger = AccessLogger(logger, None) + request = MagicMock() + request.method = 'GET' + request.path_qs = '/foobar?v=1' + response = MagicMock() + response.status = 200 + response.body_length = 100 + logger.log(request, response, 0.15) + assert info.call_count == 1 + log = json.loads(info.call_args[0][0]) + time = log.pop('time') + assert re.fullmatch(r'\[\d\d:\d\d:\d\d\]', time) + assert log == { + 'prefix': '●', + 'msg': 'GET /foobar?v=1 200 100B 150ms', + 'dim': False, + } -def _strip_ansi(v): - return re.sub(r'\033\[((?:\d|;)*)([a-zA-Z])', '', v) +def test_aiohttp_debugtoolbar(): + info = MagicMock() + logger = type('Logger', (), {'info': info}) + logger = AccessLogger(logger, None) + request = MagicMock() + request.method = 'GET' + request.path_qs = '/_debugtoolbar/whatever' + response = MagicMock() + response.status = 200 + response.body_length = 100 + logger.log(request, response, 0.15) + assert info.call_count == 1 + log = json.loads(info.call_args[0][0]) + time = log.pop('time') + assert re.fullmatch(r'\[\d\d:\d\d:\d\d\]', time) + assert log == { + 'prefix': '●', + 'msg': 'GET /_debugtoolbar/whatever 200 100B 150ms', + 'dim': True, + } -def test_aiohttp_std(): +def test_aux_logger(): info = MagicMock() logger = type('Logger', (), {'info': info}) - handler = AccessLogger(logger, None) + logger = AuxAccessLogger(logger, None) request = MagicMock() request.method = 'GET' - request.path = '/foobar?v=1' + request.path = '/' + request.path_qs = '/' response = MagicMock() response.status = 200 response.body_length = 100 - handler.log(request, response, 0.15) + logger.log(request, response, 0.15) assert info.call_count == 1 - msg = _strip_ansi(info.call_args[0][0]) - assert msg[msg.find(']'):] == ']● GET /foobar?v=1 200 100B 150ms' - assert re.match(r'^\[\d\d:\d\d:\d\d\]', msg), msg - # not dim - assert '\x1b[2m' not in info.call_args[0][0] + log = json.loads(info.call_args[0][0]) + time = log.pop('time') + assert re.fullmatch(r'\[\d\d:\d\d:\d\d\]', time) + assert log == { + 'prefix': '◆', + 'msg': 'GET / 200 100B', + 'dim': False, + } -def test_aiohttp_debugtoolbar(): +def test_aux_logger_livereload(): info = MagicMock() logger = type('Logger', (), {'info': info}) - handler = AccessLogger(logger, None) + logger = AuxAccessLogger(logger, None) request = MagicMock() request.method = 'GET' - request.path = '/_debugtoolbar/whatever' + request.path = '/livereload.js' + request.path_qs = '/livereload.js' response = MagicMock() response.status = 200 response.body_length = 100 - handler.log(request, response, 0.15) + logger.log(request, response, 0.15) + assert info.call_count == 0 + + +def test_extra(): + info = MagicMock() + logger = type('Logger', (), {'info': info}) + logger = AccessLogger(logger, None) + request = MagicMock() + request.method = 'GET' + request.headers = {'Foo': 'Bar'} + request.path_qs = '/foobar?v=1' + request._read_bytes = b'testing' + response = MagicMock() + response.status = 500 + response.body_length = 100 + response.headers = {'Foo': 'Spam'} + response.text = 'testing' + logger.log(request, response, 0.15) assert info.call_count == 1 - msg = _strip_ansi(info.call_args[0][0]) - assert msg[msg.find(']'):] == ']● GET /_debugtoolbar/whatever 200 100B 150ms' - assert re.match(r'^\[\d\d:\d\d:\d\d\]', msg), msg - # dim - assert '\x1b[2m' in info.call_args[0][0] + assert info.call_args[1]['extra'] == { + 'details': { + 'request_duration_ms': 150.0, + 'request_headers': { + 'Foo': 'Bar', + }, + 'request_body': b'testing', + 'request_size': '7B', + 'response_headers': { + 'Foo': 'Spam', + }, + 'response_body': 'testing', + } + } + + +@pytest.mark.parametrize('value,result', [ + (None, None), + ('foobar', 'foobar'), + (b'foobar', b'foobar'), + ('{"foo": "bar"}', {'foo': 'bar'}), +]) +def test_parse_body(value, result): + assert parse_body(value, 'testing') == result + + +@pytest.mark.skipif(sys.version_info < (3, 6), reason='3.5 behaves differently') +def test_parse_body_unicode_decode(): + with pytest.warns(UserWarning): + assert parse_body(b'will fail: \x80', 'testing') == 'will fail: ' + + +def _mk_record(msg, level=logging.INFO, **extra): + class Record: + levelno = level + exc_info = None + exc_text = None + stack_info = None + + def __init__(self): + if extra: + for k, v in extra.items(): + setattr(self, k, v) + + def getMessage(self): + return msg + return Record() + + +def test_dft_formatter(): + f = DefaultFormatter() + assert f.format(_mk_record('testing')) == 'testing' + + +def test_dft_formatter_colour(): + f = DefaultFormatter() + f.stream_is_tty = True + assert f.format(_mk_record('testing')) == '\x1b[32mtesting\x1b[0m' + + +def test_dft_formatter_colour_time(): + f = DefaultFormatter() + f.stream_is_tty = True + assert f.format(_mk_record('[time] testing')) == '\x1b[35m[time]\x1b[0m\x1b[32m testing\x1b[0m' + + +def test_access_formatter(): + f = AccessFormatter() + msg = json.dumps({'time': '_time_', 'prefix': '_p_', 'msg': '_msg_', 'dim': False}) + assert f.format(_mk_record(msg)) == '_time_ _p_ _msg_' + + +def test_access_formatter_no_json(): + f = AccessFormatter() + assert f.format(_mk_record('foobar')) == 'foobar' + + +def test_access_formatter_colour(): + f = AccessFormatter() + f.stream_is_tty = True + msg = json.dumps({'time': '_time_', 'prefix': '_p_', 'msg': '_msg_', 'dim': False}) + assert f.format(_mk_record(msg)) == '\x1b[35m_time_\x1b[0m \x1b[34m_p_\x1b[0m \x1b[0m_msg_\x1b[0m' + + +def test_access_formatter_extra(): + f = AccessFormatter() + msg = json.dumps({'time': '_time_', 'prefix': '_p_', 'msg': '_msg_', 'dim': False}) + assert f.format(_mk_record(msg, details={'foo': 'bar'})) == ( + 'details: {\n' + " 'foo': 'bar',\n" + '}\n' + '_time_ _p_ _msg_' + ) + + +def test_access_formatter_exc(): + f = AccessFormatter() + try: + raise RuntimeError('testing') + except RuntimeError: + stack = f.formatException(sys.exc_info()) + assert stack.startswith('Traceback (most recent call last):\n') + assert stack.endswith('RuntimeError: testing\n') + + +def test_access_formatter_exc_colour(): + f = AccessFormatter() + f.stream_is_tty = True + try: + raise RuntimeError('testing') + except RuntimeError: + stack = f.formatException(sys.exc_info()) + assert stack.startswith('\x1b[38;5;26mTraceback') diff --git a/tests/test_runserver_main.py b/tests/test_runserver_main.py index bc2de938..417d6cf6 100644 --- a/tests/test_runserver_main.py +++ b/tests/test_runserver_main.py @@ -10,6 +10,7 @@ import pytest from aiohttp import ClientTimeout from aiohttp.web import Application +from aiohttp.web_log import AccessLogger from pytest_toolbox import mktree from aiohttp_devtools.runserver import run_app, runserver @@ -60,7 +61,7 @@ def create_app(loop): }) loop = asyncio.new_event_loop() asyncio.set_event_loop(loop) - aux_app, aux_port, _ = runserver(app_path='app.py', static_path='static_dir') + aux_app, aux_port, _, _ = runserver(app_path='app.py', static_path='static_dir') assert isinstance(aux_app, aiohttp.web.Application) assert aux_port == 8001 for startup in aux_app.on_startup: @@ -104,7 +105,7 @@ async def hello(request): app.router.add_get('/', hello) """ }) - aux_app, aux_port, _ = runserver(app_path='app.py', host='foobar.com') + aux_app, aux_port, _, _ = runserver(app_path='app.py', host='foobar.com') assert isinstance(aux_app, aiohttp.web.Application) assert aux_port == 8001 assert len(aux_app.on_startup) == 2 @@ -122,7 +123,7 @@ def test_run_app(loop, aiohttp_unused_port): app = Application() port = aiohttp_unused_port() Process(target=kill_parent_soon, args=(os.getpid(),)).start() - run_app(app, port, loop) + run_app(app, port, loop, AccessLogger) @if_boxed