Generate apache-style common access logs

Taking advantage of this middleware either requires enabling
verbose/debug or utilizing an external logging.conf which configures an
'access' logger.

Example output:

  127.0.0.1 - - [2013-01-29T17:15:02.752214] "GET http://localhost:5000/v3/projects HTTP/1.0" 200 16

This patch also revises etc/logging.conf.sample with some more practical
defaults (e.g. supporting externally-managed log rotations) in addition
to illustrating how to generate an 'access.log' file.

DocImpact

Change-Id: I2a6048fa5fbf8661a6859d9e3a259d4cfa5fc589

.gitignore

@@ -23,6 +23,7 @@ AUTHORS
 build/
 dist/
 etc/keystone.conf
+etc/logging.conf
 tests/test.db.pristine
 .project
 .pydevproject

etc/keystone.conf.sample

@@ -200,6 +200,9 @@ paste.filter_factory = keystone.contrib.stats:StatsMiddleware.factory
 [filter:stats_reporting]
 paste.filter_factory = keystone.contrib.stats:StatsExtension.factory
 
+[filter:access_log]
+paste.filter_factory = keystone.contrib.access:AccessLogMiddleware.factory
+
 [app:public_service]
 paste.app_factory = keystone.service:public_app_factory
 
@@ -210,13 +213,13 @@ paste.app_factory = keystone.service:v3_app_factory
 paste.app_factory = keystone.service:admin_app_factory
 
 [pipeline:public_api]
-pipeline = sizelimit stats_monitoring url_normalize token_auth admin_token_auth xml_body json_body debug ec2_extension user_crud_extension public_service
+pipeline = access_log sizelimit stats_monitoring url_normalize token_auth admin_token_auth xml_body json_body debug ec2_extension user_crud_extension public_service
 
 [pipeline:admin_api]
-pipeline = sizelimit stats_monitoring url_normalize token_auth admin_token_auth xml_body json_body debug stats_reporting ec2_extension s3_extension crud_extension admin_service
+pipeline = access_log sizelimit stats_monitoring url_normalize token_auth admin_token_auth xml_body json_body debug stats_reporting ec2_extension s3_extension crud_extension admin_service
 
 [pipeline:api_v3]
-pipeline = sizelimit stats_monitoring url_normalize token_auth admin_token_auth xml_body json_body debug stats_reporting ec2_extension s3_extension service_v3
+pipeline = access_log sizelimit stats_monitoring url_normalize token_auth admin_token_auth xml_body json_body debug stats_reporting ec2_extension s3_extension service_v3
 
 [app:public_version_service]
 paste.app_factory = keystone.service:public_version_app_factory
@@ -225,10 +228,10 @@ paste.app_factory = keystone.service:public_version_app_factory
 paste.app_factory = keystone.service:admin_version_app_factory
 
 [pipeline:public_version_api]
-pipeline = sizelimit stats_monitoring url_normalize xml_body public_version_service
+pipeline = access_log sizelimit stats_monitoring url_normalize xml_body public_version_service
 
 [pipeline:admin_version_api]
-pipeline = sizelimit stats_monitoring url_normalize xml_body admin_version_service
+pipeline = access_log sizelimit stats_monitoring url_normalize xml_body admin_version_service
 
 [composite:main]
 use = egg:Paste#urlmap

etc/logging.conf.sample

@@ -1,27 +1,48 @@
 [loggers]
-keys=root
-
-[formatters]
-keys=normal,normal_with_name,debug
+keys=root,access
 
 [handlers]
-keys=production,file,devel
+keys=production,file,access_file,devel
+
+[formatters]
+keys=minimal,normal,debug
+
+
+###########
+# Loggers #
+###########
 
 [logger_root]
 level=WARNING
 handlers=file
 
+[logger_access]
+level=INFO
+qualname=access
+handlers=access_file
+
+
+################
+# Log Handlers #
+################
+
 [handler_production]
 class=handlers.SysLogHandler
 level=ERROR
-formatter=normal_with_name
+formatter=normal
 args=(('localhost', handlers.SYSLOG_UDP_PORT), handlers.SysLogHandler.LOG_USER)
 
 [handler_file]
-class=FileHandler
-level=DEBUG
-formatter=normal_with_name
-args=('keystone.log', 'a')
+class=handlers.WatchedFileHandler
+level=WARNING
+formatter=normal
+args=('error.log',)
+
+[handler_access_file]
+class=handlers.WatchedFileHandler
+level=INFO
+formatter=minimal
+args=('access.log',)
 
 [handler_devel]
 class=StreamHandler
@@ -29,10 +50,15 @@ level=NOTSET
 formatter=debug
 args=(sys.stdout,)
 
-[formatter_normal]
-format=%(asctime)s %(levelname)s %(message)s
 
-[formatter_normal_with_name]
+##################
+# Log Formatters #
+##################
+
+[formatter_minimal]
+format=%(message)s
+
+[formatter_normal]
 format=(%(name)s): %(asctime)s %(levelname)s %(message)s
 
 [formatter_debug]

keystone/contrib/access/__init__.py

@@ -0,0 +1,17 @@
+# vim: tabstop=4 shiftwidth=4 softtabstop=4
+
+# Copyright 2013 OpenStack LLC
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+from keystone.contrib.access.core import *

keystone/contrib/access/core.py

@@ -0,0 +1,61 @@
+# vim: tabstop=4 shiftwidth=4 softtabstop=4
+
+# Copyright 2013 OpenStack LLC
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+import webob
+import webob.dec
+
+from keystone.common import logging
+from keystone.common import wsgi
+from keystone import config
+from keystone.openstack.common import timeutils
+
+
+CONF = config.CONF
+LOG = logging.getLogger('access')
+APACHE_TIME_FORMAT = '%d/%b/%Y:%H:%M:%S'
+APACHE_LOG_FORMAT = (
+    '%(remote_addr)s - %(remote_user)s [%(datetime)s] "%(method)s %(url)s '
+    '%(http_version)s" %(status)s %(content_length)s')
+
+
+class AccessLogMiddleware(wsgi.Middleware):
+    """Writes an access log to INFO."""
+
+    @webob.dec.wsgify
+    def __call__(self, request):
+        data = {
+            'remote_addr': request.remote_addr,
+            'remote_user': request.remote_user or '-',
+            'method': request.method,
+            'url': request.url,
+            'http_version': request.http_version,
+            'status': 500,
+            'content_length': '-'}
+
+        try:
+            response = request.get_response(self.application)
+            data['status'] = response.status_int
+            data['content_length'] = len(response.body) or '-'
+        finally:
+            # must be calculated *after* the application has been called
+            now = timeutils.utcnow()
+
+            # timeutils may not return UTC, so we can't hardcode +0000
+            data['datetime'] = '%s %s' % (now.strftime(APACHE_TIME_FORMAT),
+                                          now.strftime('%z') or '+0000')
+
+            LOG.info(APACHE_LOG_FORMAT % data)
+        return response

tests/test_keystoneclient.py

@@ -995,8 +995,8 @@ class KcMasterTestCase(CompatTestCase, KeystoneClientTests):
         rv = self.public_server.application(
             req.environ,
             responseobject.start_fake_response)
-        responce_json = jsonutils.loads(rv.next())
-        new_token_id = responce_json['access']['token']['id']
+        response_json = jsonutils.loads(rv.pop())
+        new_token_id = response_json['access']['token']['id']
 
         self.assertRaises(client_exceptions.Unauthorized, client.tenants.list)
         client.auth_token = new_token_id