openstack/barbican
Code Issues Proposed changes

Add Request ID to worker-side logs in barbican.

Browse Source 
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
This commit is contained in:
Elvin Tubillara 2015-08-27 10:43:52 -05:00
parent 66acc60f71
commit d6394a2a27
6 changed files with 69 additions and 38 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

14
barbican/api/controllers/orders.py
View File

@ -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)

18
barbican/queue/client.py
View File

@ -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.

31
barbican/queue/server.py
View File

@ -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)

20
barbican/tests/queue/test_client.py
View File

@ -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):

23
barbican/tests/queue/test_server.py
View File

@ -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)

1
barbican/tests/utils.py
View File

@ -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()