From 7469083f0b9cb6142e3cc753dc784aeac1bdee67 Mon Sep 17 00:00:00 2001 From: Gergely Polonkai Date: Wed, 2 May 2018 12:35:15 +0200 Subject: [PATCH] Rewrite the whole thing as a Formatter Having a complete `Logger` class for this purpose is a bit of an overkill. --- docs/conf.py | 4 +- flask_logging_extras/__init__.py | 231 +++++++-------------------- setup.py | 2 +- tests/test_logger_keywords.py | 261 ++++++++++--------------------- 4 files changed, 148 insertions(+), 350 deletions(-) diff --git a/docs/conf.py b/docs/conf.py index 226bac1..40e4fdb 100644 --- a/docs/conf.py +++ b/docs/conf.py @@ -60,9 +60,9 @@ author = 'Gergely Polonkai' # built documents. # # The short X.Y version. -version = '0.1' +version = '1.0' # The full version, including alpha/beta/rc tags. -release = '0.1.1' +release = '1.0.0' # The language for content autogenerated by Sphinx. Refer to documentation # for a list of supported languages. diff --git a/flask_logging_extras/__init__.py b/flask_logging_extras/__init__.py index ffb0fc5..92cd9e2 100644 --- a/flask_logging_extras/__init__.py +++ b/flask_logging_extras/__init__.py @@ -34,15 +34,15 @@ import logging from flask import has_request_context, request, current_app, has_app_context -__version_info__ = ('0', '0', '1') +__version_info__ = ('1', '0', '0') __version__ = '.'.join(__version_info__) __author__ = 'Gergely Polonkai' __license__ = 'MIT' -__copyright__ = '(c) 2015 GT2' +__copyright__ = '(c) 2015-2018 Benchmarked.games' -class FlaskExtraLogger(logging.getLoggerClass()): - """ - A logger class that is capable of adding extra keywords to log + +class FlaskExtraLoggerFormatter(logging.Formatter): + """A log formatter class that is capable of adding extra keywords to log formatters and logging the blueprint name Usage: @@ -50,205 +50,92 @@ class FlaskExtraLogger(logging.getLoggerClass()): .. code-block:: python import logging + from logging.config import dictConfig - from flask_logging_extras import register_logger_class - - # This must be done before the app is initialized! - register_logger_class(cls=FlaskExtraLogger) + dictConfig({ + 'formatters': { + 'extras': { + 'format': '[%(asctime)s] [%(levelname)s] [%(category)s] [%(blueprint)s] %(message)s', + }, + }, + 'handlers': { + 'extras_handler': { + 'class': 'logging.FileHandler', + 'args': ('app.log', 'a'), + 'formatter': 'extras', + 'level': 'INFO', + }, + }, + 'loggers': { + 'my_app': { + 'handlers': ['extras_handler'], + } + }, + }) app = Flask(__name__) app.config['FLASK_LOGGING_EXTRAS_KEYWORDS'] = {'category': ''} app.config['FLASK_LOGGING_EXTRAS_BLUEPRINT'] = ('blueprint', '', '') - app.logger.init_app() bp = Blueprint('my_blueprint', __name__) app.register_blueprint(bp) - formatter = logging.Formatter( - '[%(asctime)s] [%(levelname)s] [%(category)s] %(message)s') - handler = logging.FileHandler('app.log', mode='a') - handler.setFormatter(formatter) - handler.setLevel(logging.INFO) - - app.logger.addHandler(handler) - - app.logger.info('The message', category='my category') + logger = logging.getLogger('my_app') # This will produce something like this in app.log: - # [2017-01-16 08:44:48.944] [INFO] [my category] The message + # [2018-05-02 12:44:48.944] [INFO] [my category] [] The message + logger.info('The message', extra=dict(category='my category')) - formatter = logging.Formatter('[%(blueprint)s] %(message)s') - handler = logging.FileHandler('other.log', mode='a') - handler.setFormatter(formatter) - handler.setLevel(logging.INFO) - - app.logger.addHandler(handler) - - @app.route('/1/') + @app.route('/1') def route_1(): - # This will produce this log message: - # [] Message - current_app.logger.info('Message') + # This will produce a log message like this: + # [2018-05-02 12:44:48.944] [INFO] [] [] Message + logger.info('Message') return '' @bp.route('/2') def route_2(): - # This will produce this log message: - # [my blueprint] Message - current_app.logger.info('Message') + # This will produce a log message like this: + # [2018-05-02 12:44:48.944] [INFO] [] [my_blueprint] Message + logger.info('Message') return '' - # This will produce this log message: - [] Message - app.logger.info('Message') + # This will produce a log message like this: + # [2018-05-02 12:44:48.944] [INFO] [] [] Message + logger.info('Message') """ - _RESERVED_KEYWORDS = ('exc_info', 'extra', 'stack_info') - - def __init__(self, *args, **kwargs): - if 'app' in kwargs: - if kwargs['app'] is not None: - raise TypeError( - "Cannot initialise {classname} with an app. See the" - "documentation of Flask-Logging-Extras for more info." - .format(classname=self.__class__.__name__)) - else: - # If app is None, treat it as if it wasn’t there - del(kwargs['app']) - - self.app = None - self._valid_keywords = {} - self._blueprint_var = None - self._blueprint_app = None - self._blueprint_norequest = None - - super(FlaskExtraLogger, self).__init__(*args, **kwargs) - - if hasattr(self.__class__, '__default_config__'): - self.config = self.__class__.__default_config__ - self.init_from_config() - - def _log(self, *args, **kwargs): - if has_app_context() and self.app is None: - self.init_app(current_app) - - if 'extra' not in kwargs: - kwargs['extra'] = {} - - # If we were asked to log the blueprint name, add it to the extra list - if self._blueprint_var is not None: - if has_request_context(): - kwargs['extra'][self._blueprint_var] = request.blueprint or self._blueprint_app - else: - kwargs['extra'][self._blueprint_var] = self._blueprint_norequest - - for kw in self._valid_keywords: - if kw in kwargs: - kwargs['extra'][kw] = kwargs[kw] - del(kwargs[kw]) - else: - kwargs['extra'][kw] = self._valid_keywords[kw] - - super(FlaskExtraLogger, self)._log(*args, **kwargs) - - def _check_reserved_word(self, word): - if word in self._RESERVED_KEYWORDS: - raise ValueError( - '"{keyword}" cannot be used as an extra keyword, as it is ' - 'reserved for internal use.' - .format(keyword=word)) - - def init_from_config(self): - """Intialize the logger class from a Flask config dict - - The class reads its necessary configuration from the config provided. - - If the application doesn’t call this, or doesn’t have the `FLASK_LOGGING_EXTRAS_KEYWORDS` - in its config, no extra functionality will be added. - - :raises ValueError: if the app tries to register a keyword that is - reserved for internal use - + def _collect_keywords(self, record): + """Collect all valid keywords and add them to the log record if not present """ - if not isinstance(self.config, dict): - self.config = { - 'FLASK_LOGGING_EXTRAS_KEYWORDS': getattr(self.config, 'FLASK_LOGGING_EXTRAS_KEYWORDS', {}), - 'FLASK_LOGGING_EXTRAS_BLUEPRINT': getattr(self.config, 'FLASK_LOGGING_EXTRAS_BLUEPRINT', (None, '', '',)), - } + # We assume we do have an active app context here + defaults = current_app.config.get('FLASK_LOGGING_EXTRAS_KEYWORDS', {}) - self.config.setdefault('FLASK_LOGGING_EXTRAS_KEYWORDS', {}) - self.config.setdefault('FLASK_LOGGING_EXTRAS_BLUEPRINT', - (None, '', '')) + for keyword, default in defaults.items(): + if keyword not in record.__dict__: + setattr(record, keyword, default) - for kw in self.config['FLASK_LOGGING_EXTRAS_KEYWORDS']: - self._check_reserved_word(kw) + def format(self, record): + bp_var, bp_app, bp_noreq = ('blueprint', '', '') + blueprint = None - self._check_reserved_word( - self.config['FLASK_LOGGING_EXTRAS_BLUEPRINT'][0]) + if has_app_context(): + self._collect_keywords(record) - self._valid_keywords = self.config['FLASK_LOGGING_EXTRAS_KEYWORDS'] - ( - self._blueprint_var, - self._blueprint_app, - self._blueprint_norequest, - ) = self.config['FLASK_LOGGING_EXTRAS_BLUEPRINT'] + bp_var, bp_app, bp_noreq = current_app.config.get('FLASK_LOGGING_EXTRAS_BLUEPRINT', + (bp_var, bp_app, bp_noreq)) - def init_app(self, app): - """ - Intialize the logger class with a Flask application + if bp_var and has_request_context(): + blueprint = request.blueprint or bp_app - The class reads its necessary configuration from the config of this - application. + if bp_var and bp_var not in record.__dict__: + blueprint = blueprint or bp_noreq - If the application doesn’t call this, or doesn’t have the - `FLASK_LOGGING_EXTRAS_KEYWORDS` in its config, no extra - functionality will be added. + setattr(record, bp_var, blueprint) - :param app: a Flask application - :type app: Flask - :raises ValueError: if the app tries to register a keyword that is - reserved for internal use - """ - - self.app = app - self.config = app.config - self.init_from_config() - - -def register_logger_class(cls=FlaskExtraLogger, config=None): - """ - Register a new logger class - - It is effectively a wrapper around `logging.setLoggerClass()`, with an - added check to make sure the class can be used as a logger. - - To use the extra features of the logger class in a Flask app, you must - call it before the app is instantiated. - - This function returns the logger class that was the default before - calling. This might be useful if you only want to use `cls` in the - Flask app object, but not anywhere else in your code. In this case, - simply call `register_logger_class()` again with the return value from - the first invocation. - - :param cls: a logger class to register as the default one - :type cls: class(logging.Logger) - :returns: the old default logger class - :rtype: class - :raises TypeError: if the class is not a subclass of `logging.Logger` - """ - - if not issubclass(cls, logging.Logger): - raise TypeError( - "The logger class must be a subclass of logging.Logger!") - - old_class = logging.getLoggerClass() - logging.setLoggerClass(cls) - cls.__default_config__ = config - - return old_class + return super(FlaskExtraLoggerFormatter, self).format(record) diff --git a/setup.py b/setup.py index e3b5234..10f7cb1 100644 --- a/setup.py +++ b/setup.py @@ -8,7 +8,7 @@ Flask-Logging-Extras provides extra logging functionality for Flask apps. from setuptools import setup setup(name='Flask-Logging-Extras', - version='0.2.0', + version='1.0.0', url='https://github.com/gergelypolonkai/flask-logging-extras', license='MIT', author='Gergely Polonkai', diff --git a/tests/test_logger_keywords.py b/tests/test_logger_keywords.py index 218d7d2..d39db99 100644 --- a/tests/test_logger_keywords.py +++ b/tests/test_logger_keywords.py @@ -1,9 +1,9 @@ # -*- coding: utf-8 -*- -""" -Unit tests for Flask-Logging-Extras +"""Unit tests for Flask-Logging-Extras """ import logging +from logging.config import dictConfig import sys from unittest import TestCase @@ -11,203 +11,124 @@ from flask import Flask, Blueprint, current_app import flask_logging_extras -class ListStream(object): - """ - Primitive stream that stores its input lines in a list - """ +class ListHandler(logging.StreamHandler): def __init__(self, *args, **kwargs): - self.lines = [] + super(ListHandler, self).__init__(*args, **kwargs) - super(ListStream, self).__init__(*args, **kwargs) + self.logs = [] - def write(self, data): - if len(self.lines) == 0 or self.lines[-1].endswith('\n'): - self.lines.append(data) - else: - self.lines[-1] += data + def emit(self, record): + try: + msg = self.format(record) + except (KeyError, IndexError) as exc: + msg = (exc.__class__.__name__, str(exc)) + + self.logs.append(msg) -class TestingStreamHandler(logging.StreamHandler): - def handleError(self, record): - exc, exc_msg, trace = sys.exc_info() +def configure_loggers(extra_var): + dictConfig({ + 'version': 1, + 'disable_existing_loggers': True, + 'formatters': { + 'selftest': { + 'class': 'flask_logging_extras.FlaskExtraLoggerFormatter', + 'format': '%(message)s %({extra_var})s'.format(extra_var=extra_var), + }, + }, + 'handlers': { + 'selftest': { + 'class': 'test_logger_keywords.ListHandler', + 'formatter': 'selftest', + }, + }, + 'loggers': { + 'selftest': { + 'handlers': ['selftest'], + 'level': 'INFO', + }, + }, + }) - super(logging.StreamHandler, self).handleError(record) + formatter = flask_logging_extras.FlaskExtraLoggerFormatter( + fmt='%(message)s %({extra_var})s'.format(extra_var=extra_var)) - raise(exc(exc_msg)) + logger = logging.getLogger('selftest') + handlers = [handler for handler in logger.handlers if isinstance(handler, ListHandler)] + handler = handlers[0] + # TODO: Why doesn’t this happen automatically in Python 2.7? + handler.setFormatter(formatter) + + return logger, handler class LoggerKeywordsTestCase(TestCase): def setUp(self): - self.original_logger_class = logging.getLoggerClass() + self.logger, self.handler = configure_loggers('extra_keyword') + self.app = Flask('test_app') + self.app.config['FLASK_LOGGING_EXTRAS_KEYWORDS'] = { + 'extra_keyword': 'placeholder', + } - def tearDown(self): - logging.setLoggerClass(self.original_logger_class) + # Make sure we don’t try to log the current blueprint for this test case + self.app.config['FLASK_LOGGING_EXTRAS_BLUEPRINT'] = (None, '', '') - def test_logger_registration(self): - class NotLoggerClass(object): - pass + def test_keywords_no_app_ctx(self): + """With the current formatter, the last log line must be a just the message + """ - with self.assertRaises(TypeError): - flask_logging_extras.register_logger_class(cls=NotLoggerClass) + self.logger.info('message') + self.assertIn(('KeyError', "'extra_keyword'"), self.handler.logs) - original_logging_class = logging.getLoggerClass() - - old_class = flask_logging_extras.register_logger_class() - - # If no class is specified, FlaskExtraLogger should be registered - self.assertEqual(logging.getLoggerClass(), - flask_logging_extras.FlaskExtraLogger) - # The return value of this function should be the old default - self.assertEqual(original_logging_class, old_class) - - class MyLogger(logging.Logger): - pass - - # Calling register_logger_class() with any subclass of - # logging.Logger should succeed - flask_logging_extras.register_logger_class(cls=MyLogger) - - def test_logger_class(self): - # If app is present during __init__, and is not None, we should get - # a TypeError - with self.assertRaises(TypeError): - flask_logging_extras.FlaskExtraLogger('test_logger', - app='test value') - - # If app is present, but is None, no exception should be raised - flask_logging_extras.FlaskExtraLogger('test_logger', app=None) - - def test_logger_class_init_app(self): - logger = flask_logging_extras.FlaskExtraLogger('test') - app = Flask('test_app') - - logger.init_app(app) - - self.assertEqual({}, logger._valid_keywords) - - app.config['FLASK_LOGGING_EXTRAS_KEYWORDS'] = {'exc_info': None} - - with self.assertRaises(ValueError): - logger.init_app(app) - - app.config['FLASK_LOGGING_EXTRAS_KEYWORDS'] = {'my_keyword': ''} - - logger.init_app(app) - self.assertEqual({'my_keyword': ''}, logger._valid_keywords) - - # Without registration first, app.logger should not be of class - # FlaskExtraLogger (even though logger.init_app() succeeded without - # it.) - self.assertNotIsInstance(app.logger, - flask_logging_extras.FlaskExtraLogger) - - flask_logging_extras.register_logger_class() - - # Even after registratiiion, existing apps are (obviously) not - # tampered with - - self.assertNotIsInstance(app.logger, - flask_logging_extras.FlaskExtraLogger) - - app = Flask('test_app') - - # Newly created apps, though, should be made with this class - self.assertIsInstance(app.logger, - flask_logging_extras.FlaskExtraLogger) - - def _create_app_with_logger(self, fmt, keywords=[]): - app = Flask('test_app') - - self.assertIsInstance(app.logger, - flask_logging_extras.FlaskExtraLogger) - - app.config['FLASK_LOGGING_EXTRAS_KEYWORDS'] = keywords - app.logger.init_app(app) - - formatter = logging.Formatter(fmt) - stream = ListStream() - - handler = TestingStreamHandler(stream=stream) - handler.setLevel(logging.DEBUG) - handler.setFormatter(formatter) - - app.logger.addHandler(handler) - app.logger.setLevel(logging.DEBUG) - - return app, stream - - def test_keywords(self): - # Register our logger class as the default - old_logger_class = flask_logging_extras.register_logger_class() - - app, log_stream = self._create_app_with_logger('%(message)s') - - app.logger.info('message') - # With the current formatter, the last log line must be a just the - # message - self.assertEqual(log_stream.lines[-1], 'message\n') - - app, log_stream = self._create_app_with_logger( - '%(message)s %(extra_keyword)s') - - # If we don’t register 'extra_keyword' in the app config, we get a + def test_keywords_app_ctx_assign_value(self): + """If we don’t register 'extra_keyword' in the app config, we get a # KeyError. We set logging.raiseExceptions to False here; the # reason is that this doesn’t mean an actual exception is raised, # but our TestingStreamHandler does that for us (which we need for # testing purposes) - old_raiseExceptions = logging.raiseExceptions - logging.raiseExceptions = False - with self.assertRaises(KeyError): - app.logger.info('message') - logging.raiseExceptions = old_raiseExceptions + """ - app, log_stream = self._create_app_with_logger( - '%(message)s [%(extra_keyword)s]', - keywords={'extra_keyword': ''}) + with self.app.app_context(): + self.logger.info('message', extra=dict(extra_keyword='test')) - app.logger.info('message', extra_keyword='test') - self.assertEqual('message [test]\n', log_stream.lines[-1]) + self.assertIn('message test', self.handler.logs) - # If we don’t provide a value for a registered extra keyword, the + def test_keywords_app_ctx_no_value(self): + """If we don’t provide a value for a registered extra keyword, the # string "" will be assigned. - app.logger.info('message') - self.assertEqual('message []\n', log_stream.lines[-1]) + """ + + with self.app.app_context(): + self.logger.info('message') + + self.assertIn('message placeholder', self.handler.logs) class LoggerBlueprintTestCase(TestCase): def setUp(self): # Register our logger class - self.original_logger_class = logging.getLoggerClass() - flask_logging_extras.register_logger_class() app = Flask('test_app') self.app = app - app.config['FLASK_LOGGING_EXTRAS_BLUEPRINT'] = ( - 'bp', '', '') - app.logger.init_app(app) + app.config['FLASK_LOGGING_EXTRAS_BLUEPRINT'] = ('bp', '', '') - fmt = '%(bp)s %(message)s' - self.stream = ListStream() + configure_loggers('bp') + self.logger = logging.getLogger('selftest') + handlers = [handler for handler in self.logger.handlers if isinstance(handler, ListHandler)] + self.handler = handlers[0] - formatter = logging.Formatter(fmt) - self.handler = TestingStreamHandler(stream=self.stream) - self.handler.setLevel(logging.DEBUG) - self.handler.setFormatter(formatter) - app.logger.addHandler(self.handler) - app.logger.setLevel(logging.DEBUG) - - bp = Blueprint('test_blueprint', 'test_bpg13') + bp = Blueprint('test_blueprint', 'test_bp') @app.route('/app') def route_1(): - current_app.logger.info('Message') + self.logger.info('Message') return '' @bp.route('/blueprint') def route_2(): - current_app.logger.info('Message') + self.logger.info('Message') return '' @@ -215,26 +136,16 @@ class LoggerBlueprintTestCase(TestCase): self.client = app.test_client() - def tearDown(self): - logging.setLoggerClass(self.original_logger_class) - - def test_autoconfig(self): - logger = logging.getLogger('test') - logger.addHandler(self.handler) - - with self.app.app_context(): - logger.warning('Hello') - - self.assertEqual(' Hello\n', self.stream.lines[-1]) - - def test_request_log(self): + def test_blueprint_log_no_blueprint(self): self.client.get('/app') - self.assertEqual(' Message\n', self.stream.lines[-1]) + self.assertIn('Message ', self.handler.logs) - page = self.client.get('/blueprint') - self.assertEqual('test_blueprint Message\n', self.stream.lines[-1]) + def test_blueprint_log_blueprint(self): + self.client.get('/blueprint') + self.assertIn('Message test_blueprint', self.handler.logs) + def test_blueprint_log_no_request(self): with self.app.app_context(): - current_app.logger.info('Message') + self.logger.info('Message') - self.assertEqual(' Message\n', self.stream.lines[-1]) + self.assertIn('Message ', self.handler.logs)