close #304 .

Intoduce a change in log access format:

- request headers are now added to the log format using the
  {HeaderName}i variable
- response headers are now handled using the {HeaderName}o variables
- headers name are insensitive
- non existent keys in the log access format are replaced by '-'

examples/test.py

@@ -8,16 +8,18 @@
 from wsgiref.validate import validator
 import sys
 
+from gunicorn import __version__
 #@validator
 def app(environ, start_response):
     """Simplest possible application object"""
     data = 'Hello, World!\n'
     status = '200 OK'
     print("print to stdout in test app")
-    sys.stderr.write("stderr, print to stderr in test app")
+    sys.stderr.write("stderr, print to stderr in test app\n")
     response_headers = [
         ('Content-type','text/plain'),
-        ('Content-Length', str(len(data)))
+        ('Content-Length', str(len(data))),
+        ('X-Gunicorn-Version', __version__)
     ]
     start_response(status, response_headers)
     return iter([data])

gunicorn/config.py

@@ -678,7 +678,7 @@ class AccessLogFormat(Setting):
     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"'
+    default = '"%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
     desc = """\
         The Access log format .
 
@@ -699,9 +699,8 @@ class AccessLogFormat(Setting):
         T: request time in seconds
         D: request time in microseconds,
         p: process ID
-
-        You can also pass any WSGI request header as a parameter.
-        (ex '%(HTTP_HOST)s').
+        {Header}i: request header
+        {Header}o: response header
         """
 
 class ErrorLog(Setting):

gunicorn/glogging.py

@@ -54,6 +54,26 @@ class LazyWriter(object):
     def flush(self):
         self.open().flush()
 
+class SafeAtoms(dict):
+
+    def __init__(self, atoms):
+        dict.__init__(self)
+        for key, value in atoms.items():
+            self[key] = value.replace('"', '\\"')
+
+    def __getitem__(self, k):
+        if k.startswith("{"):
+            kl = k.lower()
+            if kl in self:
+                return super(SafeAtoms, self).__getitem__(kl)
+            else:
+                return "-"
+        if k in self:
+            return super(SafeAtoms, self).__getitem__(k)
+        else:
+            return '-'
+
+
 class Logger(object):
 
     LOG_LEVELS = {
@@ -129,7 +149,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, request_time):
+    def access(self, resp, req, environ, request_time):
         """ Seee http://httpd.apache.org/docs/2.0/logs.html#combined
         for format details
         """
@@ -154,15 +174,19 @@ class Logger(object):
                 'p': "<%s>" % os.getpid()
                 }
 
-        # add WSGI request headers
-        atoms.update(dict([(k,v) for k, v in environ.items() \
-                if k.startswith('HTTP_')]))
+        # add request headers
+        atoms.update(dict([("{%s}i" % k.lower(),v) for k, v in req.headers]))
 
-        for k, v in atoms.items():
-            atoms[k] = v.replace('"', '\\"')
+        # add response headers
+        atoms.update(dict([("{%s}o" % k.lower(),v) for k, v in resp.headers]))
+
+        # wrap atoms:
+        # - make sure atoms will be test case insensitively
+        # - if atom doesn't exist replace it by '-'
+        safe_atoms = SafeAtoms(atoms)
 
         try:
-            self.access_log.info(self.cfg.access_log_format % atoms)
+            self.access_log.info(self.cfg.access_log_format % safe_atoms)
         except:
             self.error(traceback.format_exc())
 

gunicorn/workers/async.py

@@ -69,7 +69,7 @@ class AsyncWorker(base.Worker):
                     resp.write(item)
                 resp.close()
                 request_time = datetime.now() - request_start
-                self.log.access(resp, environ, request_time)
+                self.log.access(resp, req, environ, request_time)
             finally:
                 if hasattr(respiter, "close"):
                   respiter.close()

gunicorn/workers/sync.py

@@ -105,7 +105,7 @@ class SyncWorker(base.Worker):
                         resp.write(item)
                 resp.close()
                 request_time = datetime.now() - request_start
-                self.log.access(resp, environ, request_time)
+                self.log.access(resp, req, environ, request_time)
             finally:
                 if hasattr(respiter, "close"):
                     respiter.close()