Merge "Fix missing txn_id logs in GreenAsyncPile's spawned functions"

swift/proxy/controllers/obj.py

@@ -329,7 +329,8 @@ class BaseObjectController(Controller):
             else:
                 return conn.getresponse()
 
-    def _get_conn_response(self, conn, req, **kwargs):
+    def _get_conn_response(self, conn, req, logger_thread_locals, **kwargs):
+        self.app.logger.thread_locals = logger_thread_locals
         try:
             resp = self._await_response(conn, **kwargs)
             return (conn, resp)
@@ -350,7 +351,8 @@ class BaseObjectController(Controller):
 
         pile = GreenAsyncPile(len(conns))
         for conn in conns:
-            pile.spawn(self._get_conn_response, conn, req)
+            pile.spawn(self._get_conn_response, conn,
+                       req, self.app.logger.thread_locals)
 
         def _handle_response(conn, response):
             statuses.append(response.status)
@@ -2340,7 +2342,9 @@ class ECObjectController(BaseObjectController):
         return conn.await_response(
             self.app.node_timeout, not final_phase)
 
-    def _get_conn_response(self, conn, req, final_phase, **kwargs):
+    def _get_conn_response(self, conn, req, logger_thread_locals,
+                           final_phase, **kwargs):
+        self.app.logger.thread_locals = logger_thread_locals
         try:
             resp = self._await_response(conn, final_phase=final_phase,
                                         **kwargs)
@@ -2383,7 +2387,7 @@ class ECObjectController(BaseObjectController):
             if putter.failed:
                 continue
             pile.spawn(self._get_conn_response, putter, req,
-                       final_phase=final_phase)
+                       self.app.logger.thread_locals, final_phase=final_phase)
 
         def _handle_response(putter, response):
             statuses.append(response.status)

test/unit/__init__.py

@@ -607,12 +607,19 @@ class FakeLogger(logging.Logger, object):
         pass
 
 
+class DebugSwiftLogFormatter(utils.SwiftLogFormatter):
+
+    def format(self, record):
+        msg = super(DebugSwiftLogFormatter, self).format(record)
+        return msg.replace('#012', '\n')
+
+
 class DebugLogger(FakeLogger):
     """A simple stdout logging version of FakeLogger"""
 
     def __init__(self, *args, **kwargs):
         FakeLogger.__init__(self, *args, **kwargs)
-        self.formatter = logging.Formatter(
+        self.formatter = DebugSwiftLogFormatter(
             "%(server)s %(levelname)s: %(message)s")
 
     def handle(self, record):

test/unit/proxy/controllers/test_obj.py

@@ -536,6 +536,22 @@ class TestReplicatedObjController(BaseObjectControllerMixin,
             resp = req.get_response(self.app)
         self.assertEqual(resp.status_int, 201)
 
+    def test_txn_id_logging_on_PUT(self):
+        req = swift.common.swob.Request.blank('/v1/a/c/o', method='PUT')
+        self.app.logger.txn_id = req.environ['swift.trans_id'] = 'test-txn-id'
+        req.headers['content-length'] = '0'
+        # we capture stdout since the debug log formatter prints the formatted
+        # message to stdout
+        stdout = BytesIO()
+        with set_http_connect((100, Timeout()), 503, 503), \
+                mock.patch('sys.stdout', stdout):
+            resp = req.get_response(self.app)
+        self.assertEqual(resp.status_int, 503)
+        for line in stdout.getvalue().splitlines():
+            self.assertIn('test-txn-id', line)
+        self.assertIn('Trying to get final status of PUT to',
+                      stdout.getvalue())
+
     def test_PUT_empty_bad_etag(self):
         req = swift.common.swob.Request.blank('/v1/a/c/o', method='PUT')
         req.headers['Content-Length'] = '0'
@@ -1240,6 +1256,25 @@ class TestECObjController(BaseObjectControllerMixin, unittest.TestCase):
             resp = req.get_response(self.app)
         self.assertEqual(resp.status_int, 201)
 
+    def test_txn_id_logging_ECPUT(self):
+        req = swift.common.swob.Request.blank('/v1/a/c/o', method='PUT',
+                                              body='')
+        self.app.logger.txn_id = req.environ['swift.trans_id'] = 'test-txn-id'
+        codes = [(100, Timeout(), 503, 503)] * self.replicas()
+        stdout = BytesIO()
+        expect_headers = {
+            'X-Obj-Metadata-Footer': 'yes',
+            'X-Obj-Multiphase-Commit': 'yes'
+        }
+        with set_http_connect(*codes, expect_headers=expect_headers), \
+                mock.patch('sys.stdout', stdout):
+            resp = req.get_response(self.app)
+        self.assertEqual(resp.status_int, 503)
+        for line in stdout.getvalue().splitlines():
+            self.assertIn('test-txn-id', line)
+        self.assertIn('Trying to get ',
+                      stdout.getvalue())
+
     def test_PUT_with_explicit_commit_status(self):
         req = swift.common.swob.Request.blank('/v1/a/c/o', method='PUT',
                                               body='')