Wednesday, July 9, 2014

Customizing the Twisted Web Request Log


custom-logging

Python's Twisted library can log every http request it receives when it's being used as a web server.  This is accomplished by sending a custom logger to the site object when it's instantiated. 

Let's jump right into to a full working example with a custom logger that will print the duration of each request.
"""
Custom per-request logging in Twisted.
"""
__author__ = 'Ben DeMott'

import sys
import time

from twisted.web.http import _escape
from twisted.web import server, resource
from twisted.internet import reactor
from twisted.python import log
log.startLogging(sys.stdout)

class RootResource(resource.Resource):
    isLeaf = True
    def render_GET(self, request):
        """
        :param request: A twisted.web.server.Request instance
        """
        request.started = time.time()
        request.setHeader('Content-Type', 'text/plain; charset=utf-8')
        return u"""
            You requested {0}, k thx bye! {1} {1} {1} {1}
        """.format(request.uri,  unichr(128571)).encode('utf-8')
        
def timedLogFormatter(timestamp, request):
    """
    A custom request formatter.  This is whats used when each request line is formatted.
    
    :param timestamp: 
    :param request: A twisted.web.server.Request instance
    """
    referrer = _escape(request.getHeader(b"referer") or b"-")
    agent = _escape(request.getHeader(b"user-agent") or b"-")
    duration = round(time.time() - request.started, 4)
    line = (
        u'"%(ip)s" %(duration)ss "%(method)s %(uri)s %(protocol)s" '
        u'%(code)d %(length)s "%(agent)s"' % dict(
            ip=_escape(request.getClientIP() or b"-"),
            duration=duration,
            method=_escape(request.method),
            uri=_escape(request.uri),
            protocol=_escape(request.clientproto),
            code=request.code,
            length=request.sentLength or u"-",
            agent=agent
            ))
    return line
    
def main(argv=None):
    site = server.Site(RootResource(), logFormatter=timedLogFormatter)
    site.logRequest = True
    reactor.listenTCP(8080, site)
    reactor.run()
    
if __name__ == '__main__':
    sys.exit(main(sys.argv))

The important parts from above...

1.) You must enable logging:
  • from twisted.python import log
  • log.startLogging(sys.stdout)
2.) You must override the default logger: 
  • site = server.Site(RootResource(), logFormatter=timedLogFormatter)
3.) You must enable per-request logging on the site object
  • site.logRequest = True

If you save the contents of the script above to a file called "twistedlog.py" and run it using "python twistedlog.py", then direct your browser to http://localhost:8080 you'll see log entries appearing in your console.