Simplifying (and documenting) logging.
This commit is contained in:
Ryan Petrello
@@ -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
|
||||
<http://docs.python.org/library/logging.config.html#configuration-dictionary-schema>`_
|
||||
function. The full documentation for the `dictConfig
|
||||
<http://docs.python.org/library/logging.config.html#configuration-dictionary-schema>`_
|
||||
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.
|
||||
|
||||
@@ -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`
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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)
|
||||
@@ -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)
|
||||
)
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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()
|
||||
@@ -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')
|
||||
|
||||
Reference in New Issue
Block a user