From 4906b4c431edc436f165b163a228b0a221950c79 Mon Sep 17 00:00:00 2001 From: Janonymous Date: Tue, 12 Jan 2016 12:50:43 +0530 Subject: [PATCH] Fix missing txn_id logs in GreenAsyncPile's spawned functions This commit ensures that the logger thread_locals value is passed to and set in _get_conn_response methods executed in a green thread. Added partial bug tag because in bug description a more relevant fix is suggested which would fix the bug completely but for now this makes sense to add this commit for logging. Co-Authored-By: Clay Gerrard Change-Id: I13bbf174fdca89318d69bb0674ed23dc9ec25b9a Partial-Bug: #1409302 --- swift/proxy/controllers/obj.py | 12 ++++++--- test/unit/__init__.py | 9 ++++++- test/unit/proxy/controllers/test_obj.py | 35 +++++++++++++++++++++++++ 3 files changed, 51 insertions(+), 5 deletions(-) diff --git a/swift/proxy/controllers/obj.py b/swift/proxy/controllers/obj.py index e5910d312e..e129da4bbc 100644 --- a/swift/proxy/controllers/obj.py +++ b/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) @@ -2334,7 +2336,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) @@ -2377,7 +2381,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) diff --git a/test/unit/__init__.py b/test/unit/__init__.py index ec6a2a0985..f456e15a49 100644 --- a/test/unit/__init__.py +++ b/test/unit/__init__.py @@ -614,12 +614,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): diff --git a/test/unit/proxy/controllers/test_obj.py b/test/unit/proxy/controllers/test_obj.py index 655bf07700..178707748d 100755 --- a/test/unit/proxy/controllers/test_obj.py +++ b/test/unit/proxy/controllers/test_obj.py @@ -535,6 +535,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' @@ -1237,6 +1253,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='')