openstack team mailing list archive

[Pete Zaitcev <zaitcev@xxxxxxxxxx>]

Hi, Mike:

I applied the proxy_logging patch (change 5284) to another Swift, which
happens to have the swift3 loaded, and S3 accesses started to fail.
Since swift3 is an existing part of Swift, I put a -1 on the review
for now, and I hope we can resolve this somehow and re-spin a patch #7.

The pipeline looks like this:

[zaitcev@kvm-san ~]$ grep pipeline /etc/swift/proxy-server.conf 
[pipeline:main]
pipeline = healthcheck cache swift3 swauth proxy-logging proxy-server
[zaitcev@kvm-san ~]$ 

As much as I can tell, the scenario is this:

 - swift3's app.__call__ identifies the request as S3. If it's native
   Swift, it is passed along unmolested and works fine.

 - __call__ find the controller, say ServiceController

 - controller defines an intercept start_response(), do_start_response,
   invokes the downstream app with it

 - proxy_logger's app.__call__, however, is a generator (has yield).
   As I guess, a generator is used as a tool to postpone logging
   like a hook was before

 - as downstream app returns to swift3, it assumes that start_response
   was called by the app, but in fact, only the generator prologue
   was called and returned an iterable. The fields that do_start_response
   fills are not filled, and swift3 tracebacks with IndexError.

I threw together a patch like this (against proxy log patch #6):

commit 66b08d63c41c8aeebe745b00ba942dc564595e58
Author: Pete Zaitcev <zaitcev@xxxxxxxxxxxxxxxxx>
Date:   Fri May 4 17:34:32 2012 -0600

    Fixed swift3 but now proxy_logging does not log anything for PUT.

diff --git a/swift/common/middleware/proxy_logging.py b/swift/common/middleware/proxy_logging.py
index b5f25df..c3f4467 100644
--- a/swift/common/middleware/proxy_logging.py
+++ b/swift/common/middleware/proxy_logging.py
@@ -101,6 +101,10 @@ class ProxyLoggingMiddleware(object):
         self.access_logger = get_logger(access_log_conf,
                         log_route='proxy-access')
 
+        self.client_disconnect = False
+        self.input_proxy = None
+        self.start_time = None
+
     def log_request(self, env, status_int, bytes_received, bytes_sent,
                     request_time, client_disconnect):
         """
@@ -144,31 +148,34 @@ class ProxyLoggingMiddleware(object):
             )))
         self.access_logger.txn_id = None
 
-    def __call__(self, env, start_response):
-        status_int = [500]
+    def log_generator(self, env, status_int, body_resp):
         bytes_sent = 0
-        client_disconnect = False
-        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)
-
         try:
-            for chunk in self.app(env, my_start_response):
+            for chunk in body_resp:
                 bytes_sent += len(chunk)
                 yield chunk
         except GeneratorExit:  # generator was closed before we finished
-            client_disconnect = True
+            self.client_disconnect = True
             raise
         finally:
-            request_time = time.time() - start_time
-            self.log_request(env, status_int[0], input_proxy.bytes_received,
-                    bytes_sent, request_time,
-                    client_disconnect or input_proxy.client_disconnect)
+            request_time = time.time() - sef.start_time
+            self.log_request(env, status_int[0],
+                self.input_proxy.bytes_received, bytes_sent, request_time,
+                self.client_disconnect or self.input_proxy.client_disconnect)
+
+    def __call__(self, env, start_response):
+        status_int = [500]
+        self.client_disconnect = False
+        self.input_proxy = InputProxy(env['wsgi.input'])
+        env['wsgi.input'] = self.input_proxy
+        self.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)
 
+        body_resp = self.app(env, my_start_response)
+        return self.log_generator(env, status_int, body_resp)
 
 def filter_factory(global_conf, **local_conf):
     conf = global_conf.copy()

With the above, the server works once again, but I did something wrong
and PUT requests are not logged by the proxy_logging anymore. It seems
like generator's "finally" clause is not invoked somehow. I thought it
was supposed to be invoked when the iterator is deleted, but most likely
I'm confused.

I need you to take over and apply your Python-fu, because mine is lacking.

Cheers,
-- Pete