Move proxy server logging to middleware.

Change-Id: I771c87207d4e1821e32c3424b341d182cc7ea7c0

doc/source/development_saio.rst

@@ -287,7 +287,7 @@ Sample configuration files are provided with all defaults in line-by-line commen
         log_facility = LOG_LOCAL1
 
         [pipeline:main]
-        pipeline = healthcheck cache tempauth proxy-server
+        pipeline = healthcheck cache tempauth proxy-logging proxy-server
 
         [app:proxy-server]
         use = egg:swift#proxy
@@ -307,6 +307,9 @@ Sample configuration files are provided with all defaults in line-by-line commen
         [filter:cache]
         use = egg:swift#memcache
 
+        [filter:proxy-logging]
+        use = egg:swift#proxy_logging
+
   #. Create `/etc/swift/swift.conf`:
 
      .. code-block:: none

doc/source/misc.rst

@@ -174,3 +174,10 @@ CNAME Lookup
 .. automodule:: swift.common.middleware.cname_lookup
     :members:
     :show-inheritance:
+
+Proxy Logging
+=============
+
+.. automodule:: swift.common.middleware.proxy_logging
+    :members:
+    :show-inheritance:

etc/proxy-server.conf-sample

@@ -21,7 +21,7 @@
 # log_statsd_metric_prefix =
 
 [pipeline:main]
-pipeline = catch_errors healthcheck cache ratelimit tempauth proxy-server
+pipeline = catch_errors healthcheck cache ratelimit tempauth proxy-logging proxy-server
 
 [app:proxy-server]
 use = egg:swift#proxy
@@ -247,3 +247,6 @@ use = egg:swift#formpost
 use = egg:swift#name_check
 # forbidden_chars = '"`<>
 # maximum_length = 255
+
+[filter:proxy-logging]
+use = egg:swift#proxy_logging

setup.py

@@ -93,6 +93,8 @@ setup(
             'tempurl=swift.common.middleware.tempurl:filter_factory',
             'formpost=swift.common.middleware.formpost:filter_factory',
             'name_check=swift.common.middleware.name_check:filter_factory',
+            'proxy_logging=swift.common.middleware.proxy_logging:'
+                'filter_factory',
             ],
         },
     )

swift/common/middleware/proxy_logging.py

@@ -0,0 +1,189 @@
+# Copyright (c) 2010-2011 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.
+
+"""
+Logging middleware for the Swift proxy.
+
+This serves as both the default logging implementation and an example of how
+to plug in your own logging format/method.
+
+The logging format implemented below is as follows:
+
+client_ip remote_addr datetime request_method request_path protocol
+    status_int referer user_agent auth_token bytes_recvd bytes_sent
+    client_etag transaction_id headers request_time source
+
+These values are space-separated, and each is url-encoded, so that they can
+be separated with a simple .split()
+
+* remote_addr is the contents of the REMOTE_ADDR environment variable, while
+  client_ip is swift's best guess at the end-user IP, extracted variously
+  from the X-Forwarded-For header, X-Cluster-Ip header, or the REMOTE_ADDR
+  environment variable.
+
+* Values that are missing (e.g. due to a header not being present) or zero
+  are generally represented by a single hyphen ('-').
+"""
+
+import time
+from urllib import quote, unquote
+
+from webob import Request
+
+from swift.common.utils import get_logger, get_remote_client, TRUE_VALUES
+
+
+class InputProxy(object):
+    """
+    File-like object that counts bytes read.
+    To be swapped in for wsgi.input for accounting purposes.
+    """
+    def __init__(self, wsgi_input):
+        """
+        :param wsgi_input: file-like object to wrap the functionality of
+        """
+        self.wsgi_input = wsgi_input
+        self.bytes_received = 0
+        self.client_disconnect = False
+
+    def read(self, *args, **kwargs):
+        """
+        Pass read request to the underlying file-like object and
+        add bytes read to total.
+        """
+        try:
+            chunk = self.wsgi_input.read(*args, **kwargs)
+        except Exception:
+            self.client_disconnect = True
+            raise
+        self.bytes_received += len(chunk)
+        return chunk
+
+    def readline(self, *args, **kwargs):
+        """
+        Pass readline request to the underlying file-like object and
+        add bytes read to total.
+        """
+        try:
+            line = self.wsgi_input.readline(*args, **kwargs)
+        except Exception:
+            self.client_disconnect = True
+            raise
+        self.bytes_received += len(line)
+        return line
+
+
+class ProxyLoggingMiddleware(object):
+    """
+    Middleware that logs Swift proxy requests in the swift log format.
+    """
+
+    def __init__(self, app, conf):
+        self.app = app
+        self.log_hdrs = conf.get('log_headers', 'no').lower() in TRUE_VALUES
+        access_log_conf = {}
+        for key in ('log_facility', 'log_name', 'log_level'):
+            value = conf.get('access_' + key, conf.get(key, None))
+            if value:
+                access_log_conf[key] = value
+        self.access_logger = get_logger(access_log_conf,
+                        log_route='proxy-access')
+
+    def log_request(self, env, status_int, bytes_received, bytes_sent,
+                    request_time, client_disconnect):
+        """
+        Log a request.
+
+        :param env: WSGI environment
+        :param status_int: integer code for the response status
+        :param bytes_received: bytes successfully read from the request body
+        :param bytes_sent: bytes yielded to the WSGI server
+        :param request_time: time taken to satisfy the request, in seconds
+        """
+        req = Request(env)
+        if client_disconnect:  # log disconnected clients as '499' status code
+            status_int = 499
+        the_request = quote(unquote(req.path))
+        if req.query_string:
+            the_request = the_request + '?' + req.query_string
+        logged_headers = None
+        if self.log_hdrs:
+            logged_headers = '\n'.join('%s: %s' % (k, v)
+                for k, v in req.headers.items())
+        self.access_logger.info(' '.join(quote(str(x) if x else '-')
+            for x in (
+                get_remote_client(req),
+                req.remote_addr,
+                time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()),
+                req.method,
+                the_request,
+                req.environ.get('SERVER_PROTOCOL'),
+                status_int,
+                req.referer,
+                req.user_agent,
+                req.headers.get('x-auth-token'),
+                bytes_received,
+                bytes_sent,
+                req.headers.get('etag', None),
+                req.environ.get('swift.trans_id'),
+                logged_headers,
+                '%.4f' % request_time,
+                req.environ.get('swift.source'),
+            )))
+        self.access_logger.txn_id = None
+
+    def __call__(self, env, start_response):
+        status_int = [500]
+        input_proxy = InputProxy(env['wsgi.input'])
+        env['wsgi.input'] = input_proxy
+        start_time = time.time()
+
+        def my_start_response(status, headers, exc_info=None):
+            status_int[0] = int(status.split()[0])
+            return start_response(status, headers, exc_info)
+
+        def iter_response(iterator):
+            bytes_sent = 0
+            client_disconnect = False
+            try:
+                for chunk in iterator:
+                    bytes_sent += len(chunk)
+                    yield chunk
+            except GeneratorExit:  # generator was closed before we finished
+                client_disconnect = True
+                raise
+            finally:
+                self.log_request(env, status_int[0],
+                        input_proxy.bytes_received, bytes_sent,
+                        time.time() - start_time,
+                        client_disconnect or input_proxy.client_disconnect)
+
+        try:
+            iterator = self.app(env, my_start_response)
+        except Exception:
+            self.log_request(env, 500, input_proxy.bytes_received, 0,
+                    time.time() - start_time, input_proxy.client_disconnect)
+            raise
+        else:
+            return iter_response(iterator)
+
+
+def filter_factory(global_conf, **local_conf):
+    conf = global_conf.copy()
+    conf.update(local_conf)
+
+    def proxy_logger(app):
+        return ProxyLoggingMiddleware(app, conf)
+    return proxy_logger

