From d6394a2a27a6e793709ac79535e362a18bce249c Mon Sep 17 00:00:00 2001 From: Elvin Tubillara Date: Thu, 27 Aug 2015 10:43:52 -0500 Subject: [PATCH] Add Request ID to worker-side logs in barbican. This can help correlate errors in logs to an incoming request The request ID is additionally added to the RPC task args that is put into the queue by the server. The client worker then includes the request ID in the logs when it performs the task. Change-Id: Ic359228cd7877022530be21c7d00996d5723a8e0 Closes-bug: #1459800 --- barbican/api/controllers/orders.py | 14 ++++++++++--- barbican/queue/client.py | 18 ++++++++++------- barbican/queue/server.py | 31 +++++++++++++++++------------ barbican/tests/queue/test_client.py | 20 +++++++++++++------ barbican/tests/queue/test_server.py | 23 ++++++++++++--------- barbican/tests/utils.py | 1 + 6 files changed, 69 insertions(+), 38 deletions(-) diff --git a/barbican/api/controllers/orders.py b/barbican/api/controllers/orders.py index a90620831..c0845954b 100644 --- a/barbican/api/controllers/orders.py +++ b/barbican/api/controllers/orders.py @@ -91,6 +91,11 @@ class OrderController(controllers.ACLMixin): project = res.get_or_create_project(external_project_id) order_type = body.get('type') + request_id = None + ctxt = controllers._get_barbican_context(pecan.request) + if ctxt and ctxt.request_id: + request_id = ctxt.request_id + if self.order.type != order_type: order_cannot_modify_order_type() @@ -107,7 +112,8 @@ class OrderController(controllers.ACLMixin): # entity. self.queue.update_order(order_id=self.order.id, project_id=external_project_id, - updated_meta=updated_meta) + updated_meta=updated_meta, + request_id=request_id) @index.when(method='DELETE') @utils.allow_all_content_types @@ -190,7 +196,6 @@ class OrdersController(controllers.ACLMixin): @controllers.enforce_rbac('orders:post') @controllers.enforce_content_types(['application/json']) def on_post(self, external_project_id, **kwargs): - project = res.get_or_create_project(external_project_id) body = api.load_body(pecan.request, @@ -218,9 +223,11 @@ class OrdersController(controllers.ACLMixin): new_order.type = order_type new_order.project_id = project.id + request_id = None ctxt = controllers._get_barbican_context(pecan.request) if ctxt: new_order.creator_id = ctxt.user + request_id = ctxt.request_id self.order_repo.create_from(new_order) @@ -231,7 +238,8 @@ class OrdersController(controllers.ACLMixin): repo.commit() self.queue.process_type_order(order_id=order_id, - project_id=external_project_id) + project_id=external_project_id, + request_id=request_id) url = hrefs.convert_order_to_href(order_id) diff --git a/barbican/queue/client.py b/barbican/queue/client.py index 0d04e43e2..f28ae60a2 100644 --- a/barbican/queue/client.py +++ b/barbican/queue/client.py @@ -37,25 +37,29 @@ class TaskClient(object): # standalone single-node mode for Barbican. self._client = queue.get_client() or _DirectTaskInvokerClient() - def process_type_order(self, order_id, project_id): + def process_type_order(self, order_id, project_id, request_id): """Process TypeOrder.""" - self._cast('process_type_order', order_id=order_id, - project_id=project_id) + self._cast('process_type_order', + order_id=order_id, + project_id=project_id, + request_id=request_id) - def update_order(self, order_id, project_id, updated_meta): + def update_order(self, order_id, project_id, updated_meta, request_id): """Update Order.""" self._cast('update_order', order_id=order_id, project_id=project_id, - updated_meta=updated_meta) + updated_meta=updated_meta, + request_id=request_id) - def check_certificate_status(self, order_id, project_id): + def check_certificate_status(self, order_id, project_id, request_id): """Check the status of a certificate order.""" self._cast('check_certificate_status', order_id=order_id, - project_id=project_id) + project_id=project_id, + request_id=request_id) def _cast(self, name, **kwargs): """Asynchronous call handler. Barbican probably only needs casts. diff --git a/barbican/queue/server.py b/barbican/queue/server.py index 583a00b7f..bef042a39 100644 --- a/barbican/queue/server.py +++ b/barbican/queue/server.py @@ -213,37 +213,42 @@ class Tasks(object): @monitored @transactional @retryable_order - def process_type_order(self, context, order_id, project_id): + def process_type_order(self, context, order_id, project_id, request_id): """Process TypeOrder.""" - LOG.info( - u._LI("Processing type order: order ID is '%s'"), - order_id + message = u._LI( + "Processing type order: " + "order ID is '%(order)s' and request ID is '%(request)s'" ) + LOG.info(message, {'order': order_id, 'request': request_id}) return resources.BeginTypeOrder().process_and_suppress_exceptions( order_id, project_id) @monitored @transactional @retryable_order - def update_order(self, context, order_id, project_id, updated_meta): + def update_order(self, context, order_id, project_id, + updated_meta, request_id): """Update Order.""" - LOG.info( - u._LI("Processing update order: order ID is '%s'"), - order_id + message = u._LI( + "Processing update order: " + "order ID is '%(order)s' and request ID is '%(request)s'" ) + LOG.info(message, {'order': order_id, 'request': request_id}) return resources.UpdateOrder().process_and_suppress_exceptions( order_id, project_id, updated_meta) @monitored @transactional @retryable_order - def check_certificate_status(self, context, order_id, project_id): + def check_certificate_status(self, context, order_id, + project_id, request_id): """Check the status of a certificate order.""" - LOG.info( - u._LI("Processing check certificate status on order: order ID is " - "'%s'"), - order_id + message = u._LI( + "Processing check certificate status on order: " + "order ID is '%(order)s' and request ID is '%(request)s'" ) + + LOG.info(message, {'order': order_id, 'request': request_id}) check_cert_order = resources.CheckCertificateStatusOrder() return check_cert_order.process_and_suppress_exceptions( order_id, project_id) diff --git a/barbican/tests/queue/test_client.py b/barbican/tests/queue/test_client.py index e3483b4f6..ffab6c44b 100644 --- a/barbican/tests/queue/test_client.py +++ b/barbican/tests/queue/test_client.py @@ -45,27 +45,35 @@ class WhenUsingAsyncTaskClient(utils.BaseTestCase): def test_should_process_type_order(self): self.client.process_type_order(order_id=self.order_id, - project_id=self.external_project_id) + project_id=self.external_project_id, + request_id=self.request_id) self.mock_client.cast.assert_called_with( {}, 'process_type_order', order_id=self.order_id, - project_id=self.external_project_id) + project_id=self.external_project_id, + request_id=self.request_id) def test_should_update_order(self): updated_meta = {} self.client.update_order(order_id=self.order_id, project_id=self.external_project_id, - updated_meta=updated_meta) + updated_meta=updated_meta, + request_id=self.request_id) self.mock_client.cast.assert_called_with( {}, 'update_order', order_id=self.order_id, - project_id=self.external_project_id, updated_meta=updated_meta) + project_id=self.external_project_id, + updated_meta=updated_meta, + request_id=self.request_id) def test_should_check_certificate_order(self): self.client.check_certificate_status( order_id=self.order_id, - project_id=self.external_project_id) + project_id=self.external_project_id, + request_id=self.request_id) self.mock_client.cast.assert_called_with( {}, 'check_certificate_status', - order_id=self.order_id, project_id=self.external_project_id) + order_id=self.order_id, + project_id=self.external_project_id, + request_id=self.request_id) class WhenCreatingDirectTaskClient(utils.BaseTestCase): diff --git a/barbican/tests/queue/test_server.py b/barbican/tests/queue/test_server.py index 502aac1cd..9d360c110 100644 --- a/barbican/tests/queue/test_server.py +++ b/barbican/tests/queue/test_server.py @@ -294,13 +294,14 @@ class WhenCallingTasksMethod(utils.BaseTestCase): method.return_value = 'result' self.tasks.process_type_order( - None, self.order_id, self.external_project_id) + None, self.order_id, self.external_project_id, self.request_id) mock_process = mock_begin_order.return_value mock_process.process_and_suppress_exceptions.assert_called_with( self.order_id, self.external_project_id) mock_schedule.assert_called_with( - mock.ANY, 'result', None, 'order1234', 'keystone1234') + mock.ANY, 'result', None, 'order1234', + 'keystone1234', 'request1234') @mock.patch('barbican.queue.server.schedule_order_retry_tasks') @mock.patch('barbican.tasks.resources.UpdateOrder') @@ -311,7 +312,8 @@ class WhenCallingTasksMethod(utils.BaseTestCase): updated_meta = {'foo': 1} self.tasks.update_order( - None, self.order_id, self.external_project_id, updated_meta) + None, self.order_id, self.external_project_id, + updated_meta, self.request_id) mock_process = mock_update_order.return_value mock_process.process_and_suppress_exceptions.assert_called_with( @@ -319,7 +321,7 @@ class WhenCallingTasksMethod(utils.BaseTestCase): ) mock_schedule.assert_called_with( mock.ANY, 'result', None, - 'order1234', 'keystone1234', updated_meta) + 'order1234', 'keystone1234', updated_meta, 'request1234') @mock.patch('barbican.queue.server.schedule_order_retry_tasks') @mock.patch('barbican.tasks.resources.CheckCertificateStatusOrder') @@ -329,14 +331,15 @@ class WhenCallingTasksMethod(utils.BaseTestCase): method.return_value = 'result' self.tasks.check_certificate_status( - None, self.order_id, self.external_project_id) + None, self.order_id, self.external_project_id, self.request_id) mock_process = mock_check_cert.return_value mock_process.process_and_suppress_exceptions.assert_called_with( self.order_id, self.external_project_id ) mock_schedule.assert_called_with( - mock.ANY, 'result', None, 'order1234', 'keystone1234') + mock.ANY, 'result', None, 'order1234', + 'keystone1234', 'request1234') @mock.patch('barbican.tasks.resources.BeginTypeOrder') def test_process_order_catch_exception(self, mock_begin_order): @@ -344,7 +347,8 @@ class WhenCallingTasksMethod(utils.BaseTestCase): mock_begin_order.return_value._process.side_effect = Exception() self.tasks.process_type_order(None, self.order_id, - self.external_project_id) + self.external_project_id, + self.request_id) class WhenUsingTaskServer(database_utils.RepositoryTestCase): @@ -390,6 +394,7 @@ class WhenUsingTaskServer(database_utils.RepositoryTestCase): external_id=self.external_id) self.order = database_utils.create_order( project=project) + self.request_id = 'request1234' def tearDown(self): super(WhenUsingTaskServer, self).tearDown() @@ -419,7 +424,7 @@ class WhenUsingTaskServer(database_utils.RepositoryTestCase): # the session when it is done. Hence we must re-retrieve the order for # verification afterwards. self.server.process_type_order( - None, self.order.id, self.external_id) + None, self.order.id, self.external_id, self.request_id) order_repo = repositories.get_order_repository() order_result = order_repo.get(order_id, self.external_id) @@ -442,7 +447,7 @@ class WhenUsingTaskServer(database_utils.RepositoryTestCase): # the session when it is done. Hence we must re-retrieve the order for # verification afterwards. self.server.update_order( - None, self.order.id, self.external_id, None) + None, self.order.id, self.external_id, None, self.request_id) order_repo = repositories.get_order_repository() order_result = order_repo.get(order_id, self.external_id) diff --git a/barbican/tests/utils.py b/barbican/tests/utils.py index ba3d3ecc9..dcecb1d69 100644 --- a/barbican/tests/utils.py +++ b/barbican/tests/utils.py @@ -77,6 +77,7 @@ class BaseTestCase(oslotest.BaseTestCase): super(BaseTestCase, self).setUp() self.order_id = 'order1234' self.external_project_id = 'keystone1234' + self.request_id = 'request1234' def tearDown(self): super(BaseTestCase, self).tearDown()