Added logging of x-delete-at values

Added logging of the x-delete-at value for object PUTs and POSTs and
made the additional log field generic for other similar use cases.

Logging the x-delete-at is useful because otherwise you might never
know why an object "disappeared" just by looking at saved proxy logs.
You'd see a successful PUT of the object followed some time by a GET
that 404s. If you still have the other logs, you could track down
what happened; but, at least with our clusters, we keep proxy logs
forever but only keep the other logs for a short while.

Change-Id: Ida559abcf8dc5666e2a7eea250a67d1c4b28b1be

swift/common/middleware/proxy_logging.py

@@ -23,7 +23,7 @@ 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
+    client_etag transaction_id headers request_time source log_info
 
 These values are space-separated, and each is url-encoded, so that they can
 be separated with a simple .split()
@@ -33,6 +33,18 @@ be separated with a simple .split()
   from the X-Forwarded-For header, X-Cluster-Ip header, or the REMOTE_ADDR
   environment variable.
 
+* source (swift.source in the WSGI environment) indicates the code
+  that generated the request, such as most middleware. (See below for
+  more detail.)
+
+* log_info (swift.log_info in the WSGI environment) is for additional
+  information that could prove quite useful, such as any x-delete-at
+  value or other "behind the scenes" activity that might not
+  otherwise be detectable from the plain log information. Code that
+  wishes to add additional log information should use code like
+  ``env.setdefault('swift.log_info', []).append(your_info)`` so as to
+  not disturb others' log information.
+
 * Values that are missing (e.g. due to a header not being present) or zero
   are generally represented by a single hyphen ('-').
 
@@ -152,6 +164,7 @@ class ProxyLoggingMiddleware(object):
                 logged_headers,
                 '%.4f' % request_time,
                 req.environ.get('swift.source'),
+                ','.join(req.environ.get('swift.log_info') or '-'),
             )))
         self.mark_req_logged(req)
         # Log timing and bytes-transfered data to StatsD

swift/proxy/controllers/obj.py

@@ -589,6 +589,8 @@ class ObjectController(Controller):
                     return HTTPBadRequest(request=req,
                                           content_type='text/plain',
                                           body='Non-integer X-Delete-At')
+                req.environ.setdefault('swift.log_info', []).append(
+                    'x-delete-at:%d' % x_delete_at)
                 delete_at_container = str(
                     x_delete_at /
                     self.app.expiring_objects_container_divisor *
@@ -866,6 +868,8 @@ class ObjectController(Controller):
             except ValueError:
                 return HTTPBadRequest(request=req, content_type='text/plain',
                                       body='Non-integer X-Delete-At')
+            req.environ.setdefault('swift.log_info', []).append(
+                'x-delete-at:%d' % x_delete_at)
             delete_at_container = str(
                 x_delete_at /
                 self.app.expiring_objects_container_divisor *

test/unit/common/middleware/test_proxy_logging.py

@@ -537,6 +537,44 @@ class TestProxyLogging(unittest.TestCase):
         self.assertEquals(resp_body, 'FAKE APP')
         self.assertEquals(log_parts[11], str(len(resp_body)))
 
+    def test_log_info_none(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 = self._log_parts(app)
+        self.assertEquals(log_parts[17], '-')
+
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        req.environ['swift.log_info'] = []
+        resp = app(req.environ, start_response)
+        resp_body = ''.join(resp)
+        log_parts = self._log_parts(app)
+        self.assertEquals(log_parts[17], '-')
+
+    def test_log_info_single(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        req.environ['swift.log_info'] = ['one']
+        resp = app(req.environ, start_response)
+        resp_body = ''.join(resp)
+        log_parts = self._log_parts(app)
+        self.assertEquals(log_parts[17], 'one')
+
+    def test_log_info_multiple(self):
+        app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
+        app.access_logger = FakeLogger()
+        req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
+        req.environ['swift.log_info'] = ['one', 'and two']
+        resp = app(req.environ, start_response)
+        resp_body = ''.join(resp)
+        log_parts = self._log_parts(app)
+        self.assertEquals(log_parts[17], 'one%2Cand%20two')
+
 
 if __name__ == '__main__':
     unittest.main()