swift/proxy/server.py

@@ -65,8 +65,8 @@ from swift.common.http import is_informational, is_success, is_redirection, \
     is_client_error, is_server_error, HTTP_CONTINUE, HTTP_OK, HTTP_CREATED, \
     HTTP_ACCEPTED, HTTP_PARTIAL_CONTENT, HTTP_MULTIPLE_CHOICES, \
     HTTP_BAD_REQUEST, HTTP_NOT_FOUND, HTTP_REQUESTED_RANGE_NOT_SATISFIABLE, \
-    HTTP_CLIENT_CLOSED_REQUEST, HTTP_INTERNAL_SERVER_ERROR, \
+    HTTP_INTERNAL_SERVER_ERROR, HTTP_SERVICE_UNAVAILABLE, \
-    HTTP_SERVICE_UNAVAILABLE, HTTP_INSUFFICIENT_STORAGE, HTTPClientDisconnect
+    HTTP_INSUFFICIENT_STORAGE, HTTPClientDisconnect
 
 
 def update_headers(response, headers):
@@ -129,11 +129,9 @@ class SegmentedIterable(object):
     """
     Iterable that returns the object contents for a segmented object in Swift.
 
-    If set, the response's `bytes_transferred` value will be updated (used to
+    If there's a failure that cuts the transfer short, the response's
-    log the size of the request). Also, if there's a failure that cuts the
+    `status_int` will be updated (again, just for logging since the original
-    transfer short, the response's `status_int` will be updated (again, just
+    status would have already been sent to the client).
-    for logging since the original status would have already been sent to the
-    client).
 
     :param controller: The ObjectController instance to work with.
     :param container: The container the object segments are within.
@@ -224,8 +222,6 @@ class SegmentedIterable(object):
                         except StopIteration:
                             self._load_next_segment()
                 self.position += len(chunk)
-                self.response.bytes_transferred = getattr(self.response,
-                    'bytes_transferred', 0) + len(chunk)
                 yield chunk
         except StopIteration:
             raise
@@ -268,9 +264,6 @@ class SegmentedIterable(object):
                     length -= len(chunk)
                     if length < 0:
                         # Chop off the extra:
-                        self.response.bytes_transferred = \
-                           getattr(self.response, 'bytes_transferred', 0) \
-                           + length
                         yield chunk[:length]
                         break
                 yield chunk
@@ -714,12 +707,8 @@ class Controller(object):
     def _make_app_iter(self, node, source, response):
         """
         Returns an iterator over the contents of the source (via its read
-        func). The response.bytes_transferred will be incremented as the
+        func).  There is also quite a bit of cleanup to ensure garbage
-        iterator is read so as to measure how much the client is actually sent.
+        collection works and the underlying socket of the source is closed.
-        response.client_disconnect will be set to true if the GeneratorExit
-        occurs before all the source is read. There is also quite a bit of
-        cleanup to ensure garbage collection works and the underlying socket of
-        the source is closed.
 
         :param response: The webob.Response object this iterator should be
                          assigned to via response.app_iter.
