From c9a40c180a60f7c6f4943c619d81d71093e703c1 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Sun, 10 Sep 2017 11:11:16 -0700 Subject: [PATCH 01/12] remove some logging stuff --- sanic/app.py | 18 ++--------- sanic/config.py | 83 ------------------------------------------------- sanic/log.py | 13 -------- 3 files changed, 3 insertions(+), 111 deletions(-) diff --git a/sanic/app.py b/sanic/app.py index 20c02a5c..c585bf43 100644 --- a/sanic/app.py +++ b/sanic/app.py @@ -10,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, LOGGING +from sanic.config import Config from sanic.constants import HTTP_METHODS from sanic.exceptions import ServerError, URLBuildError, SanicException from sanic.handlers import ErrorHandler @@ -28,18 +28,7 @@ class Sanic: def __init__(self, name=None, router=None, error_handler=None, load_env=True, request_class=None, - log_config=LOGGING, strict_slashes=False): - 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: - formatter = logging.Formatter( - "%(asctime)s: %(levelname)s: %(message)s") - handler = logging.StreamHandler() - handler.setFormatter(formatter) - log.addHandler(handler) - log.setLevel(logging.INFO) + strict_slashes=False): # Get name from previous stack frame if name is None: @@ -51,7 +40,6 @@ 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 = {} @@ -642,7 +630,7 @@ class Sanic: async def create_server(self, host=None, port=None, debug=False, ssl=None, sock=None, protocol=None, backlog=100, stop_event=None, - log_config=LOGGING): + log_config=None): """Asynchronous version of `run`. NOTE: This does not support multiprocessing and is not the preferred diff --git a/sanic/config.py b/sanic/config.py index 0c2cc701..716ec1a6 100644 --- a/sanic/config.py +++ b/sanic/config.py @@ -15,89 +15,6 @@ _address_dict = { 'FreeBSD': '/var/run/log' } -LOGGING = { - 'version': 1, - 'disable_existing_loggers': False, - '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' - }, - }, - 'loggers': { - 'sanic': { - 'level': 'INFO', - 'handlers': ['internal', 'errorStream'] - }, - 'network': { - 'level': 'INFO', - '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/log.py b/sanic/log.py index 760ad1c6..a7933c0d 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -1,18 +1,5 @@ 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 - - log = logging.getLogger('sanic') netlog = logging.getLogger('network') From c9cbc00e362eda60f3af296d743e1ee6ca69626f Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Sun, 10 Sep 2017 18:38:52 -0700 Subject: [PATCH 02/12] use access_log as param --- sanic/app.py | 17 ++++++----------- sanic/server.py | 20 ++++++++++---------- 2 files changed, 16 insertions(+), 21 deletions(-) diff --git a/sanic/app.py b/sanic/app.py index c585bf43..595b50c1 100644 --- a/sanic/app.py +++ b/sanic/app.py @@ -567,7 +567,7 @@ class Sanic: def run(self, host=None, port=None, debug=False, ssl=None, sock=None, workers=1, protocol=None, backlog=100, stop_event=None, register_sys_signals=True, - log_config=None): + access_log=True): """Run the HTTP Server and listen until keyboard interrupt or term signal. On termination, drain connections before closing. @@ -588,9 +588,6 @@ class Sanic: if sock is None: host, port = host or "127.0.0.1", port or 8000 - if log_config: - self.log_config = log_config - logging.config.dictConfig(log_config) if protocol is None: protocol = (WebSocketProtocol if self.websocket_enabled else HttpProtocol) @@ -603,7 +600,7 @@ class Sanic: host=host, port=port, debug=debug, ssl=ssl, sock=sock, workers=workers, protocol=protocol, backlog=backlog, register_sys_signals=register_sys_signals, - has_log=self.log_config is not None) + access_log=access_log) try: self.is_running = True @@ -630,7 +627,7 @@ class Sanic: async def create_server(self, host=None, port=None, debug=False, ssl=None, sock=None, protocol=None, backlog=100, stop_event=None, - log_config=None): + access_log=True): """Asynchronous version of `run`. NOTE: This does not support multiprocessing and is not the preferred @@ -639,8 +636,6 @@ class Sanic: if sock is None: host, port = host or "127.0.0.1", port or 8000 - if log_config: - logging.config.dictConfig(log_config) if protocol is None: protocol = (WebSocketProtocol if self.websocket_enabled else HttpProtocol) @@ -654,7 +649,7 @@ class Sanic: host=host, port=port, debug=debug, ssl=ssl, sock=sock, loop=get_event_loop(), protocol=protocol, backlog=backlog, run_async=True, - has_log=log_config is not None) + access_log=access_log) # Trigger before_start events await self.trigger_events( @@ -699,7 +694,7 @@ class Sanic: def _helper(self, host=None, port=None, debug=False, ssl=None, sock=None, workers=1, loop=None, protocol=HttpProtocol, backlog=100, stop_event=None, - register_sys_signals=True, run_async=False, has_log=True): + register_sys_signals=True, run_async=False, access_log=True): """Helper function used by `run` and `create_server`.""" if isinstance(ssl, dict): # try common aliaseses @@ -738,7 +733,7 @@ class Sanic: 'loop': loop, 'register_sys_signals': register_sys_signals, 'backlog': backlog, - 'has_log': has_log, + 'access_log': access_log, 'websocket_max_size': self.config.WEBSOCKET_MAX_SIZE, 'websocket_max_queue': self.config.WEBSOCKET_MAX_QUEUE, 'graceful_shutdown_timeout': self.config.GRACEFUL_SHUTDOWN_TIMEOUT diff --git a/sanic/server.py b/sanic/server.py index f62ba654..3e52d634 100644 --- a/sanic/server.py +++ b/sanic/server.py @@ -65,15 +65,15 @@ class HttpProtocol(asyncio.Protocol): # request config 'request_handler', 'request_timeout', 'request_max_size', 'request_class', 'is_request_stream', 'router', - # enable or disable access log / error log purpose - 'has_log', + # enable or disable access log purpose + 'access_log', # connection management '_total_request_size', '_timeout_handler', '_last_communication_time', '_is_stream_handler') def __init__(self, *, loop, request_handler, error_handler, signal=Signal(), connections=set(), request_timeout=60, - request_max_size=None, request_class=None, has_log=True, + request_max_size=None, request_class=None, access_log=True, keep_alive=True, is_request_stream=False, router=None, state=None, debug=False, **kwargs): self.loop = loop @@ -84,7 +84,7 @@ class HttpProtocol(asyncio.Protocol): self.headers = None self.router = router self.signal = signal - self.has_log = has_log + self.access_log = access_log self.connections = connections self.request_handler = request_handler self.error_handler = error_handler @@ -246,7 +246,7 @@ class HttpProtocol(asyncio.Protocol): response.output( self.request.version, keep_alive, self.request_timeout)) - if self.has_log: + if self.access_log: netlog.info('', extra={ 'status': response.status, 'byte': len(response.body), @@ -288,7 +288,7 @@ class HttpProtocol(asyncio.Protocol): response.transport = self.transport await response.stream( self.request.version, keep_alive, self.request_timeout) - if self.has_log: + if self.access_log: netlog.info('', extra={ 'status': response.status, 'byte': -1, @@ -333,7 +333,7 @@ class HttpProtocol(asyncio.Protocol): "Writing error failed, connection closed {}".format(repr(e)), from_error=True) finally: - if self.has_log: + if self.access_log: extra = dict() if isinstance(response, HTTPResponse): extra['status'] = response.status @@ -424,7 +424,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, has_log=True, keep_alive=True, + signal=Signal(), request_class=None, access_log=True, keep_alive=True, is_request_stream=False, router=None, websocket_max_size=None, websocket_max_queue=None, state=None, graceful_shutdown_timeout=15.0): @@ -453,7 +453,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 + :param access_log: disable/enable access log :param is_request_stream: disable/enable Request.stream :param router: Router object :return: Nothing @@ -476,7 +476,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, + access_log=access_log, keep_alive=keep_alive, is_request_stream=is_request_stream, router=router, From 986135ff76f0a4e94d0842e5d1c79c5c43491e2f Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Sun, 10 Sep 2017 18:39:42 -0700 Subject: [PATCH 03/12] remove DefaultFilter --- sanic/config.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/sanic/config.py b/sanic/config.py index 716ec1a6..1f0bbd3e 100644 --- a/sanic/config.py +++ b/sanic/config.py @@ -4,8 +4,6 @@ import syslog import platform import types -from sanic.log import DefaultFilter - SANIC_PREFIX = 'SANIC_' _address_dict = { From 8f6fa5e9ffe0580407c8a999e35171664b4010b8 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Sun, 10 Sep 2017 18:44:54 -0700 Subject: [PATCH 04/12] old logging cleanup --- tests/test_logging.py | 18 ------------------ 1 file changed, 18 deletions(-) diff --git a/tests/test_logging.py b/tests/test_logging.py index d6911d86..3d75dbe0 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,7 +1,6 @@ import uuid from importlib import reload -from sanic.config import LOGGING from sanic.response import text from sanic import Sanic from io import StringIO @@ -38,20 +37,3 @@ def test_log(): request, response = app.test_client.get('/') log_text = log_stream.getvalue() assert rand_string in log_text - - -def test_default_log_fmt(): - - reset_logging() - Sanic() - for fmt in [h.formatter for h in logging.getLogger('sanic').handlers]: - assert fmt._fmt == LOGGING['formatters']['simple']['format'] - - reset_logging() - Sanic(log_config=None) - for fmt in [h.formatter for h in logging.getLogger('sanic').handlers]: - assert fmt._fmt == "%(asctime)s: %(levelname)s: %(message)s" - - -if __name__ == "__main__": - test_log() From 4bdb9a2c8e0d323352e136624e9558c4d1633aa9 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Sun, 10 Sep 2017 23:19:09 -0700 Subject: [PATCH 05/12] prototype --- sanic/log.py | 53 +++++++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 52 insertions(+), 1 deletion(-) diff --git a/sanic/log.py b/sanic/log.py index a7933c0d..3d254d6c 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -1,5 +1,56 @@ import logging +LOGGING_CONFIG_DEFAULTS = dict( + version=1, + disable_existing_loggers=False, + + loggers={ + "root": { + "level": "INFO", + "handlers": ["console"]}, + "sanic.error": { + "level": "INFO", + "handlers": ["error_console"], + "propagate": True, + "qualname": "sanic.error" + }, + + "sanic.access": { + "level": "INFO", + "handlers": ["console"], + "propagate": True, + "qualname": "sanic.access" + } + }, + handlers={ + "console": { + "class": "logging.StreamHandler", + "formatter": "generic", + "stream": "sys.stdout" + }, + "error_console": { + "class": "logging.StreamHandler", + "formatter": "generic", + "stream": "sys.stderr" + }, + }, + formatters={ + "generic": { + "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s", + "datefmt": "[%Y-%m-%d %H:%M:%S %z]", + "class": "logging.Formatter" + } + } +) + + +class AccessLogger: + + def __init__(self, logger, access_log_format=None): + pass + + log = logging.getLogger('sanic') -netlog = logging.getLogger('network') +error_logger = logging.getLogger('sanic.error') +access_logger = logging.getLogger('sanic.access') From a46e004f07600f9041da1c05d640bd870a643a4c Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Mon, 11 Sep 2017 22:12:49 -0700 Subject: [PATCH 06/12] apply new loggers --- sanic/__main__.py | 6 +++--- sanic/app.py | 14 +++++++------- sanic/handlers.py | 8 ++++---- sanic/log.py | 11 +++-------- sanic/request.py | 4 ++-- sanic/server.py | 34 +++++++++++++++++----------------- sanic/testing.py | 6 +++--- 7 files changed, 39 insertions(+), 44 deletions(-) diff --git a/sanic/__main__.py b/sanic/__main__.py index cc580566..1473aa5f 100644 --- a/sanic/__main__.py +++ b/sanic/__main__.py @@ -1,7 +1,7 @@ from argparse import ArgumentParser from importlib import import_module -from sanic.log import log +from sanic.log import logger from sanic.app import Sanic if __name__ == "__main__": @@ -36,9 +36,9 @@ if __name__ == "__main__": app.run(host=args.host, port=args.port, workers=args.workers, debug=args.debug, ssl=ssl) except ImportError as e: - log.error("No module named {} found.\n" + logger.error("No module named {} found.\n" " Example File: project/sanic_server.py -> app\n" " Example Module: project.sanic_server.app" .format(e.name)) except ValueError as e: - log.error("{}".format(e)) + logger.error("{}".format(e)) diff --git a/sanic/app.py b/sanic/app.py index 595b50c1..4c0fa15e 100644 --- a/sanic/app.py +++ b/sanic/app.py @@ -14,7 +14,7 @@ from sanic.config import Config from sanic.constants import HTTP_METHODS from sanic.exceptions import ServerError, URLBuildError, SanicException from sanic.handlers import ErrorHandler -from sanic.log import log +from sanic.log import logger, error_logger from sanic.response import HTTPResponse, StreamingHTTPResponse from sanic.router import Router from sanic.server import serve, serve_multiple, HttpProtocol, Signal @@ -542,7 +542,7 @@ class Sanic: response = await self._run_response_middleware(request, response) except: - log.exception( + error_logger.exception( 'Exception occured in one of response middleware handlers' ) @@ -609,12 +609,12 @@ class Sanic: else: serve_multiple(server_settings, workers) except: - log.exception( + error_logger.exception( 'Experienced exception while trying to serve') raise finally: self.is_running = False - log.info("Server Stopped") + logger.info("Server Stopped") def stop(self): """This kills the Sanic""" @@ -757,9 +757,9 @@ class Sanic: server_settings[settings_name] = listeners if debug: - log.setLevel(logging.DEBUG) + logger.setLevel(logging.DEBUG) if self.config.LOGO is not None: - log.debug(self.config.LOGO) + logger.debug(self.config.LOGO) if run_async: server_settings['run_async'] = True @@ -769,6 +769,6 @@ class Sanic: proto = "http" if ssl is not None: proto = "https" - log.info('Goin\' Fast @ {}://{}:{}'.format(proto, host, port)) + logger.info('Goin\' Fast @ {}://{}:{}'.format(proto, host, port)) return server_settings diff --git a/sanic/handlers.py b/sanic/handlers.py index 6a87fd5d..2e335b09 100644 --- a/sanic/handlers.py +++ b/sanic/handlers.py @@ -12,7 +12,7 @@ from sanic.exceptions import ( TRACEBACK_WRAPPER_HTML, TRACEBACK_WRAPPER_INNER_HTML, TRACEBACK_BORDER) -from sanic.log import log +from sanic.log import logger from sanic.response import text, html @@ -90,7 +90,7 @@ class ErrorHandler: 'Exception raised in exception handler "{}" ' 'for uri: "{}"\n{}').format( handler.__name__, url, format_exc()) - log.error(response_message) + logger.error(response_message) return text(response_message, 500) else: return text('An error occurred while handling an error', 500) @@ -101,7 +101,7 @@ class ErrorHandler: Override this method in an ErrorHandler subclass to prevent logging exceptions. """ - getattr(log, level)(message) + getattr(logger, level)(message) def default(self, request, exception): self.log(format_exc()) @@ -117,7 +117,7 @@ class ErrorHandler: response_message = ( 'Exception occurred while handling uri: "{}"\n{}'.format( request.url, format_exc())) - log.error(response_message) + logger.error(response_message) return html(html_output, status=500) else: return html(INTERNAL_SERVER_ERROR_HTML, status=500) diff --git a/sanic/log.py b/sanic/log.py index 3d254d6c..5abce0e2 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -8,7 +8,8 @@ LOGGING_CONFIG_DEFAULTS = dict( loggers={ "root": { "level": "INFO", - "handlers": ["console"]}, + "handlers": ["console"] + }, "sanic.error": { "level": "INFO", "handlers": ["error_console"], @@ -45,12 +46,6 @@ LOGGING_CONFIG_DEFAULTS = dict( ) -class AccessLogger: - - def __init__(self, logger, access_log_format=None): - pass - - -log = logging.getLogger('sanic') +logger = logging.getLogger('root') error_logger = logging.getLogger('sanic.error') access_logger = logging.getLogger('sanic.access') diff --git a/sanic/request.py b/sanic/request.py index 27ff011e..b54d463f 100644 --- a/sanic/request.py +++ b/sanic/request.py @@ -17,7 +17,7 @@ except ImportError: json_loads = json.loads from sanic.exceptions import InvalidUsage -from sanic.log import log +from sanic.log import logger DEFAULT_HTTP_CONTENT_TYPE = "application/octet-stream" @@ -114,7 +114,7 @@ class Request(dict): self.parsed_form, self.parsed_files = ( parse_multipart_form(self.body, boundary)) except Exception: - log.exception("Failed when parsing form") + logger.exception("Failed when parsing form") return self.parsed_form diff --git a/sanic/server.py b/sanic/server.py index 3e52d634..7764b120 100644 --- a/sanic/server.py +++ b/sanic/server.py @@ -24,7 +24,7 @@ try: except ImportError: async_loop = asyncio -from sanic.log import log, netlog +from sanic.log import logger, access_logger, error_logger from sanic.response import HTTPResponse from sanic.request import Request from sanic.exceptions import ( @@ -247,7 +247,7 @@ class HttpProtocol(asyncio.Protocol): self.request.version, keep_alive, self.request_timeout)) if self.access_log: - netlog.info('', extra={ + access_logger.info('', extra={ 'status': response.status, 'byte': len(response.body), 'host': '{0}:{1}'.format(self.request.ip[0], @@ -256,13 +256,13 @@ class HttpProtocol(asyncio.Protocol): self.request.url) }) except AttributeError: - log.error( + logger.error( ('Invalid response object for url {}, ' 'Expected Type: HTTPResponse, Actual Type: {}').format( self.url, type(response))) self.write_error(ServerError('Invalid response type')) except RuntimeError: - log.error( + logger.error( 'Connection lost before response written @ {}'.format( self.request.ip)) except Exception as e: @@ -289,7 +289,7 @@ class HttpProtocol(asyncio.Protocol): await response.stream( self.request.version, keep_alive, self.request_timeout) if self.access_log: - netlog.info('', extra={ + access_logger.info('', extra={ 'status': response.status, 'byte': -1, 'host': '{0}:{1}'.format(self.request.ip[0], @@ -298,13 +298,13 @@ class HttpProtocol(asyncio.Protocol): self.request.url) }) except AttributeError: - log.error( + logger.error( ('Invalid response object for url {}, ' 'Expected Type: HTTPResponse, Actual Type: {}').format( self.url, type(response))) self.write_error(ServerError('Invalid response type')) except RuntimeError: - log.error( + logger.error( 'Connection lost before response written @ {}'.format( self.request.ip)) except Exception as e: @@ -325,7 +325,7 @@ class HttpProtocol(asyncio.Protocol): version = self.request.version if self.request else '1.1' self.transport.write(response.output(version)) except RuntimeError: - log.error( + logger.error( 'Connection lost before error written @ {}'.format( self.request.ip if self.request else 'Unknown')) except Exception as e: @@ -350,21 +350,21 @@ class HttpProtocol(asyncio.Protocol): extra['request'] = 'nil' if self.parser and not (self.keep_alive and extra['status'] == 408): - netlog.info('', extra=extra) + access_logger.info('', extra=extra) self.transport.close() def bail_out(self, message, from_error=False): if from_error or self.transport.is_closing(): - log.error( + logger.error( ("Transport closed @ {} and exception " "experienced during error handling").format( self.transport.get_extra_info('peername'))) - log.debug( + logger.debug( 'Exception:\n{}'.format(traceback.format_exc())) else: exception = ServerError(message) self.write_error(exception) - log.error(message) + logger.error(message) def cleanup(self): self.parser = None @@ -508,7 +508,7 @@ def serve(host, port, request_handler, error_handler, before_start=None, try: http_server = loop.run_until_complete(server_coroutine) except: - log.exception("Unable to start server") + logger.exception("Unable to start server") return trigger_events(after_start, loop) @@ -519,14 +519,14 @@ def serve(host, port, request_handler, error_handler, before_start=None, try: loop.add_signal_handler(_signal, loop.stop) except NotImplementedError: - log.warn('Sanic tried to use loop.add_signal_handler but it is' + logger.warn('Sanic tried to use loop.add_signal_handler but it is' ' not implemented on this platform.') pid = os.getpid() try: - log.info('Starting worker [{}]'.format(pid)) + logger.info('Starting worker [{}]'.format(pid)) loop.run_forever() finally: - log.info("Stopping worker [{}]".format(pid)) + logger.info("Stopping worker [{}]".format(pid)) # Run the on_stop function if provided trigger_events(before_stop, loop) @@ -588,7 +588,7 @@ def serve_multiple(server_settings, workers): server_settings['port'] = None def sig_handler(signal, frame): - log.info("Received signal {}. Shutting down.".format( + logger.info("Received signal {}. Shutting down.".format( Signals(signal).name)) for process in processes: os.kill(process.pid, SIGINT) diff --git a/sanic/testing.py b/sanic/testing.py index de26d025..5d233d7b 100644 --- a/sanic/testing.py +++ b/sanic/testing.py @@ -1,7 +1,7 @@ import traceback from json import JSONDecodeError -from sanic.log import log +from sanic.log import logger HOST = '127.0.0.1' PORT = 42101 @@ -19,7 +19,7 @@ class SanicTestClient: url = 'http://{host}:{port}{uri}'.format( host=HOST, port=PORT, uri=uri) - log.info(url) + logger.info(url) conn = aiohttp.TCPConnector(verify_ssl=False) async with aiohttp.ClientSession( cookies=cookies, connector=conn) as session: @@ -61,7 +61,7 @@ class SanicTestClient: **request_kwargs) results[-1] = response except Exception as e: - log.error( + logger.error( 'Exception:\n{}'.format(traceback.format_exc())) exceptions.append(e) self.app.stop() From 24bdb1ce98d8c918cc1503892cd148a4e5b7c3d7 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Tue, 12 Sep 2017 23:42:42 -0700 Subject: [PATCH 07/12] add unit tests/refactoring --- sanic/app.py | 15 +++++++++++---- sanic/config.py | 8 +------- sanic/log.py | 15 +++++++++++++-- sanic/request.py | 4 ++-- tests/test_logging.py | 34 ++++++++++++++++++++++++++++++++++ 5 files changed, 61 insertions(+), 15 deletions(-) diff --git a/sanic/app.py b/sanic/app.py index 4c0fa15e..1d4497d0 100644 --- a/sanic/app.py +++ b/sanic/app.py @@ -14,7 +14,7 @@ from sanic.config import Config from sanic.constants import HTTP_METHODS from sanic.exceptions import ServerError, URLBuildError, SanicException from sanic.handlers import ErrorHandler -from sanic.log import logger, error_logger +from sanic.log import logger, error_logger, LOGGING_CONFIG_DEFAULTS from sanic.response import HTTPResponse, StreamingHTTPResponse from sanic.router import Router from sanic.server import serve, serve_multiple, HttpProtocol, Signal @@ -28,13 +28,16 @@ class Sanic: def __init__(self, name=None, router=None, error_handler=None, load_env=True, request_class=None, - strict_slashes=False): + strict_slashes=False, log_config=None): # Get name from previous stack frame if name is None: frame_records = stack()[1] name = getmodulename(frame_records[1]) + # logging + logging.config.dictConfig(log_config or LOGGING_CONFIG_DEFAULTS) + self.name = name self.router = router or Router() self.request_class = request_class @@ -567,7 +570,7 @@ class Sanic: def run(self, host=None, port=None, debug=False, ssl=None, sock=None, workers=1, protocol=None, backlog=100, stop_event=None, register_sys_signals=True, - access_log=True): + access_log=True, log_config=None): """Run the HTTP Server and listen until keyboard interrupt or term signal. On termination, drain connections before closing. @@ -585,6 +588,8 @@ class Sanic: :param protocol: Subclass of asyncio protocol class :return: Nothing """ + logging.config.dictConfig(log_config or LOGGING_CONFIG_DEFAULTS) + if sock is None: host, port = host or "127.0.0.1", port or 8000 @@ -627,12 +632,14 @@ class Sanic: async def create_server(self, host=None, port=None, debug=False, ssl=None, sock=None, protocol=None, backlog=100, stop_event=None, - access_log=True): + access_log=True, log_config=None): """Asynchronous version of `run`. NOTE: This does not support multiprocessing and is not the preferred way to run a Sanic application. """ + logging.config.dictConfig(log_config or LOGGING_CONFIG_DEFAULTS) + if sock is None: host, port = host or "127.0.0.1", port or 8000 diff --git a/sanic/config.py b/sanic/config.py index 1f0bbd3e..b5430445 100644 --- a/sanic/config.py +++ b/sanic/config.py @@ -4,14 +4,8 @@ import syslog import platform import types -SANIC_PREFIX = 'SANIC_' -_address_dict = { - 'Windows': ('localhost', 514), - 'Darwin': '/var/run/syslog', - 'Linux': '/dev/log', - 'FreeBSD': '/var/run/log' -} +SANIC_PREFIX = 'SANIC_' class Config(dict): diff --git a/sanic/log.py b/sanic/log.py index 5abce0e2..72636cd0 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -19,7 +19,7 @@ LOGGING_CONFIG_DEFAULTS = dict( "sanic.access": { "level": "INFO", - "handlers": ["console"], + "handlers": ["access_console"], "propagate": True, "qualname": "sanic.access" } @@ -35,13 +35,24 @@ LOGGING_CONFIG_DEFAULTS = dict( "formatter": "generic", "stream": "sys.stderr" }, + "access_console": { + "class": "logging.StreamHandler", + "formatter": "access", + "stream": "sys.stdout" + }, }, formatters={ "generic": { "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s", "datefmt": "[%Y-%m-%d %H:%M:%S %z]", "class": "logging.Formatter" - } + }, + "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 %z]", + "class": "logging.Formatter" + }, } ) diff --git a/sanic/request.py b/sanic/request.py index b54d463f..c842cb4b 100644 --- a/sanic/request.py +++ b/sanic/request.py @@ -17,7 +17,7 @@ except ImportError: json_loads = json.loads from sanic.exceptions import InvalidUsage -from sanic.log import logger +from sanic.log import error_logger DEFAULT_HTTP_CONTENT_TYPE = "application/octet-stream" @@ -114,7 +114,7 @@ class Request(dict): self.parsed_form, self.parsed_files = ( parse_multipart_form(self.body, boundary)) except Exception: - logger.exception("Failed when parsing form") + error_logger.exception("Failed when parsing form") return self.parsed_form diff --git a/tests/test_logging.py b/tests/test_logging.py index 3d75dbe0..112c94a0 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -2,6 +2,7 @@ import uuid from importlib import reload from sanic.response import text +from sanic.log import LOGGING_CONFIG_DEFAULTS from sanic import Sanic from io import StringIO import logging @@ -37,3 +38,36 @@ def test_log(): request, response = app.test_client.get('/') log_text = log_stream.getvalue() assert rand_string in log_text + + +def test_logging_defaults(): + reset_logging() + app = Sanic("test_logging") + + for fmt in [h.formatter for h in logging.getLogger('root').handlers]: + assert fmt._fmt == LOGGING_CONFIG_DEFAULTS['formatters']['generic']['format'] + + for fmt in [h.formatter for h in logging.getLogger('sanic.error').handlers]: + assert fmt._fmt == LOGGING_CONFIG_DEFAULTS['formatters']['generic']['format'] + + for fmt in [h.formatter for h in logging.getLogger('sanic.access').handlers]: + assert fmt._fmt == LOGGING_CONFIG_DEFAULTS['formatters']['access']['format'] + + +def test_logging_pass_customer_logconfig(): + reset_logging() + + modified_config = LOGGING_CONFIG_DEFAULTS + modified_config['formatters']['generic']['format'] = '%(asctime)s - (%(name)s)[%(levelname)s]: %(message)s' + modified_config['formatters']['access']['format'] = '%(asctime)s - (%(name)s)[%(levelname)s]: %(message)s' + + app = Sanic("test_logging", log_config=modified_config) + + for fmt in [h.formatter for h in logging.getLogger('root').handlers]: + assert fmt._fmt == modified_config['formatters']['generic']['format'] + + for fmt in [h.formatter for h in logging.getLogger('sanic.error').handlers]: + assert fmt._fmt == modified_config['formatters']['generic']['format'] + + for fmt in [h.formatter for h in logging.getLogger('sanic.access').handlers]: + assert fmt._fmt == modified_config['formatters']['access']['format'] From 9c4b0f7b15f240f81b249848e649278226eb0a62 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Wed, 13 Sep 2017 07:40:42 -0700 Subject: [PATCH 08/12] fix flake8 --- sanic/__main__.py | 6 +-- sanic/config.py | 3 -- sanic/log.py | 98 +++++++++++++++++++++++------------------------ sanic/server.py | 13 ++++--- 4 files changed, 59 insertions(+), 61 deletions(-) diff --git a/sanic/__main__.py b/sanic/__main__.py index 1473aa5f..594256f8 100644 --- a/sanic/__main__.py +++ b/sanic/__main__.py @@ -37,8 +37,8 @@ if __name__ == "__main__": workers=args.workers, debug=args.debug, ssl=ssl) except ImportError as e: logger.error("No module named {} found.\n" - " Example File: project/sanic_server.py -> app\n" - " Example Module: project.sanic_server.app" - .format(e.name)) + " Example File: project/sanic_server.py -> app\n" + " Example Module: project.sanic_server.app" + .format(e.name)) except ValueError as e: logger.error("{}".format(e)) diff --git a/sanic/config.py b/sanic/config.py index b5430445..a79c1c12 100644 --- a/sanic/config.py +++ b/sanic/config.py @@ -1,7 +1,4 @@ import os -import sys -import syslog -import platform import types diff --git a/sanic/log.py b/sanic/log.py index 72636cd0..f9f96005 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -2,58 +2,58 @@ import logging LOGGING_CONFIG_DEFAULTS = dict( - version=1, - disable_existing_loggers=False, + version=1, + disable_existing_loggers=False, - loggers={ - "root": { - "level": "INFO", - "handlers": ["console"] - }, - "sanic.error": { - "level": "INFO", - "handlers": ["error_console"], - "propagate": True, - "qualname": "sanic.error" - }, + loggers={ + "root": { + "level": "INFO", + "handlers": ["console"] + }, + "sanic.error": { + "level": "INFO", + "handlers": ["error_console"], + "propagate": True, + "qualname": "sanic.error" + }, - "sanic.access": { - "level": "INFO", - "handlers": ["access_console"], - "propagate": True, - "qualname": "sanic.access" - } - }, - handlers={ - "console": { - "class": "logging.StreamHandler", - "formatter": "generic", - "stream": "sys.stdout" - }, - "error_console": { - "class": "logging.StreamHandler", - "formatter": "generic", - "stream": "sys.stderr" - }, - "access_console": { - "class": "logging.StreamHandler", - "formatter": "access", - "stream": "sys.stdout" - }, - }, - formatters={ - "generic": { - "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s", - "datefmt": "[%Y-%m-%d %H:%M:%S %z]", - "class": "logging.Formatter" - }, - "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 %z]", - "class": "logging.Formatter" - }, + "sanic.access": { + "level": "INFO", + "handlers": ["access_console"], + "propagate": True, + "qualname": "sanic.access" } + }, + handlers={ + "console": { + "class": "logging.StreamHandler", + "formatter": "generic", + "stream": "sys.stdout" + }, + "error_console": { + "class": "logging.StreamHandler", + "formatter": "generic", + "stream": "sys.stderr" + }, + "access_console": { + "class": "logging.StreamHandler", + "formatter": "access", + "stream": "sys.stdout" + }, + }, + formatters={ + "generic": { + "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s", + "datefmt": "[%Y-%m-%d %H:%M:%S %z]", + "class": "logging.Formatter" + }, + "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 %z]", + "class": "logging.Formatter" + }, + } ) diff --git a/sanic/server.py b/sanic/server.py index 7764b120..75c4ee55 100644 --- a/sanic/server.py +++ b/sanic/server.py @@ -24,7 +24,7 @@ try: except ImportError: async_loop = asyncio -from sanic.log import logger, access_logger, error_logger +from sanic.log import logger, access_logger from sanic.response import HTTPResponse from sanic.request import Request from sanic.exceptions import ( @@ -424,9 +424,9 @@ 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, access_log=True, keep_alive=True, - is_request_stream=False, router=None, websocket_max_size=None, - websocket_max_queue=None, state=None, + signal=Signal(), request_class=None, access_log=True, + keep_alive=True, is_request_stream=False, router=None, + websocket_max_size=None, websocket_max_queue=None, state=None, graceful_shutdown_timeout=15.0): """Start asynchronous HTTP Server on an individual process. @@ -519,8 +519,9 @@ def serve(host, port, request_handler, error_handler, before_start=None, try: loop.add_signal_handler(_signal, loop.stop) except NotImplementedError: - logger.warn('Sanic tried to use loop.add_signal_handler but it is' - ' not implemented on this platform.') + logger.warn( + 'Sanic tried to use loop.add_signal_handler but it is' + ' not implemented on this platform.') pid = os.getpid() try: logger.info('Starting worker [{}]'.format(pid)) From 5ee7b6caeba6b39ac0400c59ed9a16c0de316427 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Wed, 13 Sep 2017 10:35:34 -0700 Subject: [PATCH 09/12] fixing small issue --- sanic/app.py | 6 ++---- sanic/log.py | 7 ++++--- 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/sanic/app.py b/sanic/app.py index 1d4497d0..f06e9cd4 100644 --- a/sanic/app.py +++ b/sanic/app.py @@ -570,7 +570,7 @@ class Sanic: def run(self, host=None, port=None, debug=False, ssl=None, sock=None, workers=1, protocol=None, backlog=100, stop_event=None, register_sys_signals=True, - access_log=True, log_config=None): + access_log=True): """Run the HTTP Server and listen until keyboard interrupt or term signal. On termination, drain connections before closing. @@ -588,7 +588,6 @@ class Sanic: :param protocol: Subclass of asyncio protocol class :return: Nothing """ - logging.config.dictConfig(log_config or LOGGING_CONFIG_DEFAULTS) if sock is None: host, port = host or "127.0.0.1", port or 8000 @@ -632,13 +631,12 @@ class Sanic: async def create_server(self, host=None, port=None, debug=False, ssl=None, sock=None, protocol=None, backlog=100, stop_event=None, - access_log=True, log_config=None): + access_log=True): """Asynchronous version of `run`. NOTE: This does not support multiprocessing and is not the preferred way to run a Sanic application. """ - logging.config.dictConfig(log_config or LOGGING_CONFIG_DEFAULTS) if sock is None: host, port = host or "127.0.0.1", port or 8000 diff --git a/sanic/log.py b/sanic/log.py index f9f96005..9c6d868d 100644 --- a/sanic/log.py +++ b/sanic/log.py @@ -1,4 +1,5 @@ import logging +import sys LOGGING_CONFIG_DEFAULTS = dict( @@ -28,17 +29,17 @@ LOGGING_CONFIG_DEFAULTS = dict( "console": { "class": "logging.StreamHandler", "formatter": "generic", - "stream": "sys.stdout" + "stream": sys.stdout }, "error_console": { "class": "logging.StreamHandler", "formatter": "generic", - "stream": "sys.stderr" + "stream": sys.stderr }, "access_console": { "class": "logging.StreamHandler", "formatter": "access", - "stream": "sys.stdout" + "stream": sys.stdout }, }, formatters={ From ddc039ed2e0df68908f2a9c673c6440f2704fa8d Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Wed, 13 Sep 2017 18:14:46 -0700 Subject: [PATCH 10/12] update doc --- docs/sanic/logging.md | 65 ++++++++----------------------------------- 1 file changed, 12 insertions(+), 53 deletions(-) diff --git a/docs/sanic/logging.md b/docs/sanic/logging.md index eb807388..092df5c7 100644 --- a/docs/sanic/logging.md +++ b/docs/sanic/logging.md @@ -9,12 +9,6 @@ A simple example using default settings 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'] = [ - 'accessSysLog', 'errorSysLog'] app = Sanic('test') @@ -23,14 +17,14 @@ async def test(request): return response.text('Hello World!') if __name__ == "__main__": - app.run(log_config=LOGGING) + app.run(debug=True, access_log=True) ``` -And to close logging, simply assign log_config=None: +And to close logging, simply assign access_log=False: ```python if __name__ == "__main__": - app.run(log_config=None) + app.run(access_log=False) ``` This would skip calling logging functions when handling requests. @@ -38,59 +32,24 @@ 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) + # disable debug messages + app.run(debug=False, access_log=False) ``` ### Configuration -By default, log_config parameter is set to use sanic.config.LOGGING dictionary for configuration. The default configuration provides several predefined `handlers`: +By default, log_config parameter is set to use sanic.log.LOGGING_CONFIG_DEFAULTS dictionary for configuration. -- internal (using [logging.StreamHandler](https://docs.python.org/3/library/logging.handlers.html#logging.StreamHandler))
- For internal information console outputs. +There are three `loggers` used in sanic, and **must be defined if you want to create your own logging configuration**: - -- 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) - - -And `filters`: - -- accessFilter (using sanic.log.DefaultFilter)
- The filter that allows only levels in `DEBUG`, `INFO`, and `NONE(0)` - - -- errorFilter (using sanic.log.DefaultFilter)
- The filter that 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:
+- root:
Used to log internal messages. +- sanic.error:
+ Used to log error logs. -- network:
- Used to log requests from network, and any information from those requests. +- sanic.access:
+ Used to log access logs. #### Log format: From 5cabc9cff2dc023db0e0667cba232e30cc1dbd96 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Wed, 13 Sep 2017 18:16:58 -0700 Subject: [PATCH 11/12] update doc --- docs/sanic/logging.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/sanic/logging.md b/docs/sanic/logging.md index 092df5c7..286282f0 100644 --- a/docs/sanic/logging.md +++ b/docs/sanic/logging.md @@ -54,7 +54,7 @@ There are three `loggers` used in sanic, and **must be defined if you want to cr #### Log format: In addition to default parameters provided by python (asctime, levelname, message), -Sanic provides additional parameters for network logger with accessFilter: +Sanic provides additional parameters for access logger with: - host (str)
request.ip From 730f7c5e41635d5ab7a78102f4c534acab758392 Mon Sep 17 00:00:00 2001 From: Yun Xu Date: Wed, 13 Sep 2017 18:30:38 -0700 Subject: [PATCH 12/12] add doc for customizing logging config --- docs/sanic/logging.md | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/docs/sanic/logging.md b/docs/sanic/logging.md index 286282f0..49805d0e 100644 --- a/docs/sanic/logging.md +++ b/docs/sanic/logging.md @@ -20,6 +20,13 @@ if __name__ == "__main__": app.run(debug=True, access_log=True) ``` +To use your own logging config, simply use `logging.config.dictConfig`, or +pass `log_config` when you initialize `Sanic` app: + +```python +app = Sanic('test', log_config=LOGGING_CONFIG) +``` + And to close logging, simply assign access_log=False: ```python