diff --git a/docs/index.rst b/docs/index.rst index 3fa63d5c..80e7e70f 100644 --- a/docs/index.rst +++ b/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 diff --git a/docs/sanic/logging.md b/docs/sanic/logging.md new file mode 100644 index 00000000..c38a1c55 --- /dev/null +++ b/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))
+ For internal information console outputs. + + +- accessStream (using [logging.StreamHandler](https://docs.python.org/3/library/logging.handlers.html#logging.StreamHandler))
+ For requests information logging in console + + +- errorStream (using [logging.StreamHandler](https://docs.python.org/3/library/logging.handlers.html#logging.StreamHandler))
+ 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))
+ For requests information logging to syslog. + Currently supports Windows (via localhost:514), Darwin (/var/run/syslog), + Linux (/dev/log) and FreeBSD (/dev/log).
+ 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))
+ 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).
+ 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))
+ 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))
+ For error message and traceback logging to file with daily rotation support. + +And `filters`: + +- accessFilter (using sanic.defaultFilter.DefaultFilter)
+ The filter that allows only levels in `DEBUG`, `INFO`, and `NONE(0)` + + +- errorFilter (using sanic.defaultFilter.DefaultFilter)
+ 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:
+ Used to log internal messages. + + +- network:
+ 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)
+ request.ip + + +- request (str)
+ request.method + " " + request.url + + +- status (int)
+ response.status + + +- byte (int)
+ 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 +``` diff --git a/sanic/app.py b/sanic/app.py index 5bc7b468..c0505ab0 100644 --- a/sanic/app.py +++ b/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 } # -------------------------------------------- # diff --git a/sanic/config.py b/sanic/config.py index 4c128b4b..c12037fe 100644 --- a/sanic/config.py +++ b/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): diff --git a/sanic/defaultFilter.py b/sanic/defaultFilter.py new file mode 100644 index 00000000..9e9508ec --- /dev/null +++ b/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 diff --git a/sanic/log.py b/sanic/log.py index 1b4d7334..cce4a64f 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -1,3 +1,4 @@ import logging log = logging.getLogger('sanic') +netlog = logging.getLogger('network') diff --git a/sanic/server.py b/sanic/server.py index d10a75cf..16d300ba 100644 --- a/sanic/server.py +++ b/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, )