From 36b1e871753c989dffeaf3f9baf2595ab60c0114 Mon Sep 17 00:00:00 2001 From: Ryan Petrello Date: Fri, 23 Mar 2012 18:33:31 -0400 Subject: [PATCH] Simplifying (and documenting) logging. --- docs/source/logging.rst | 103 ++++++++++++++- docs/source/quick_start.rst | 43 +++++-- pecan/__init__.py | 17 +-- pecan/middleware/logger.py | 102 --------------- pecan/scaffolds/base/+package+/app.py_tmpl | 4 +- pecan/scaffolds/base/config.py_tmpl | 42 +++++-- pecan/tests/middleware/test_logger.py | 49 -------- pecan/tests/test_base.py | 139 --------------------- 8 files changed, 176 insertions(+), 323 deletions(-) delete mode 100644 pecan/middleware/logger.py delete mode 100644 pecan/tests/middleware/test_logger.py diff --git a/docs/source/logging.rst b/docs/source/logging.rst index 0eaa27c..71f4317 100644 --- a/docs/source/logging.rst +++ b/docs/source/logging.rst @@ -1,5 +1,106 @@ +.. |FileHandler| replace:: ``FileHandler`` +.. _FileHandler: http://docs.python.org/dev/library/logging.handlers.html#filehandler + +.. |RotatingFileHandler| replace:: ``RotatingFileHandler`` +.. _RotatingFileHandler: http://docs.python.org/dev/library/logging.handlers.html#rotatingfilehandler + +.. |SysLogHandler| replace:: ``SysLogHandler`` +.. _SysLogHandler: http://docs.python.org/dev/library/logging.handlers.html#sysloghandler + +.. |SMTPHandler| replace:: ``SMTPHandler`` +.. _SMTPHandler: http://docs.python.org/dev/library/logging.handlers.html#smtphandler + .. _logging: Logging ======= -TODO +Pecan hooks into the Python standard library's ``logging`` module by passing +logging configuration options into the +`logging.config.dictConfig +`_ +function. The full documentation for the `dictConfig +`_ +format is the best source of information for logging configuration, but to get +you started, this chapter will provide you with a few simple examples. + +Configuring Logging +------------------- +Sample logging configuration is provided with the quickstart project +introduced in :ref:`quick_start`:: + + $ pecan create myapp + +:: + + # myapp/config.py + + app = { ... } + server = { ... } + + logging = { + 'loggers': { + 'root' : {'level': 'INFO', 'handlers': ['console']}, + 'myapp': {'level': 'DEBUG', 'handlers': ['console']} + }, + 'handlers': { + 'console': { + 'level': 'DEBUG', + 'class': 'logging.StreamHandler', + 'formatter': 'simple' + } + }, + 'formatters': { + 'simple': { + 'format': ('%(asctime)s %(levelname)-5.5s [%(name)s]' + '[%(threadName)s] %(message)s') + } + } + } + +This configuration defines one handler: + +* ``console`` logs messages to ``stderr`` using the ``simple`` formatter. + +...and two loggers. + +* ``myapp`` logs messages sent at a level above or equal to ``DEBUG`` to + the ``console`` handler + +* ``root`` logs messages at a level above or equal to the ``INFO`` level to + the ``console`` handler + + +Writing Logs in Your Application +-------------------------------- +The logger named ``myapp`` is reserved for your usage in your Pecan +application. + +Once you have configured your logging, you can place logging calls in your +code. Using the logging framework is very simple. Here’s an example:: + + # myapp/myapp/controllers/root.py + from pecan import expose + + logger = logging.getLogger(__name__) + + class RootController(object): + + @expose() + def index(self): + if bad_stuff(): + logger.error('Uh-oh!') + return dict() + +Writing Logs to Files and Other Locations +----------------------------------------- +Python's ``logging`` library defines a variety of handlers that assist in +writing logs to file. A few interesting ones are: + +* |FileHandler|_ - used to log messages to a file on the filesystem +* |RotatingFileHandler|_ - similar to |FileHandler|_, but also rotates logs + periodically +* |SysLogHandler|_ - used to log messages to a UNIX syslog +* |SMTPHandler|_ - used to log messages to an email address via SMTP + +Using any of them is as simple as defining a new handler in your +application's ``logging`` block and assigning it to one of more loggers. diff --git a/docs/source/quick_start.rst b/docs/source/quick_start.rst index 07d08cc..6727340 100644 --- a/docs/source/quick_start.rst +++ b/docs/source/quick_start.rst @@ -113,31 +113,50 @@ This is how your default (generated) configuration file should look:: # Server Specific Configurations server = { - 'port' : '8080', - 'host' : '0.0.0.0' + 'port': '8080', + 'host': '0.0.0.0' } # Pecan Application Configurations app = { - 'root' : 'test_project.controllers.root.RootController', - 'modules' : ['test_project'], - 'static_root' : '%(confdir)s/public', - 'template_path' : '%(confdir)s/test_project/templates', - 'debug' : True, - 'errors' : { - '404' : '/error/404', - '__force_dict__' : True + 'root': '${package}.controllers.root.RootController', + 'modules': ['${package}'], + 'static_root': '%(confdir)s/public', + 'template_path': '%(confdir)s/${package}/templates', + 'debug': True, + 'errors': { + '404': '/error/404', + '__force_dict__': True + } + } + + logging = { + 'loggers': { + 'root' : {'level': 'INFO', 'handlers': ['console']}, + '${package}': {'level': 'DEBUG', 'handlers': ['console']} + }, + 'handlers': { + 'console': { + 'level': 'DEBUG', + 'class': 'logging.StreamHandler', + 'formatter': 'simple' + } + }, + 'formatters': { + 'simple': { + 'format': ('%(asctime)s %(levelname)-5.5s [%(name)s]' + '[%(threadName)s] %(message)s') + } } } # Custom Configurations must be in Python dictionary format:: # # foo = {'bar':'baz'} - # + # # All configurations are accessible at:: # pecan.conf - You can also add your own configuration as Python dictionaries. For more specific documentation on configuration, see the :ref:`Configuration` diff --git a/pecan/__init__.py b/pecan/__init__.py index ebcfebf..3dd9433 100644 --- a/pecan/__init__.py +++ b/pecan/__init__.py @@ -6,12 +6,12 @@ from decorators import expose from hooks import RequestViewerHook from middleware.debug import DebugMiddleware from middleware.errordocument import ErrorDocumentMiddleware -from middleware.logger import TransLogger from middleware.recursive import RecursiveMiddleware from middleware.static import StaticFileMiddleware from configuration import set_config from configuration import _runtime_conf as conf +from logging.config import dictConfig as load_logging_config __all__ = [ @@ -21,8 +21,8 @@ __all__ = [ ] -def make_app(root, static_root=None, debug=False, errorcfg={}, - wrap_app=None, logging=False, **kw): +def make_app(root, static_root=None, logging={}, debug=False, + wrap_app=None, **kw): # A shortcut for the RequestViewerHook middleware. if hasattr(conf, 'requestviewer'): @@ -44,6 +44,13 @@ def make_app(root, static_root=None, debug=False, errorcfg={}, # Included for internal redirect support app = RecursiveMiddleware(app) + # Pass logging configuration (if it exists) on to the Python logging module + if logging: + logging = logging.as_dict() + if 'version' not in logging: + logging['version'] = 1 + load_logging_config(logging) + # When in debug mode, load our exception dumping middleware if debug: app = DebugMiddleware(app) @@ -58,8 +65,4 @@ def make_app(root, static_root=None, debug=False, errorcfg={}, RuntimeWarning ) - # Support for simple Apache-style logs - if isinstance(logging, dict) or logging == True: - app = TransLogger(app, **(isinstance(logging, dict) and logging or {})) - return app diff --git a/pecan/middleware/logger.py b/pecan/middleware/logger.py deleted file mode 100644 index 946ec17..0000000 --- a/pecan/middleware/logger.py +++ /dev/null @@ -1,102 +0,0 @@ -# (c) 2005 Ian Bicking and contributors; written for Paste -# (http://pythonpaste.org) Licensed under the MIT license: -# http://www.opensource.org/licenses/mit-license.php -""" -Middleware for logging requests, using Apache combined log format -""" - -import logging -import time -import urllib - - -class TransLogger(object): - """ - This logging middleware will log all requests as they go through. - They are, by default, sent to a logger named ``'wsgi'`` at the - INFO level. - - If ``setup_console_handler`` is true, then messages for the named - logger will be sent to the console. - """ - - format = ('%(REMOTE_ADDR)s - %(REMOTE_USER)s [%(time)s] ' - '"%(REQUEST_METHOD)s %(REQUEST_URI)s %(HTTP_VERSION)s" ' - '%(status)s %(bytes)s "%(HTTP_REFERER)s" "%(HTTP_USER_AGENT)s"') - - def __init__(self, application, - logger=None, - format=None, - logging_level=logging.INFO, - logger_name='wsgi', - setup_console_handler=True, - set_logger_level=logging.DEBUG): - if format is not None: - self.format = format - self.application = application - self.logging_level = logging_level - self.logger_name = logger_name - if logger is None: - self.logger = logging.getLogger(self.logger_name) - if setup_console_handler: - console = logging.StreamHandler() - console.setLevel(logging.DEBUG) - # We need to control the exact format: - console.setFormatter(logging.Formatter('%(message)s')) - self.logger.addHandler(console) - self.logger.propagate = False - if set_logger_level is not None: - self.logger.setLevel(set_logger_level) - else: - self.logger = logger - - def __call__(self, environ, start_response): - start = time.localtime() - req_uri = urllib.quote(environ.get('SCRIPT_NAME', '') - + environ.get('PATH_INFO', '')) - if environ.get('QUERY_STRING'): - req_uri += '?' + environ['QUERY_STRING'] - method = environ['REQUEST_METHOD'] - - def replacement_start_response(status, headers, exc_info=None): - # @@: Ideally we would count the bytes going by if no - # content-length header was provided; but that does add - # some overhead, so at least for now we'll be lazy. - bytes = None - for name, value in headers: - if name.lower() == 'content-length': - bytes = value - self.write_log(environ, method, req_uri, start, status, bytes) - return start_response(status, headers) - return self.application(environ, replacement_start_response) - - def write_log(self, environ, method, req_uri, start, status, bytes): - if bytes is None: - bytes = '-' - if time.daylight: - offset = time.altzone / 60 / 60 * -100 # pragma: nocover - else: - offset = time.timezone / 60 / 60 * -100 # pragma: nocover - if offset >= 0: - offset = "+%0.4d" % (offset) # pragma: nocover - elif offset < 0: - offset = "%0.4d" % (offset) # pragma: nocover - remote_addr = '-' - if environ.get('HTTP_X_FORWARDED_FOR'): - remote_addr = environ['HTTP_X_FORWARDED_FOR'] # pragma: nocover - elif environ.get('REMOTE_ADDR'): - remote_addr = environ['REMOTE_ADDR'] # pragma: nocover - d = { - 'REMOTE_ADDR': remote_addr, - 'REMOTE_USER': environ.get('REMOTE_USER') or '-', - 'REQUEST_METHOD': method, - 'REQUEST_URI': req_uri, - 'HTTP_VERSION': environ.get('SERVER_PROTOCOL'), - 'time': time.strftime('%d/%b/%Y:%H:%M:%S ', start) + offset, - 'status': status.split(None, 1)[0], - 'bytes': bytes, - 'HTTP_REFERER': environ.get('HTTP_REFERER', '-'), - 'HTTP_USER_AGENT': environ.get('HTTP_USER_AGENT', '-'), - } - message = self.format % d - self.logger.log(self.logging_level, message) diff --git a/pecan/scaffolds/base/+package+/app.py_tmpl b/pecan/scaffolds/base/+package+/app.py_tmpl index fc1da50..ca6c5f9 100644 --- a/pecan/scaffolds/base/+package+/app.py_tmpl +++ b/pecan/scaffolds/base/+package+/app.py_tmpl @@ -9,7 +9,7 @@ def setup_app(config): config.app.root, static_root = config.app.static_root, template_path = config.app.template_path, - debug = getattr(config.app, 'debug', None), - logging = getattr(config.app, 'logging', None), + logging = getattr(config, 'logging', {}), + debug = getattr(config.app, 'debug', False), force_canonical = getattr(config.app, 'force_canonical', True) ) diff --git a/pecan/scaffolds/base/config.py_tmpl b/pecan/scaffolds/base/config.py_tmpl index 481d846..b820e59 100644 --- a/pecan/scaffolds/base/config.py_tmpl +++ b/pecan/scaffolds/base/config.py_tmpl @@ -1,25 +1,45 @@ # Server Specific Configurations server = { - 'port' : '8080', - 'host' : '0.0.0.0' + 'port': '8080', + 'host': '0.0.0.0' } # Pecan Application Configurations app = { - 'root' : '${package}.controllers.root.RootController', - 'modules' : ['${package}'], - 'static_root' : '%(confdir)s/public', - 'template_path' : '%(confdir)s/${package}/templates', - 'debug' : True, - 'errors' : { - '404' : '/error/404', - '__force_dict__' : True + 'root': '${package}.controllers.root.RootController', + 'modules': ['${package}'], + 'static_root': '%(confdir)s/public', + 'template_path': '%(confdir)s/${package}/templates', + 'debug': True, + 'errors': { + '404': '/error/404', + '__force_dict__': True + } +} + +logging = { + 'loggers': { + 'root' : {'level': 'INFO', 'handlers': ['console']}, + '${package}': {'level': 'DEBUG', 'handlers': ['console']} + }, + 'handlers': { + 'console': { + 'level': 'DEBUG', + 'class': 'logging.StreamHandler', + 'formatter': 'simple' + } + }, + 'formatters': { + 'simple': { + 'format': ('%(asctime)s %(levelname)-5.5s [%(name)s]' + '[%(threadName)s] %(message)s') + } } } # Custom Configurations must be in Python dictionary format:: # # foo = {'bar':'baz'} -# +# # All configurations are accessible at:: # pecan.conf diff --git a/pecan/tests/middleware/test_logger.py b/pecan/tests/middleware/test_logger.py deleted file mode 100644 index 530440e..0000000 --- a/pecan/tests/middleware/test_logger.py +++ /dev/null @@ -1,49 +0,0 @@ -from cStringIO import StringIO -from unittest import TestCase -from webtest import TestApp - -from pecan.middleware.logger import TransLogger - - -def simple_app(environ, start_response): - start_response("200 OK", [('Content-type', 'text/plain')]) - return ['Hello, World'] - - -class FakeLogger(object): - - def __init__(self): - self.b = StringIO() - - def log(self, level, msg): - self.b.write(msg) - - def getvalue(self): - return self.b.getvalue() - - -class TestDebugMiddleware(TestCase): - - def setUp(self): - self.logger = FakeLogger() - - def test_simple_log(self): - app = TestApp(TransLogger(simple_app, logger=self.logger)) - r = app.get('/') - assert r.status_int == 200 - assert r.body == 'Hello, World' - assert '"GET / HTTP/1.0" 200 - "-" "-"' in self.logger.getvalue() - - def test_log_format(self): - app = TestApp(TransLogger(simple_app, logger=self.logger, format='X')) - r = app.get('/') - assert r.status_int == 200 - assert r.body == 'Hello, World' - assert self.logger.getvalue() == 'X' - - def test_log_query_string(self): - app = TestApp(TransLogger(simple_app, logger=self.logger)) - r = app.get('/?foo=1') - assert r.status_int == 200 - assert r.body == 'Hello, World' - assert '"GET /?foo=1 HTTP/1.0" 200 - "-" "-"' in self.logger.getvalue() diff --git a/pecan/tests/test_base.py b/pecan/tests/test_base.py index d02f57f..452a084 100644 --- a/pecan/tests/test_base.py +++ b/pecan/tests/test_base.py @@ -1,6 +1,5 @@ import sys import warnings -from pecan.middleware.logger import TransLogger from webtest import TestApp if sys.version_info < (2, 7): @@ -1074,144 +1073,6 @@ class TestNonCanonical(unittest.TestCase): assert len(wrapped_apps) == 1 -class TestLogging(unittest.TestCase): - """ - Mocks logging calls so we can make sure they get called. We could use - Fudge for this, but it would add an additional dependency to Pecan for - a single set of tests. - """ - - def setUp(self): - self._write_log = TransLogger.write_log - - def tearDown(self): - TransLogger.write_log = self._write_log - - def test_default(self): - - class RootController(object): - @expose() - def index(self): - return '/' - - # monkeypatch the logger - writes = [] - - def _write_log(self, *args, **kwargs): - writes.append(1) # pragma: nocover - TransLogger.write_log = _write_log - - # check the request - app = TestApp(make_app(RootController(), debug=True)) - r = app.get('/') - assert r.status_int == 200 - assert writes == [] - - def test_default_route(self): - - class RootController(object): - @expose() - def index(self): - return '/' - - # monkeypatch the logger - writes = [] - - def _write_log(self, *args, **kwargs): - writes.append(1) # pragma: nocover - TransLogger.write_log = _write_log - - # check the request - app = TestApp(make_app(RootController(), debug=True)) - r = app.get('/') - assert r.status_int == 200 - assert len(writes) == 0 - - def test_no_logging(self): - - class RootController(object): - @expose() - def index(self): - return '/' - - # monkeypatch the logger - writes = [] - - def _write_log(self, *args, **kwargs): - writes.append(1) # pragma: nocover - - TransLogger.write_log = _write_log - - # check the request - app = TestApp(make_app(RootController(), debug=True, logging=False)) - r = app.get('/') - assert r.status_int == 200 - assert len(writes) == 0 - - def test_basic_logging(self): - - class RootController(object): - @expose() - def index(self): - return '/' - - # monkeypatch the logger - writes = [] - - def _write_log(self, *args, **kwargs): - writes.append(1) - - TransLogger.write_log = _write_log - - # check the request - app = TestApp(make_app(RootController(), debug=True, logging=True)) - r = app.get('/') - assert r.status_int == 200 - assert len(writes) == 1 - - def test_empty_config(self): - - class RootController(object): - @expose() - def index(self): - return '/' - - # monkeypatch the logger - writes = [] - - def _write_log(self, *args, **kwargs): - writes.append(1) - - TransLogger.write_log = _write_log - - # check the request - app = TestApp(make_app(RootController(), debug=True, logging={})) - r = app.get('/') - assert r.status_int == 200 - assert len(writes) == 1 - - def test_custom_config(self): - - class RootController(object): - @expose() - def index(self): - return '/' - - # create a custom logger - writes = [] - - class FakeLogger(object): - def log(self, *args, **kwargs): - writes.append(1) - - # check the request - app = TestApp(make_app(RootController(), debug=True, - logging={'logger': FakeLogger()})) - r = app.get('/') - assert r.status_int == 200 - assert len(writes) == 1 - - class TestEngines(unittest.TestCase): template_path = os.path.join(os.path.dirname(__file__), 'templates')