- add request time support in log access

- make log access format customizable in settings:
- fix logger

To setup a log format use the --access-logformat option.

        By default:

        %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"

        h: remote address
        t: date of the request
        r: status line (ex: GET / HTTP/1.1)
        s: status
        b: response length or '-'
        f: referer
        a: user agent
        T: request time in seconds
        D: request time in microseconds

        You can also pass any WSGI request header as a parameter.
        (ex '%(HTTP_HOST)s').

gunicorn/config.py

@@ -596,6 +596,36 @@ class AccessLog(Setting):
         "-" means log to stdout.
         """
 
+class AccessLogFormat(Setting):
+    name = "access_log_format"
+    section = "Logging"
+    cli = ["--access-logformat"]
+    meta = "STRING"
+    validator = validate_string
+    default = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'  
+    desc = """\
+        The Access log format .
+
+        By default:
+
+        %(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
+
+
+        h: remote address
+        t: date of the request
+        r: status line (ex: GET / HTTP/1.1)
+        s: status
+        b: response length or '-'
+        f: referer
+        a: user agent
+        T: request time in seconds
+        D: request time in microseconds
+
+        You can also pass any WSGI request header as a parameter. 
+        (ex '%(HTTP_HOST)s').
+        """
+
+
 class ErrorLog(Setting):
     name = "errorlog"
     section = "Logging"

gunicorn/glogging.py

@@ -7,6 +7,7 @@ import datetime
 import logging
 logging.Logger.manager.emittedNoHandlerWarning = 1
 import sys
+import traceback
 
 from gunicorn import util
 
@@ -77,7 +78,7 @@ class Logger(object):
             lvl = self.LOG_LEVELS.get(lvl.lower(), logging.INFO)
         self.error_log.log(lvl, msg, *args, **kwargs)
 
-    def access(self, resp, environ):
+    def access(self, resp, environ, request_time):
         """ Seee http://httpd.apache.org/docs/2.0/logs.html#combined
         for format details
         """
@@ -85,6 +86,7 @@ class Logger(object):
         if not self.cfg.accesslog:
             return
 
+
         status = resp.status.split(None, 1)[0]
         atoms = {
                 'h': environ['REMOTE_ADDR'],
@@ -96,16 +98,22 @@ class Logger(object):
                 's': status,
                 'b': str(resp.clength) or '-',
                 'f': environ.get('HTTP_REFERER', '-'),
-                'a': environ.get('HTTP_USER_AGENT', '-')
+                'a': environ.get('HTTP_USER_AGENT', '-'),
+                'T': str(request_time.seconds),
+                'D': str(request_time.microseconds)
                 }
 
+        # add WSGI request headers 
+        atoms.update(dict([(k,v) for k, v in environ.items() \
+                if k.startswith('HTTP_')]))
+
         for k, v in atoms.items():
             atoms[k] = v.replace('"', '\\"')
-
+    
         try:
-            self.access_log.info(self.access_log_format % atoms)
+            self.access_log.info(self.cfg.access_log_format % atoms)
         except:
-            self.errors(traceback.format_exc())
+            self.error(traceback.format_exc())
 
     def now(self):
         """ return date in Apache Common Log Format """

gunicorn/workers/async.py

@@ -5,6 +5,7 @@
 
 from __future__ import with_statement
 
+from datetime import datetime
 import errno
 import socket
 
@@ -53,6 +54,7 @@ class AsyncWorker(base.Worker):
     def handle_request(self, req, sock, addr):
         try:
             self.cfg.pre_request(self, req)
+            request_start = datetime.now()
             resp, environ = wsgi.create(req, sock, addr, self.address, self.cfg)
             self.nr += 1
             if self.alive and self.nr >= self.max_requests:
@@ -65,9 +67,9 @@ class AsyncWorker(base.Worker):
             try:
                 for item in respiter:
                     resp.write(item)
-
-                self.log.access(resp, environ)
                 resp.close()
+                request_time = request_start - datetime.now()
+                self.log.access(resp, environ, request_time)
             finally:
                 if hasattr(respiter, "close"):
                   respiter.close()

gunicorn/workers/sync.py

@@ -4,6 +4,7 @@
 # See the NOTICE for more information.
 #
 
+import datetime
 import errno
 import os
 import select
@@ -84,6 +85,7 @@ class SyncWorker(base.Worker):
         environ = {}
         try:
             self.cfg.pre_request(self, req)
+            request_start = datetime.now()
             resp, environ = wsgi.create(req, client, addr,
                     self.address, self.cfg)
             # Force the connection closed until someone shows
@@ -101,8 +103,9 @@ class SyncWorker(base.Worker):
                 else:
                     for item in respiter:
                         resp.write(item)
-                self.log.access(resp, environ)
                 resp.close()
+                request_time = request_start - datetime.now()
+                self.log.access(resp, environ)
             finally:
                 if hasattr(respiter, "close"):
                     respiter.close()