@@ -740,11 +729,9 @@ class Controller(object):
                     if not chunk:
                         break
                     yield chunk
-                    response.bytes_transferred += len(chunk)
             except Empty:
                 raise ChunkReadTimeout()
             except (GeneratorExit, Timeout):
-                response.client_disconnect = True
                 self.app.logger.warn(_('Client disconnected on read'))
             except Exception:
                 self.app.logger.exception(_('Trying to send to client'))
@@ -831,7 +818,6 @@ class Controller(object):
             if req.method == 'GET' and \
                source.status in (HTTP_OK, HTTP_PARTIAL_CONTENT):
                 res = Response(request=req, conditional_response=True)
-                res.bytes_transferred = 0
                 res.app_iter = self._make_app_iter(node, source, res)
                 # See NOTE: swift_conn at top of file about this.
                 res.swift_conn = source.swift_conn
@@ -1340,13 +1326,13 @@ class ObjectController(Controller):
             self.app.logger.increment('errors')
             return HTTPServiceUnavailable(request=req)
         chunked = req.headers.get('transfer-encoding')
+        bytes_transferred = 0
         try:
             with ContextPool(len(nodes)) as pool:
                 for conn in conns:
                     conn.failed = False
                     conn.queue = Queue(self.app.put_queue_depth)
                     pool.spawn(self._send_file, conn, req.path)
-                req.bytes_transferred = 0
                 while True:
                     with ChunkReadTimeout(self.app.client_timeout):
                         try:
@@ -1355,8 +1341,8 @@ class ObjectController(Controller):
                             if chunked:
                                 [conn.queue.put('0\r\n\r\n') for conn in conns]
                             break
-                    req.bytes_transferred += len(chunk)
+                    bytes_transferred += len(chunk)
-                    if req.bytes_transferred > MAX_FILE_SIZE:
+                    if bytes_transferred > MAX_FILE_SIZE:
                         self.app.logger.increment('errors')
                         return HTTPRequestEntityTooLarge(request=req)
                     for conn in list(conns):
@@ -1381,14 +1367,13 @@ class ObjectController(Controller):
             self.app.logger.increment('client_timeouts')
             return HTTPRequestTimeout(request=req)
         except (Exception, Timeout):
-            req.client_disconnect = True
             self.app.logger.exception(
                 _('ERROR Exception causing client disconnect'))
             self.app.logger.increment('client_disconnects')
             self.app.logger.timing_since(
                 '%s.timing' % (stats_type,), start_time)
             return HTTPClientDisconnect(request=req)
-        if req.content_length and req.bytes_transferred < req.content_length:
+        if req.content_length and bytes_transferred < req.content_length:
             req.client_disconnect = True
             self.app.logger.warn(
                 _('Client disconnected without sending enough data'))
@@ -1438,8 +1423,6 @@ class ObjectController(Controller):
             for k, v in req.headers.items():
                 if k.lower().startswith('x-object-meta-'):
                     resp.headers[k] = v
-            # reset the bytes, since the user didn't actually send anything
-            req.bytes_transferred = 0
         resp.last_modified = float(req.headers['X-Timestamp'])
         self.app.logger.timing_since('%s.timing' % (stats_type,), start_time)
         return resp
@@ -1985,18 +1968,7 @@ class BaseApplication(object):
             if self.memcache is None:
                 self.memcache = cache_from_env(env)
             req = self.update_request(Request(env))
-            if 'eventlet.posthooks' in env:
+            return self.handle_request(req)(env, start_response)
-                env['eventlet.posthooks'].append(
-                    (self.posthooklogger, (req,), {}))
-                return self.handle_request(req)(env, start_response)
-            else:
-                # Lack of posthook support means that we have to log on the
-                # start of the response, rather than after all the data has
-                # been sent. This prevents logging client disconnects
-                # differently than full transmissions.
-                response = self.handle_request(req)(env, start_response)
-                self.posthooklogger(env, req)
-                return response
         except (Exception, Timeout):
             print "EXCEPTION IN __call__: %s: %s" % \
                   (traceback.format_exc(), env)
@@ -2004,12 +1976,7 @@ class BaseApplication(object):
                     [('Content-Type', 'text/plain')])
             return ['Internal server error.\n']
 
-    def posthooklogger(self, env, req):
-        pass
-
     def update_request(self, req):
-        req.bytes_transferred = '-'
-        req.client_disconnect = False
         if 'x-storage-token' in req.headers and \
                 'x-auth-token' not in req.headers:
             req.headers['x-auth-token'] = req.headers['x-storage-token']
@@ -2098,45 +2065,6 @@ class Application(BaseApplication):
         req.response = super(Application, self).handle_request(req)
         return req.response
 
