Let users add their own txid suffixes

The value of the X-Trans-Id-Extra header on the request (if any) will
now be appended to the transaction ID. This lets users put their own
information into transaction IDs.

For example, Glance folks upload images as large objects, so they'd
like to be able to tie together all the segment PUTs and the manifest
PUT with some operation ID in the logs. This would let them pass in
that operation ID as X-Trans-Id-Extra, and then when things went
wrong, it'd be much easier to find all the requests in Swift's logs.

Also, this aids debuggability when requests fail to receive
responses. If a user is sending in their own X-Trans-Id-Extra strings,
then that gives operators something to search for in the logs. The
normal txid won't work since that's in the response, but the client
didn't receive one.

Swift will only use the first 32 characters of X-Trans-Id-Extra so
that its log lines stay a manageable length. Also, it's URL-quoted so
that users cannot inject double quotes into X-Trans-Id-Extra and screw
up log parsers.

DocImpact

Change-Id: I3c51d0c5ac55697ac230001840da219e73a03157

swift/common/middleware/catch_errors.py

@@ -28,7 +28,12 @@ class CatchErrorsContext(WSGIContext):
         self.trans_id_suffix = trans_id_suffix
 
     def handle_request(self, env, start_response):
-        trans_id = generate_trans_id(self.trans_id_suffix)
+        trans_id_suffix = self.trans_id_suffix
+        trans_id_extra = env.get('HTTP_X_TRANS_ID_EXTRA')
+        if trans_id_extra:
+            trans_id_suffix += '-' + trans_id_extra[:32]
+
+        trans_id = generate_trans_id(trans_id_suffix)
         env['swift.trans_id'] = trans_id
         self.logger.txn_id = trans_id
         try:

swift/common/utils.py

@@ -289,7 +289,7 @@ def load_libc_function(func_name, log_error=True):
 
 def generate_trans_id(trans_id_suffix):
     return 'tx%s-%010x%s' % (
-        uuid.uuid4().hex[:21], time.time(), trans_id_suffix)
+        uuid.uuid4().hex[:21], time.time(), quote(trans_id_suffix))
 
 
 def get_log_line(req, res, trans_time, additional_info):

swift/proxy/server.py

@@ -318,7 +318,11 @@ class Application(object):
             controller = controller(self, **path_parts)
             if 'swift.trans_id' not in req.environ:
                 # if this wasn't set by an earlier middleware, set it now
-                trans_id = generate_trans_id(self.trans_id_suffix)
+                trans_id_suffix = self.trans_id_suffix
+                trans_id_extra = req.headers.get('x-trans-id-extra')
+                if trans_id_extra:
+                    trans_id_suffix += '-' + trans_id_extra[:32]
+                trans_id = generate_trans_id(trans_id_suffix)
                 req.environ['swift.trans_id'] = trans_id
                 self.logger.txn_id = trans_id
             req.headers['x-trans-id'] = req.environ['swift.trans_id']

test/unit/common/middleware/test_except.py

@@ -103,6 +103,42 @@ class TestCatchErrors(unittest.TestCase):
         app(req.environ, start_response)
         self.assertTrue(self.logger.txn_id.endswith('-stuff'))
 
+    def test_trans_id_header_extra(self):
+        self.assertEquals(self.logger.txn_id, None)
+
+        def start_response(status, headers, exc_info=None):
+            self.assert_('X-Trans-Id' in (x[0] for x in headers))
+        app = catch_errors.CatchErrorMiddleware(
+            FakeApp(), {'trans_id_suffix': '-fromconf'})
+        req = Request.blank('/v1/a/c/o',
+                            headers={'X-Trans-Id-Extra': 'fromuser'})
+        app(req.environ, start_response)
+        self.assertTrue(self.logger.txn_id.endswith('-fromconf-fromuser'))
+
+    def test_trans_id_header_extra_length_limit(self):
+        self.assertEquals(self.logger.txn_id, None)
+
+        def start_response(status, headers, exc_info=None):
+            self.assert_('X-Trans-Id' in (x[0] for x in headers))
+        app = catch_errors.CatchErrorMiddleware(
+            FakeApp(), {'trans_id_suffix': '-fromconf'})
+        req = Request.blank('/v1/a/c/o',
+                            headers={'X-Trans-Id-Extra': 'a' * 1000})
+        app(req.environ, start_response)
+        self.assertTrue(self.logger.txn_id.endswith(
+            '-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'))
+
+    def test_trans_id_header_extra_quoted(self):
+        self.assertEquals(self.logger.txn_id, None)
+
+        def start_response(status, headers, exc_info=None):
+            self.assert_('X-Trans-Id' in (x[0] for x in headers))
+        app = catch_errors.CatchErrorMiddleware(FakeApp(), {})
+        req = Request.blank('/v1/a/c/o',
+                            headers={'X-Trans-Id-Extra': 'xan than"gum'})
+        app(req.environ, start_response)
+        self.assertTrue(self.logger.txn_id.endswith('-xan%20than%22gum'))
+
     def test_catcherrors_with_unexpected_error(self):
         app = catch_errors.CatchErrorMiddleware(FakeApp(error='strange'), {})
         req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})

test/unit/proxy/test_server.py

@@ -578,6 +578,43 @@ class TestProxyServer(unittest.TestCase):
         finally:
             rmtree(swift_dir, ignore_errors=True)
 
+    def test_adds_transaction_id(self):
+        swift_dir = mkdtemp()
+        try:
+            logger = FakeLogger()
+            baseapp = proxy_server.Application({'swift_dir': swift_dir},
+                                               FakeMemcache(), logger,
+                                               FakeRing(), FakeRing(),
+                                               FakeRing())
+            baseapp.handle_request(
+                Request.blank('/info',
+                              environ={'HTTP_X_TRANS_ID_EXTRA': 'sardine',
+                                       'REQUEST_METHOD': 'GET'}))
+            # This is kind of a hokey way to get the transaction ID; it'd be
+            # better to examine response headers, but the catch_errors
+            # middleware is what sets the X-Trans-Id header, and we don't have
+            # that available here.
+            self.assertTrue(logger.txn_id.endswith('-sardine'))
+        finally:
+            rmtree(swift_dir, ignore_errors=True)
+
+    def test_adds_transaction_id_length_limit(self):
+        swift_dir = mkdtemp()
+        try:
+            logger = FakeLogger()
+            baseapp = proxy_server.Application({'swift_dir': swift_dir},
+                                               FakeMemcache(), logger,
+                                               FakeRing(), FakeRing(),
+                                               FakeRing())
+            baseapp.handle_request(
+                Request.blank('/info',
+                              environ={'HTTP_X_TRANS_ID_EXTRA': 'a' * 1000,
+                                       'REQUEST_METHOD': 'GET'}))
+            self.assertTrue(logger.txn_id.endswith(
+                '-aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'))
+        finally:
+            rmtree(swift_dir, ignore_errors=True)
+
     def test_denied_host_header(self):
         swift_dir = mkdtemp()
         try: