Merge pull request #625 from zenixls2/master

based on issue #608, create access log

docs/index.rst

@@ -20,6 +20,7 @@ Guides
    sanic/class_based_views
    sanic/custom_protocol
    sanic/ssl
+   sanic/logging
    sanic/testing
    sanic/deploying
    sanic/extensions

docs/sanic/logging.md

@@ -0,0 +1,128 @@
+# Logging
+
+
+Sanic allows you to do different types of logging (access log, error log) on the requests based on the [python3 logging API](https://docs.python.org/3/howto/logging.html). You should have some basic knowledge on python3 logging if you want do create a new configuration.
+
+### Quck Start
+
+A simple example using default setting would be like this:
+
+```python
+from sanic import Sanic
+from sanic.config import LOGGING
+
+# The default logging handlers are ['accessStream', 'errorStream']
+# but we change it to use other handlers here for demo purpose
+LOGGING['loggers']['network']['handlers'] = [
+    'accessTimedRotatingFile', 'errorTimedRotationgFile']
+
+app = Sanic('test')
+
+@app.route('/')
+async def test(request):
+    return response.text('Hello World!')
+
+if __name__ == "__main__":
+  app.run(log_config=LOGGING)
+```
+
+After the program starts, it will log down all the information/requests in access.log and error.log in your working directory.
+
+And to close logging, simply assign log_config=None:
+
+```python
+if __name__ == "__main__":
+  app.run(log_config=None)
+```
+
+This would skip calling logging functions when handling requests.
+And you could even do further in production to gain extra speed:
+
+```python
+if __name__ == "__main__":
+  # disable internal messages
+  app.run(debug=False, log_config=None)
+```
+
+### Configuration
+
+By default, log_config parameter is set to use sanic.config.LOGGING dictionary for configuration. The default configuration provides several predefined `handlers`:
+
+- internal (using [logging.StreamHandler](https://docs.python.org/3/library/logging.handlers.html#logging.StreamHandler))<br>
+  For internal information console outputs.
+
+
+- accessStream (using [logging.StreamHandler](https://docs.python.org/3/library/logging.handlers.html#logging.StreamHandler))<br>
+  For requests information logging in console
+
+
+- errorStream (using [logging.StreamHandler](https://docs.python.org/3/library/logging.handlers.html#logging.StreamHandler))<br>
+  For error message and traceback logging in console.
+
+
+- accessSysLog (using [logging.handlers.SysLogHandler](https://docs.python.org/3/library/logging.handlers.html#logging.handlers.SysLogHandler))<br>
+  For requests information logging to syslog.
+  Currently supports Windows (via localhost:514), Darwin (/var/run/syslog),
+  Linux (/dev/log) and FreeBSD (/dev/log).<br>
+  You would not be able to access this property if the directory doesn't exist.
+  (Notice that in Docker you have to enable everything by yourself)
+
+
+- errorSysLog (using [logging.handlers.SysLogHandler](https://docs.python.org/3/library/logging.handlers.html#logging.handlers.SysLogHandler))<br>
+  For error message and traceback logging to syslog.
+  Currently supports Windows (via localhost:514), Darwin (/var/run/syslog),
+  Linux (/dev/log) and FreeBSD (/dev/log).<br>
+  You would not be able to access this property if the directory doesn't exist.
+  (Notice that in Docker you have to enable everything by yourself)
+
+
+- accessTimedRotatingFile (using [logging.handlers.TimedRotatingFileHandler](https://docs.python.org/3/library/logging.handlers.html#logging.handlers.TimedRotatingFileHandler))<br>
+  For requests information logging to file with daily rotation support.
+
+
+- errorTimedRotatingFile (using [logging.handlers.TimedRotatingFileHandler](https://docs.python.org/3/library/logging.handlers.html#logging.handlers.TimedRotatingFileHandler))<br>
+  For error message and traceback logging to file with daily rotation support.
+
+And `filters`:
+
+- accessFilter (using sanic.defaultFilter.DefaultFilter)<br>
+  The filter that allows only levels in `DEBUG`, `INFO`, and `NONE(0)`
+
+
+- errorFilter (using sanic.defaultFilter.DefaultFilter)<br>
+  The filter taht allows only levels in `WARNING`, `ERROR`, and `CRITICAL`
+
+There are two `loggers` used in sanic, and **must be defined if you want to create your own logging configuration**:
+
+- sanic:<br>
+  Used to log internal messages.
+
+
+- network:<br>
+  Used to log requests from network, and any information from those requests.
+
+#### Log format:
+
+In addition to default parameters provided by python (asctime, levelname, message),
+Sanic provides additional parameters for network logger with accessFilter:
+
+- host (str)<br>
+  request.ip
+
+
+- request (str)<br>
+  request.method + " " + request.url
+
+
+- status (int)<br>
+  response.status
+
+
+- byte (int)<br>
+  len(response.body)
+
+
+The default access log format is 
+```python
+%(asctime)s - (%(name)s)[%(levelname)s][%(host)s]: %(request)s %(message)s %(status)d %(byte)d
+```

sanic/app.py

@@ -1,4 +1,5 @@
 import logging
+import logging.config
 import re
 import warnings
 from asyncio import get_event_loop, ensure_future, CancelledError
@@ -9,7 +10,7 @@ from traceback import format_exc
 from urllib.parse import urlencode, urlunparse
 from ssl import create_default_context, Purpose
 
-from sanic.config import Config
+from sanic.config import Config, LOGGING
 from sanic.constants import HTTP_METHODS
 from sanic.exceptions import ServerError, URLBuildError, SanicException
 from sanic.handlers import ErrorHandler
@@ -26,7 +27,10 @@ from sanic.websocket import WebSocketProtocol, ConnectionClosed
 class Sanic:
 
     def __init__(self, name=None, router=None, error_handler=None,
-                 load_env=True, request_class=None):
+                 load_env=True, request_class=None,
+                 log_config=LOGGING):
+        if log_config:
+            logging.config.dictConfig(log_config)
         # Only set up a default log handler if the
         # end-user application didn't set anything up.
         if not logging.root.handlers and log.level == logging.NOTSET:
@@ -47,6 +51,7 @@ class Sanic:
         self.request_class = request_class
         self.error_handler = error_handler or ErrorHandler()
         self.config = Config(load_env=load_env)
+        self.log_config = log_config
         self.request_middleware = deque()
         self.response_middleware = deque()
         self.blueprints = {}
@@ -513,7 +518,8 @@ class Sanic:
     def run(self, host="127.0.0.1", port=8000, debug=False, before_start=None,
             after_start=None, before_stop=None, after_stop=None, ssl=None,
             sock=None, workers=1, loop=None, protocol=None,
-            backlog=100, stop_event=None, register_sys_signals=True):
+            backlog=100, stop_event=None, register_sys_signals=True,
+            log_config=LOGGING):
         """Run the HTTP Server and listen until keyboard interrupt or term
         signal. On termination, drain connections before closing.
 
@@ -540,6 +546,8 @@ class Sanic:
         :param protocol: Subclass of asyncio protocol class
         :return: Nothing
         """
+        if log_config:
+            logging.config.dictConfig(log_config)
         if protocol is None:
             protocol = (WebSocketProtocol if self.websocket_enabled
                         else HttpProtocol)
@@ -553,7 +561,8 @@ class Sanic:
             after_start=after_start, before_stop=before_stop,
             after_stop=after_stop, ssl=ssl, sock=sock, workers=workers,
             loop=loop, protocol=protocol, backlog=backlog,
-            register_sys_signals=register_sys_signals)
+            register_sys_signals=register_sys_signals,
+            has_log=log_config is not None)
 
         try:
             self.is_running = True
@@ -580,12 +589,15 @@ class Sanic:
                             before_start=None, after_start=None,
                             before_stop=None, after_stop=None, ssl=None,
                             sock=None, loop=None, protocol=None,
-                            backlog=100, stop_event=None):
+                            backlog=100, stop_event=None,
+                            log_config=LOGGING):
         """Asynchronous version of `run`.
 
         NOTE: This does not support multiprocessing and is not the preferred
               way to run a Sanic application.
         """
+        if log_config:
+            logging.config.dictConfig(log_config)
         if protocol is None:
             protocol = (WebSocketProtocol if self.websocket_enabled
                         else HttpProtocol)
@@ -599,7 +611,8 @@ class Sanic:
             after_start=after_start, before_stop=before_stop,
             after_stop=after_stop, ssl=ssl, sock=sock,
             loop=loop or get_event_loop(), protocol=protocol,
-            backlog=backlog, run_async=True)
+            backlog=backlog, run_async=True,
+            has_log=log_config is not None)
 
         return await serve(**server_settings)
 
@@ -629,7 +642,7 @@ class Sanic:
                 before_start=None, after_start=None, before_stop=None,
                 after_stop=None, ssl=None, sock=None, workers=1, loop=None,
                 protocol=HttpProtocol, backlog=100, stop_event=None,
-                register_sys_signals=True, run_async=False):
+                register_sys_signals=True, run_async=False, has_log=True):
         """Helper function used by `run` and `create_server`."""
 
         if isinstance(ssl, dict):
@@ -683,7 +696,8 @@ class Sanic:
             'keep_alive': self.config.KEEP_ALIVE,
             'loop': loop,
             'register_sys_signals': register_sys_signals,
-            'backlog': backlog
+            'backlog': backlog,
+            'has_log': has_log
         }
 
         # -------------------------------------------- #

sanic/config.py

@@ -1,9 +1,119 @@
+from sanic.defaultFilter import DefaultFilter
 import os
-
+import sys
+import syslog
+import platform
 import types
 
 SANIC_PREFIX = 'SANIC_'
 
+_address_dict = {
+    'Windows': ('localhost', 514),
+    'Darwin': '/var/run/syslog',
+    'Linux': '/dev/log',
+    'FreeBSD': '/dev/log'
+}
+
+LOGGING = {
+    'version': 1,
+    'filters': {
+        'accessFilter': {
+            '()': DefaultFilter,
+            'param': [0, 10, 20]
+        },
+        'errorFilter': {
+            '()': DefaultFilter,
+            'param': [30, 40, 50]
+        }
+    },
+    'formatters': {
+        'simple': {
+            'format': '%(asctime)s - (%(name)s)[%(levelname)s]: %(message)s',
+            'datefmt': '%Y-%m-%d %H:%M:%S'
+        },
+        'access': {
+            'format': '%(asctime)s - (%(name)s)[%(levelname)s][%(host)s]: ' +
+                      '%(request)s %(message)s %(status)d %(byte)d',
+            'datefmt': '%Y-%m-%d %H:%M:%S'
+        }
+    },
+    'handlers': {
+        'internal': {
+            'class': 'logging.StreamHandler',
+            'filters': ['accessFilter'],
+            'formatter': 'simple',
+            'stream': sys.stderr
+        },
+        'accessStream': {
+            'class': 'logging.StreamHandler',
+            'filters': ['accessFilter'],
+            'formatter': 'access',
+            'stream': sys.stderr
+        },
+        'errorStream': {
+            'class': 'logging.StreamHandler',
+            'filters': ['errorFilter'],
+            'formatter': 'simple',
+            'stream': sys.stderr
+        },
+        # before you use accessSysLog, be sure that log levels
+        # 0, 10, 20 have been enabled in you syslog configuration
+        # otherwise you won't be able to see the output in syslog
+        # logging file.
+        'accessSysLog': {
+            'class': 'logging.handlers.SysLogHandler',
+            'address': _address_dict.get(platform.system(),
+                                         ('localhost', 514)),
+            'facility': syslog.LOG_DAEMON,
+            'filters': ['accessFilter'],
+            'formatter': 'access'
+        },
+        'errorSysLog': {
+            'class': 'logging.handlers.SysLogHandler',
+            'address': _address_dict.get(platform.system(),
+                                         ('localhost', 514)),
+            'facility': syslog.LOG_DAEMON,
+            'filters': ['errorFilter'],
+            'formatter': 'simple'
+        },
+        'accessTimedRotatingFile': {
+            'class': 'logging.handlers.TimedRotatingFileHandler',
+            'filters': ['accessFilter'],
+            'formatter': 'access',
+            'when': 'D',
+            'interval': 1,
+            'backupCount': 7,
+            'filename': 'access.log'
+        },
+        'errorTimedRotatingFile': {
+            'class': 'logging.handlers.TimedRotatingFileHandler',
+            'filters': ['errorFilter'],
+            'when': 'D',
+            'interval': 1,
+            'backupCount': 7,
+            'filename': 'error.log',
+            'formatter': 'simple'
+        }
+    },
+    'loggers': {
+        'sanic': {
+            'level': 'DEBUG',
+            'handlers': ['internal', 'errorStream']
+        },
+        'network': {
+            'level': 'DEBUG',
+            'handlers': ['accessStream', 'errorStream']
+        }
+    }
+}
+
+# this happens when using container or systems without syslog
+# keep things in config would cause file not exists error
+_addr = LOGGING['handlers']['accessSysLog']['address']
+if type(_addr) is str and not os.path.exists(_addr):
+    LOGGING['handlers'].pop('accessSysLog')
+    LOGGING['handlers'].pop('errorSysLog')
+
 
 class Config(dict):
     def __init__(self, defaults=None, load_env=True, keep_alive=True):

sanic/defaultFilter.py

@@ -0,0 +1,13 @@
+import logging
+
+
+class DefaultFilter(logging.Filter):
+    def __init__(self, param=None):
+        self.param = param
+
+    def filter(self, record):
+        if self.param is None:
+            return True
+        if record.levelno in self.param:
+            return True
+        return False

sanic/log.py

@@ -1,3 +1,4 @@
 import logging
 
 log = logging.getLogger('sanic')
+netlog = logging.getLogger('network')

sanic/server.py

@@ -25,7 +25,8 @@ try:
 except ImportError:
     async_loop = asyncio
 
-from sanic.log import log
+from sanic.log import log, netlog
+from sanic.response import HTTPResponse
 from sanic.request import Request
 from sanic.exceptions import (
     RequestTimeout, PayloadTooLarge, InvalidUsage, ServerError)
@@ -65,12 +66,14 @@ class HttpProtocol(asyncio.Protocol):
         # request config
         'request_handler', 'request_timeout', 'request_max_size',
         'request_class',
+        # enable or disable access log / error log purpose
+        'has_log',
         # connection management
         '_total_request_size', '_timeout_handler', '_last_communication_time')
 
     def __init__(self, *, loop, request_handler, error_handler,
                  signal=Signal(), connections=set(), request_timeout=60,
-                 request_max_size=None, request_class=None,
+                 request_max_size=None, request_class=None, has_log=True,
                  keep_alive=True):
         self.loop = loop
         self.transport = None
@@ -79,6 +82,7 @@ class HttpProtocol(asyncio.Protocol):
         self.url = None
         self.headers = None
         self.signal = signal
+        self.has_log = has_log
         self.connections = connections
         self.request_handler = request_handler
         self.error_handler = error_handler
@@ -194,6 +198,14 @@ class HttpProtocol(asyncio.Protocol):
                 response.output(
                     self.request.version, keep_alive,
                     self.request_timeout))
+            if self.has_log:
+                netlog.info('', extra={
+                    'status': response.status,
+                    'byte': len(response.body),
+                    'host': '%s:%d' % self.request.ip,
+                    'request': '%s %s' % (self.request.method,
+                                          self.request.url)
+                })
         except AttributeError:
             log.error(
                 ('Invalid response object for url {}, '
@@ -227,6 +239,14 @@ class HttpProtocol(asyncio.Protocol):
             response.transport = self.transport
             await response.stream(
                 self.request.version, keep_alive, self.request_timeout)
+            if self.has_log:
+                netlog.info('', extra={
+                    'status': response.status,
+                    'byte': -1,
+                    'host': '%s:%d' % self.request.ip,
+                    'request': '%s %s' % (self.request.method,
+                                          self.request.url)
+                })
         except AttributeError:
             log.error(
                 ('Invalid response object for url {}, '
@@ -262,6 +282,21 @@ class HttpProtocol(asyncio.Protocol):
                 "Writing error failed, connection closed {}".format(repr(e)),
                 from_error=True)
         finally:
+            if self.has_log:
+                extra = {
+                    'status': response.status,
+                    'host': '',
+                    'request': str(self.request) + str(self.url)
+                }
+                if response and isinstance(response, HTTPResponse):
+                    extra['byte'] = len(response.body)
+                else:
+                    extra['byte'] = -1
+                if self.request:
+                    extra['host'] = '%s:%d' % self.request.ip,
+                    extra['request'] = '%s %s' % (self.request.method,
+                                                  self.url)
+                netlog.info('', extra=extra)
             self.transport.close()
 
     def bail_out(self, message, from_error=False):
@@ -325,7 +360,7 @@ def serve(host, port, request_handler, error_handler, before_start=None,
           request_timeout=60, ssl=None, sock=None, request_max_size=None,
           reuse_port=False, loop=None, protocol=HttpProtocol, backlog=100,
           register_sys_signals=True, run_async=False, connections=None,
-          signal=Signal(), request_class=None, keep_alive=True):
+          signal=Signal(), request_class=None, has_log=True, keep_alive=True):
     """Start asynchronous HTTP Server on an individual process.
 
     :param host: Address to host on
@@ -351,6 +386,7 @@ def serve(host, port, request_handler, error_handler, before_start=None,
     :param loop: asyncio compatible event loop
     :param protocol: subclass of asyncio protocol class
     :param request_class: Request class to use
+    :param has_log: disable/enable access log and error log
     :return: Nothing
     """
     if not run_async:
@@ -373,6 +409,7 @@ def serve(host, port, request_handler, error_handler, before_start=None,
         request_timeout=request_timeout,
         request_max_size=request_max_size,
         request_class=request_class,
+        has_log=has_log,
         keep_alive=keep_alive,
     )