-    def posthooklogger(self, env, req):
-        response = getattr(req, 'response', None)
-        if not response:
-            return
-        trans_time = '%.4f' % (time.time() - req.start_time)
-        the_request = quote(unquote(req.path))
-        if req.query_string:
-            the_request = the_request + '?' + req.query_string
-        client = get_remote_client(req)
-        logged_headers = None
-        if self.log_headers:
-            logged_headers = '\n'.join('%s: %s' % (k, v)
-                for k, v in req.headers.items())
-        status_int = response.status_int
-        if getattr(req, 'client_disconnect', False) or \
-                getattr(response, 'client_disconnect', False):
-            status_int = HTTP_CLIENT_CLOSED_REQUEST
-        self.access_logger.info(' '.join(quote(str(x)) for x in (
-                client or '-',
-                req.remote_addr or '-',
-                time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()),
-                req.method,
-                the_request,
-                req.environ['SERVER_PROTOCOL'],
-                status_int,
-                req.referer or '-',
-                req.user_agent or '-',
-                req.headers.get('x-auth-token', '-'),
-                getattr(req, 'bytes_transferred', 0) or '-',
-                getattr(response, 'bytes_transferred', 0) or '-',
-                req.headers.get('etag', '-'),
-                req.environ.get('swift.trans_id', '-'),
-                logged_headers or '-',
-                trans_time,
-                req.environ.get('swift.source', '-'),
-            )))
-        # done with this transaction
-        self.access_logger.txn_id = None
-
 
 def app_factory(global_conf, **local_conf):
     """paste.deploy app factory for creating WSGI proxy apps."""

test/unit/common/middleware/test_proxy_logging.py

@@ -0,0 +1,228 @@
+# Copyright (c) 2010-2011 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 unittest
+from urllib import quote, unquote
+import cStringIO as StringIO
+
+from webob import Request
+
+from swift.common.middleware import proxy_logging
+
+
+class FakeApp(object):
+    def __init__(self, body=['FAKE APP']):
+        self.body = body
+
+    def __call__(self, env, start_response):
+        start_response('200 OK', [('Content-Type', 'text/plain')])
+        while env['wsgi.input'].read(5):
+            pass
+        return self.body
+
+
+class FileLikeExceptor(object):
+    def __init__(self):
+        pass
+
+    def read(self, len):
+        raise IOError('of some sort')
+
+    def readline(self, len=1024):
+        raise IOError('of some sort')
+
+
+class FakeAppReadline(object):
+    def __call__(self, env, start_response):
+        start_response('200 OK', [('Content-Type', 'text/plain')])
+        line = env['wsgi.input'].readline()
+        return ["FAKE APP"]
+
+
+class FakeLogger(object):
+    def __init__(self, *args, **kwargs):
+        self.msg = ''
+
+    def info(self, string):
+        self.msg = string
+
+
+def start_response(*args):
+    pass
+
+
+class TestProxyLogging(unittest.TestCase):
+
+    def test_basic_req(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        resp = app(req.environ, start_response)
+        resp_body = ''.join(resp)
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[3], 'GET')
+        self.assertEquals(log_parts[4], '/')
+        self.assertEquals(log_parts[5], 'HTTP/1.0')
+        self.assertEquals(log_parts[6], '200')
+        self.assertEquals(resp_body, 'FAKE APP')
+        self.assertEquals(log_parts[11], str(len(resp_body)))
+
+    def test_multi_segment_resp(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(
+            ['some', 'chunks', 'of data']), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        resp = app(req.environ, start_response)
+        resp_body = ''.join(resp)
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[3], 'GET')
+        self.assertEquals(log_parts[4], '/')
+        self.assertEquals(log_parts[5], 'HTTP/1.0')
+        self.assertEquals(log_parts[6], '200')
+        self.assertEquals(resp_body, 'somechunksof data')
+        self.assertEquals(log_parts[11], str(len(resp_body)))
+
+    def test_log_headers(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
+                    {'log_headers': 'yes'})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        resp = app(req.environ, start_response)
+        exhaust_generator = [x for x in resp]
+        log_parts = app.access_logger.msg.split()
+        headers = unquote(log_parts[14]).split('\n')
+        self.assert_('Host: localhost:80' in headers)
+
+    def test_upload_size(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
+                    {'log_headers': 'yes'})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+            'wsgi.input': StringIO.StringIO('some stuff')})
+        resp = app(req.environ, start_response)
+        exhaust_generator = [x for x in resp]
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[10], str(len('some stuff')))
+
+    def test_upload_line(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(),
+                    {'log_headers': 'yes'})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+            'wsgi.input': StringIO.StringIO(
+                            'some stuff\nsome other stuff\n')})
+        resp = app(req.environ, start_response)
+        exhaust_generator = ''.join(resp)
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[10], str(len('some stuff\n')))
+
+    def test_log_query_string(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+                'QUERY_STRING': 'x=3'})
+        resp = app(req.environ, start_response)
+        exhaust_generator = [x for x in resp]
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(unquote(log_parts[4]), '/?x=3')
+
+    def test_client_logging(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+                'REMOTE_ADDR': '1.2.3.4'})
+        resp = app(req.environ, start_response)
+        exhaust_generator = [x for x in resp]
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[0], '1.2.3.4')  # client ip
+        self.assertEquals(log_parts[1], '1.2.3.4')  # remote addr
+
+    def test_proxy_client_logging(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+                'REMOTE_ADDR': '1.2.3.4',
+                'HTTP_X_FORWARDED_FOR': '4.5.6.7,8.9.10.11'
+                })
+        resp = app(req.environ, start_response)
+        exhaust_generator = [x for x in resp]
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[0], '4.5.6.7')  # client ip
+        self.assertEquals(log_parts[1], '1.2.3.4')  # remote addr
+
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+                'REMOTE_ADDR': '1.2.3.4',
+                'HTTP_X_CLUSTER_CLIENT_IP': '4.5.6.7'
+                })
+        resp = app(req.environ, start_response)
+        exhaust_generator = [x for x in resp]
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[0], '4.5.6.7')  # client ip
+        self.assertEquals(log_parts[1], '1.2.3.4')  # remote addr
+
+    def test_facility(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
+                    {'log_headers': 'yes', 'access_log_facility': 'whatever'})
+
+    def test_filter(self):
+        factory = proxy_logging.filter_factory({})
+        self.assert_(callable(factory))
+        self.assert_(callable(factory(FakeApp())))
+
+    def test_unread_body(self):
+        app = proxy_logging.ProxyLoggingMiddleware(
+                FakeApp(['some', 'stuff']), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        resp = app(req.environ, start_response)
+        read_first_chunk = next(resp)
+        resp.close()  # raise a GeneratorExit in middleware app_iter loop
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[6], '499')
+        self.assertEquals(log_parts[11], '4')  # write length
+
+    def test_disconnect_on_readline(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+            'wsgi.input': FileLikeExceptor()})
+        try:
+            resp = app(req.environ, start_response)
+            body = ''.join(resp)
+        except Exception:
+            pass
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[6], '499')
+        self.assertEquals(log_parts[10], '-')  # read length
+
+    def test_disconnect_on_read(self):
+        app = proxy_logging.ProxyLoggingMiddleware(
+                FakeApp(['some', 'stuff']), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
+            'wsgi.input': FileLikeExceptor()})
+        try:
+            resp = app(req.environ, start_response)
+            body = ''.join(resp)
+        except Exception:
+            pass
+        log_parts = app.access_logger.msg.split()
+        self.assertEquals(log_parts[6], '499')
+        self.assertEquals(log_parts[10], '-')  # read length
+
+if __name__ == '__main__':
+    unittest.main()

