Loggings improvements (#221)

* improvements to logging

* fixing log imports

* full request/response info in logs

* simplify request/response summary

* add history

* use json for access loggers, logging tests

* fix 'extra' usage

* tweak setup

* fix AccessFormatter

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

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,
+            },
         },
     }
 

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

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

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