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