test/unit/proxy/test_server.py

@@ -546,131 +546,6 @@ class TestController(unittest.TestCase):
 
 class TestProxyServer(unittest.TestCase):
 
-    def test_access_log(self):
-
-        class MyApp(proxy_server.Application):
-
-            def handle_request(self, req):
-                resp = Response(request=req)
-                req.response = resp
-                req.start_time = time()
-                return resp
-
-        def start_response(*args):
-            pass
-
-        class MockLogger():
-
-            def __init__(self):
-                self.buffer = StringIO()
-
-            def info(self, msg, args=None):
-                if args:
-                    msg = msg % args
-                self.buffer.write(msg)
-
-            def strip_value(self):
-                rv = self.buffer.getvalue()
-                self.buffer.truncate(0)
-                return rv
-
-        class SnarfStream(object):
-            # i can't seem to subclass cStringIO
-
-            def __init__(self, *args, **kwargs):
-                self.sio = StringIO()
-
-            def strip_value(self):
-                rv = self.getvalue().strip()
-                self.truncate(0)
-                return rv
-
-            def __getattr__(self, name):
-                try:
-                    return object.__getattr__(self, name)
-                except AttributeError:
-                    try:
-                        return getattr(self.sio, name)
-                    except AttributeError:
-                        return self.__getattribute__(name)
-
-        snarf = SnarfStream()
-        _orig_get_logger = proxy_server.get_logger
-
-        def mock_get_logger(*args, **kwargs):
-            if kwargs.get('log_route') != 'proxy-access':
-                return _orig_get_logger(*args, **kwargs)
-            kwargs['log_route'] = 'snarf'
-            logger = _orig_get_logger(*args, **kwargs)
-            if [h for h in logger.logger.handlers if
-                isinstance(h, logging.StreamHandler) and h.stream is snarf]:
-                # snarf handler already setup!
-                return logger
-            formatter = logger.logger.handlers[0].formatter
-            formatter._fmt += ' %(levelname)s'
-            snarf_handler = logging.StreamHandler(snarf)
-            snarf_handler.setFormatter(formatter)
-            logger.logger.addHandler(snarf_handler)
-            return logger
-
-        def test_conf(conf):
-            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
-                        container_ring=FakeRing(), object_ring=FakeRing())
-            req = Request.blank('')
-            app(req.environ, start_response)
-
-        try:
-            proxy_server.get_logger = mock_get_logger
-            test_conf({})
-            line = snarf.strip_value()
-            self.assert_(line.startswith('swift'))
-            self.assert_(line.endswith('INFO'))
-            test_conf({'log_name': 'snarf-test'})
-            line = snarf.strip_value()
-            self.assert_(line.startswith('snarf-test'))
-            self.assert_(line.endswith('INFO'))
-            test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR'})
-            line = snarf.strip_value()
-            self.assertFalse(line)
-            test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR',
-                       'access_log_name': 'access-test',
-                       'access_log_level': 'INFO'})
-            line = snarf.strip_value()
-            self.assert_(line.startswith('access-test'))
-            self.assert_(line.endswith('INFO'))
-
-            # test facility
-            def get_facility(logger):
-                h = [h for h in logger.logger.handlers if
-                     isinstance(h, SysLogHandler)][0]
-                return h.facility
-
-            conf = {'log_facility': 'LOG_LOCAL0'}
-            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
-                        container_ring=FakeRing(), object_ring=FakeRing())
-            self.assertEquals(get_facility(app.logger),
-                              SysLogHandler.LOG_LOCAL0)
-            self.assertEquals(get_facility(app.access_logger),
-                              SysLogHandler.LOG_LOCAL0)
-            conf = {'log_facility': 'LOG_LOCAL0',
-                    'access_log_facility': 'LOG_LOCAL1'}
-            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
-                        container_ring=FakeRing(), object_ring=FakeRing())
-            self.assertEquals(get_facility(app.logger),
-                              SysLogHandler.LOG_LOCAL0)
-            self.assertEquals(get_facility(app.access_logger),
-                              SysLogHandler.LOG_LOCAL1)
-            conf = {'access_log_facility': 'LOG_LOCAL1'}
-            app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(),
-                        container_ring=FakeRing(), object_ring=FakeRing())
-            self.assertEquals(get_facility(app.logger),
-                              SysLogHandler.LOG_LOCAL0)
-            self.assertEquals(get_facility(app.access_logger),
-                              SysLogHandler.LOG_LOCAL1)
-
-        finally:
-            proxy_server.get_logger = _orig_get_logger
-
     def test_unhandled_exception(self):
 
         class MyApp(proxy_server.Application):
