def fn(*_, **__):
thread_data[
'first_get'] = PySOALogContextFilter.get_logging_request_context(
)
thread_data[
'first_action'] = PySOALogContextFilter.get_logging_action_name(
)
PySOALogContextFilter.set_logging_request_context(foo='bar',
**{'baz': 'qux'})
PySOALogContextFilter.set_logging_action_name('status')
thread_data[
'second_get'] = PySOALogContextFilter.get_logging_request_context(
)
thread_data[
'second_action'] = PySOALogContextFilter.get_logging_action_name(
)
if thread_data.get('do_clear'):
PySOALogContextFilter.clear_logging_request_context()
PySOALogContextFilter.clear_logging_action_name()
thread_data[
'third_get'] = PySOALogContextFilter.get_logging_request_context(
)
thread_data[
'third_action'] = PySOALogContextFilter.get_logging_action_name(
)
def test_filter(self):
record = mock.MagicMock()
log_filter = PySOALogContextFilter()
self.assertTrue(log_filter.filter(record))
self.assertEqual('--', record.correlation_id)
self.assertEqual('--', record.request_id)
self.assertEqual('unknown', record.service_name)
PySOALogContextFilter.set_service_name('foo_qux')
PySOALogContextFilter.set_logging_request_context(filter='mine', **{'logger': 'yours'})
self.assertEqual({'filter': 'mine', 'logger': 'yours'}, PySOALogContextFilter.get_logging_request_context())
record.reset_mock()
self.assertTrue(log_filter.filter(record))
self.assertEqual('--', record.correlation_id)
self.assertEqual('--', record.request_id)
self.assertEqual('foo_qux', record.service_name)
PySOALogContextFilter.set_logging_request_context(request_id=4321, **{'correlation_id': 'abc1234'})
self.assertEqual(
{'request_id': 4321, 'correlation_id': 'abc1234'},
PySOALogContextFilter.get_logging_request_context()
)
record.reset_mock()
self.assertTrue(log_filter.filter(record))
self.assertEqual('abc1234', record.correlation_id)
self.assertEqual(4321, record.request_id)
self.assertEqual('foo_qux', record.service_name)
PySOALogContextFilter.clear_logging_request_context()
self.assertEqual({'filter': 'mine', 'logger': 'yours'}, PySOALogContextFilter.get_logging_request_context())
record.reset_mock()
self.assertTrue(log_filter.filter(record))
self.assertEqual('--', record.correlation_id)
self.assertEqual('--', record.request_id)
self.assertEqual('foo_qux', record.service_name)
PySOALogContextFilter.clear_logging_request_context()
self.assertIsNone(PySOALogContextFilter.get_logging_request_context())
record.reset_mock()
self.assertTrue(log_filter.filter(record))
self.assertEqual('--', record.correlation_id)
self.assertEqual('--', record.request_id)
self.assertEqual('foo_qux', record.service_name)
def test_threading(self):
thread_data = {}
def fn(*_, **__):
thread_data['first_get'] = PySOALogContextFilter.get_logging_request_context()
PySOALogContextFilter.set_logging_request_context(foo='bar', **{'baz': 'qux'})
thread_data['second_get'] = PySOALogContextFilter.get_logging_request_context()
if thread_data.get('do_clear'):
PySOALogContextFilter.clear_logging_request_context()
thread_data['third_get'] = PySOALogContextFilter.get_logging_request_context()
self.assertIsNone(PySOALogContextFilter.get_logging_request_context())
PySOALogContextFilter.set_logging_request_context(request_id=1234, **{'correlation_id': 'abc'})
self.assertEqual(
{'request_id': 1234, 'correlation_id': 'abc'},
PySOALogContextFilter.get_logging_request_context()
)
thread = threading.Thread(target=fn)
thread.start()
thread.join()
self.assertEqual(
{'request_id': 1234, 'correlation_id': 'abc'},
PySOALogContextFilter.get_logging_request_context()
)
self.assertIsNone(thread_data['first_get'])
self.assertEqual({'foo': 'bar', 'baz': 'qux'}, thread_data['second_get'])
self.assertEqual({'foo': 'bar', 'baz': 'qux'}, thread_data['third_get'])
thread_data['do_clear'] = True
thread = threading.Thread(target=fn)
thread.start()
thread.join()
self.assertEqual(
{'request_id': 1234, 'correlation_id': 'abc'},
PySOALogContextFilter.get_logging_request_context()
)
self.assertIsNone(thread_data['first_get'])
self.assertEqual({'foo': 'bar', 'baz': 'qux'}, thread_data['second_get'])
self.assertIsNone(thread_data['third_get'])
def handle_next_request(self):
"""
Retrieves the next request from the transport, or returns if it times out (no request has been made), and then
processes that request, sends its response, and returns when done.
"""
if not self._idle_timer:
# This method may be called multiple times before receiving a request, so we only create and start a timer
# if it's the first call or if the idle timer was stopped on the last call.
self._idle_timer = self.metrics.timer('server.idle_time', resolution=TimerResolution.MICROSECONDS)
self._idle_timer.start()
# Get the next JobRequest
try:
request_id, meta, job_request = self.transport.receive_request_message()
except MessageReceiveTimeout:
# no new message, nothing to do
self.perform_idle_actions()
return
# We are no longer idle, so stop the timer and reset for the next idle period
self._idle_timer.stop()
self._idle_timer = None
PySOALogContextFilter.set_logging_request_context(request_id=request_id, **job_request['context'])
request_for_logging = self.logging_dict_wrapper_class(job_request)
self.job_logger.log(self.request_log_success_level, 'Job request: %s', request_for_logging)
try:
self.perform_pre_request_actions()
# Process and run the Job
job_response = self.process_job(job_request)
# Prepare the JobResponse for sending by converting it to a message dict
try:
response_message = attr.asdict(job_response, dict_factory=UnicodeKeysDict)
except Exception as e:
self.metrics.counter('server.error.response_conversion_failure').increment()
job_response = self.handle_job_exception(e, variables={'job_response': job_response})
response_message = attr.asdict(job_response, dict_factory=UnicodeKeysDict)
response_for_logging = self.logging_dict_wrapper_class(response_message)
# Send the response message
try:
if not job_request['control'].get('suppress_response', False):
self.transport.send_response_message(request_id, meta, response_message)
except MessageTooLarge as e:
self.metrics.counter('server.error.response_too_large').increment()
job_response = self.handle_job_error_code(
ERROR_CODE_RESPONSE_TOO_LARGE,
'Could not send the response because it was too large',
request_for_logging,
response_for_logging,
extra={'serialized_length_in_bytes': e.message_size_in_bytes},
)
self.transport.send_response_message(
request_id,
meta,
attr.asdict(job_response, dict_factory=UnicodeKeysDict),
)
except InvalidField:
self.metrics.counter('server.error.response_not_serializable').increment()
job_response = self.handle_job_error_code(
ERROR_CODE_RESPONSE_NOT_SERIALIZABLE,
'Could not send the response because it failed to serialize',
request_for_logging,
response_for_logging,
)
self.transport.send_response_message(
request_id,
meta,
attr.asdict(job_response, dict_factory=UnicodeKeysDict),
)
finally:
if job_response.errors or any(a.errors for a in job_response.actions):
if (
self.request_log_error_level > self.request_log_success_level and
self.job_logger.getEffectiveLevel() > self.request_log_success_level
):
# When we originally logged the request, it may have been hidden because the effective logging
# level threshold was greater than the level at which we logged the request. So re-log the
# request at the error level, if set higher.
self.job_logger.log(self.request_log_error_level, 'Job request: %s', request_for_logging)
self.job_logger.log(self.request_log_error_level, 'Job response: %s', response_for_logging)
else:
self.job_logger.log(self.request_log_success_level, 'Job response: %s', response_for_logging)
finally:
PySOALogContextFilter.clear_logging_request_context()
self.perform_post_request_actions()