@@ -2133,77 +2008,6 @@ class TestObjectController(unittest.TestCase):
         self.assertEquals(headers[:len(exp)], exp)
         self.assert_('\r\nContent-Length: 0\r\n' in headers)
 
-    def test_client_ip_logging(self):
-        # test that the client ip field in the log gets populated with the
-        # ip instead of being blank
-        (prosrv, acc1srv, acc2srv, con1srv, con2srv, obj1srv, obj2srv) = \
-                _test_servers
-        (prolis, acc1lis, acc2lis, con1lis, con2lis, obj1lis, obj2lis) = \
-                 _test_sockets
-
-        orig_logger, orig_access_logger = prosrv.logger, prosrv.access_logger
-        prosrv.logger = prosrv.access_logger = FakeLogger()
-        sock = connect_tcp(('localhost', prolis.getsockname()[1]))
-        fd = sock.makefile()
-        fd.write(
-            'GET /v1/a?format=json HTTP/1.1\r\nHost: localhost\r\n'
-            'Connection: close\r\nX-Auth-Token: t\r\n'
-            'Content-Length: 0\r\n'
-            '\r\n')
-        fd.flush()
-        headers = readuntil2crlfs(fd)
-        exp = 'HTTP/1.1 200'
-        self.assertEquals(headers[:len(exp)], exp)
-        exp = '127.0.0.1 127.0.0.1'
-        self.assertEquals(prosrv.logger.log_dict['exception'], [])
-        self.assert_(exp in prosrv.logger.log_dict['info'][-1][0][0])
-
-    def test_chunked_put_logging(self):
-        # GET account with a query string to test that
-        # Application.log_request logs the query string. Also, throws
-        # in a test for logging x-forwarded-for (first entry only).
-        (prosrv, acc1srv, acc2srv, con1srv, con2srv, obj1srv, obj2srv) = \
-                _test_servers
-        (prolis, acc1lis, acc2lis, con1lis, con2lis, obj1lis, obj2lis) = \
-                 _test_sockets
-
-        orig_logger, orig_access_logger = prosrv.logger, prosrv.access_logger
-        prosrv.logger = prosrv.access_logger = FakeLogger()
-        sock = connect_tcp(('localhost', prolis.getsockname()[1]))
-        fd = sock.makefile()
-        fd.write(
-            'GET /v1/a?format=json HTTP/1.1\r\nHost: localhost\r\n'
-            'Connection: close\r\nX-Auth-Token: t\r\n'
-            'Content-Length: 0\r\nX-Forwarded-For: host1, host2\r\n'
-            '\r\n')
-        fd.flush()
-        headers = readuntil2crlfs(fd)
-        exp = 'HTTP/1.1 200'
-        self.assertEquals(headers[:len(exp)], exp)
-        got_log_msg = prosrv.logger.log_dict['info'][-1][0][0]
-        self.assert_('/v1/a%3Fformat%3Djson' in got_log_msg,
-                     prosrv.logger.log_dict)
-        exp = 'host1'
-        self.assertEquals(got_log_msg[:len(exp)], exp)
-        # Turn on header logging.
-
-        prosrv.logger = prosrv.access_logger = FakeLogger()
-        prosrv.log_headers = True
-        sock = connect_tcp(('localhost', prolis.getsockname()[1]))
-        fd = sock.makefile()
-        fd.write('GET /v1/a HTTP/1.1\r\nHost: localhost\r\n'
-            'Connection: close\r\nX-Auth-Token: t\r\n'
-            'Content-Length: 0\r\nGoofy-Header: True\r\n\r\n')
-        fd.flush()
-        headers = readuntil2crlfs(fd)
-        exp = 'HTTP/1.1 200'
-        self.assertEquals(headers[:len(exp)], exp)
-        self.assert_('Goofy-Header%3A%20True' in
-                     prosrv.logger.log_dict['info'][-1][0][0],
-                     prosrv.logger.log_dict)
-        prosrv.log_headers = False
-        prosrv.logger, prosrv.access_logger = orig_logger, orig_access_logger
-
     def test_chunked_put_utf8_all_the_way_down(self):
         # Test UTF-8 Unicode all the way through the system
         ustr = '\xe1\xbc\xb8\xce\xbf\xe1\xbd\xba \xe1\xbc\xb0\xce' \
@@ -2914,87 +2718,6 @@ class TestObjectController(unittest.TestCase):
             resp = controller.PUT(req)
             self.assertEquals(resp.status_int // 100, 4)  # client error
 
-    def test_request_bytes_transferred_attr(self):
-        with save_globals():
-            proxy_server.http_connect = \
-                fake_http_connect(200, 200, 201, 201, 201)
-            controller = proxy_server.ObjectController(self.app, 'account',
-                            'container', 'object')
-            req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'PUT'},
-                                headers={'Content-Length': '10'},
-                                body='1234567890')
-            self.app.update_request(req)
-            res = controller.PUT(req)
-            self.assert_(hasattr(req, 'bytes_transferred'))
-            self.assertEquals(req.bytes_transferred, 10)
-
-    def test_copy_zero_bytes_transferred_attr(self):
-        with save_globals():
-            proxy_server.http_connect = \
-                fake_http_connect(200, 200, 200, 200, 200, 201, 201, 201,
-                                  body='1234567890')
-            controller = proxy_server.ObjectController(self.app, 'account',
-                            'container', 'object')
-            req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'PUT'},
-                                headers={'X-Copy-From': 'c/o2',
-                                         'Content-Length': '0'})
-            self.app.update_request(req)
-            res = controller.PUT(req)
-            self.assert_(hasattr(req, 'bytes_transferred'))
-            self.assertEquals(req.bytes_transferred, 0)
-
-    def test_response_bytes_transferred_attr(self):
-        with save_globals():
-            proxy_server.http_connect = \
-                fake_http_connect(200, 200, 200, body='1234567890')
-            controller = proxy_server.ObjectController(self.app, 'account',
-                            'container', 'object')
-            req = Request.blank('/a/c/o')
-            self.app.update_request(req)
-            res = controller.GET(req)
-            res.body
-            self.assert_(hasattr(res, 'bytes_transferred'))
-            self.assertEquals(res.bytes_transferred, 10)
-
-    def test_request_client_disconnect_attr(self):
-        with save_globals():
-            proxy_server.http_connect = \
-                fake_http_connect(200, 200, 201, 201, 201)
-            controller = proxy_server.ObjectController(self.app, 'account',
-                            'container', 'object')
-            req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'PUT'},
-                                headers={'Content-Length': '10'},
-                                body='12345')
-            self.app.update_request(req)
-            res = controller.PUT(req)
-            self.assertEquals(req.bytes_transferred, 5)
-            self.assert_(hasattr(req, 'client_disconnect'))
-            self.assert_(req.client_disconnect)
-
-    def test_response_client_disconnect_attr(self):
-        with save_globals():
-            proxy_server.http_connect = \
-                fake_http_connect(200, 200, 200, body='1234567890')
-            controller = proxy_server.ObjectController(self.app, 'account',
-                            'container', 'object')
-            req = Request.blank('/a/c/o')
-            self.app.update_request(req)
-            orig_object_chunk_size = self.app.object_chunk_size
-            try:
-                self.app.object_chunk_size = 5
-                res = controller.GET(req)
-                ix = 0
-                for v in res.app_iter:
-                    ix += 1
-                    if ix > 1:
-                        break
-                res.app_iter.close()
-                self.assertEquals(res.bytes_transferred, 5)
-                self.assert_(hasattr(res, 'client_disconnect'))
-                self.assert_(res.client_disconnect)
-            finally:
-                self.app.object_chunk_size = orig_object_chunk_size
-
     def test_response_get_accept_ranges_header(self):
         with save_globals():
             req = Request.blank('/a/c/o', environ={'REQUEST_METHOD': 'GET'})
@@ -3561,41 +3284,6 @@ class TestContainerController(unittest.TestCase):
             self.assert_status_map(controller.DELETE,
                                    (200, 404, 404, 404), 404)
 
-    def test_response_bytes_transferred_attr(self):
-        with save_globals():
-            proxy_server.http_connect = fake_http_connect(200, 200, body='{}')
-            controller = proxy_server.ContainerController(self.app, 'account',
-                                                          'container')
-            req = Request.blank('/a/c?format=json')
-            self.app.update_request(req)
-            res = controller.GET(req)
-            res.body
-            self.assert_(hasattr(res, 'bytes_transferred'))
-            self.assertEquals(res.bytes_transferred, 2)
-
-    def test_response_client_disconnect_attr(self):
-        with save_globals():
-            proxy_server.http_connect = fake_http_connect(200, 200, body='{}')
-            controller = proxy_server.ContainerController(self.app, 'account',
-                                                          'container')
-            req = Request.blank('/a/c?format=json')
-            self.app.update_request(req)
-            orig_object_chunk_size = self.app.object_chunk_size
-            try:
-                self.app.object_chunk_size = 1
-                res = controller.GET(req)
-                ix = 0
-                for v in res.app_iter:
-                    ix += 1
-                    if ix > 1:
-                        break
-                res.app_iter.close()
-                self.assertEquals(res.bytes_transferred, 1)
-                self.assert_(hasattr(res, 'client_disconnect'))
-                self.assert_(res.client_disconnect)
-            finally:
-                self.app.object_chunk_size = orig_object_chunk_size
-
     def test_response_get_accept_ranges_header(self):
         with save_globals():
             proxy_server.http_connect = fake_http_connect(200, 200, body='{}')
@@ -3950,17 +3638,6 @@ class TestAccountController(unittest.TestCase):
         resp = controller.HEAD(req)
         self.assertEquals(resp.status_int, 503)
 
-    def test_response_bytes_transferred_attr(self):
-        with save_globals():
-            proxy_server.http_connect = fake_http_connect(200, 200, body='{}')
-            controller = proxy_server.AccountController(self.app, 'account')
-            req = Request.blank('/a?format=json')
-            self.app.update_request(req)
-            res = controller.GET(req)
-            res.body
-            self.assert_(hasattr(res, 'bytes_transferred'))
-            self.assertEquals(res.bytes_transferred, 2)
-
     def test_response_get_accept_ranges_header(self):
         with save_globals():
             proxy_server.http_connect = fake_http_connect(200, 200, body='{}')
@@ -3982,28 +3659,6 @@ class TestAccountController(unittest.TestCase):
             self.assert_('accept-ranges' in res.headers)
             self.assertEqual(res.headers['accept-ranges'], 'bytes')
 
-    def test_response_client_disconnect_attr(self):
-        with save_globals():
-            proxy_server.http_connect = fake_http_connect(200, 200, body='{}')
-            controller = proxy_server.AccountController(self.app, 'account')
-            req = Request.blank('/a?format=json')
-            self.app.update_request(req)
-            orig_object_chunk_size = self.app.object_chunk_size
-            try:
-                self.app.object_chunk_size = 1
-                res = controller.GET(req)
-                ix = 0
-                for v in res.app_iter:
-                    ix += 1
-                    if ix > 1:
-                        break
-                res.app_iter.close()
-                self.assertEquals(res.bytes_transferred, 1)
-                self.assert_(hasattr(res, 'client_disconnect'))
-                self.assert_(res.client_disconnect)
-            finally:
-                self.app.object_chunk_size = orig_object_chunk_size
-
     def test_PUT(self):
         with save_globals():
             controller = proxy_server.AccountController(self.app, 'account')
@@ -4325,14 +3980,12 @@ class TestSegmentedIterable(unittest.TestCase):
             'o1'}])
         segit.response = Stub()
         self.assertEquals(''.join(segit), '1')
-        self.assertEquals(segit.response.bytes_transferred, 1)
 
     def test_iter_with_two_segments(self):
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', [{'name':
             'o1'}, {'name': 'o2'}])
         segit.response = Stub()
         self.assertEquals(''.join(segit), '122')
-        self.assertEquals(segit.response.bytes_transferred, 3)
 
     def test_iter_with_get_error(self):
 
@@ -4372,7 +4025,6 @@ class TestSegmentedIterable(unittest.TestCase):
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, None)), '1')
-        self.assertEquals(segit.response.bytes_transferred, 1)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         self.assertEquals(''.join(segit.app_iter_range(3, None)), '')
@@ -4383,7 +4035,6 @@ class TestSegmentedIterable(unittest.TestCase):
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, 5)), '1')
-        self.assertEquals(segit.response.bytes_transferred, 1)
 
     def test_app_iter_range_with_two_segments(self):
         listing = [{'name': 'o1', 'bytes': 1}, {'name': 'o2', 'bytes': 2}]
@@ -4391,22 +4042,18 @@ class TestSegmentedIterable(unittest.TestCase):
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, None)), '122')
-        self.assertEquals(segit.response.bytes_transferred, 3)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(1, None)), '22')
-        self.assertEquals(segit.response.bytes_transferred, 2)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(1, 5)), '22')
-        self.assertEquals(segit.response.bytes_transferred, 2)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, 2)), '12')
-        self.assertEquals(segit.response.bytes_transferred, 2)
 
     def test_app_iter_range_with_many_segments(self):
         listing = [{'name': 'o1', 'bytes': 1}, {'name': 'o2', 'bytes': 2},
@@ -4417,38 +4064,31 @@ class TestSegmentedIterable(unittest.TestCase):
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, None)),
             '122333444455555')
-        self.assertEquals(segit.response.bytes_transferred, 15)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(3, None)),
             '333444455555')
-        self.assertEquals(segit.response.bytes_transferred, 12)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(5, None)), '3444455555')
-        self.assertEquals(segit.response.bytes_transferred, 10)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, 6)), '122333')
-        self.assertEquals(segit.response.bytes_transferred, 6)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(None, 7)), '1223334')
-        self.assertEquals(segit.response.bytes_transferred, 7)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(3, 7)), '3334')
-        self.assertEquals(segit.response.bytes_transferred, 4)
 
         segit = proxy_server.SegmentedIterable(self.controller, 'lc', listing)
         segit.response = Stub()
         self.assertEquals(''.join(segit.app_iter_range(5, 7)), '34')
-        self.assertEquals(segit.response.bytes_transferred, 2)
 
 
 if __name__ == '__main__':