async def _request_execute(app_engine: AppEngine, event_name: str,
context: EventContext, query_args: Dict[str, Any],
payload: Optional[EventPayloadType],
preprocess_hook: PreprocessHook) -> ResponseType:
"""
Executes request using engine event handler
"""
response_hook = PostprocessHook()
result = await app_engine.preprocess(context=context,
query_args=query_args,
payload=payload,
request=preprocess_hook)
if (preprocess_hook.status is None) or (preprocess_hook.status == 200):
result = await app_engine.execute(context=context,
query_args=query_args,
payload=result)
result = await app_engine.postprocess(context=context,
payload=result,
response=response_hook)
else:
response_hook.set_status(preprocess_hook.status)
# body = Json.to_json(result, key=event_name)
response = _response(track_ids=context.track_ids,
key=event_name,
payload=result,
hook=response_hook)
logger.done(context,
extra=combined(_response_info(response), metrics(context)))
return response
async def _process_stream_event(
self, *, stream_event: StreamEvent,
stream_info: ReadStreamDescriptor, stream_name: str, queue: str,
context: EventContext, stats: StreamStats,
log_info: Dict[str,
str]) -> Optional[Union[EventPayload, Exception]]:
"""
Process a single stream event, execute events, ack if not failed, log error if fail
:return: results of executing the event, or Exception if errors during processing
"""
try:
assert self.event_handler
assert self.stream_manager
result = await self._execute_event(context=context,
query_args=None,
payload=stream_event.payload,
queue=stream_event.queue)
await self.stream_manager.ack_read_stream(
stream_name=stream_name,
consumer_group=stream_info.consumer_group,
stream_event=stream_event)
logger.done(context,
extra=combined(
extra(prefix='stream.',
**{
**log_info, 'name': stream_name,
'queue': queue
}), metrics(context),
stream_metrics(context)))
stats.inc()
return result
except CancelledError as e:
extra_info = {**log_info, 'name': stream_name, 'queue': queue}
logger.error(context,
'Cancelled',
extra=extra(prefix='stream.', **extra_info))
logger.failed(context, extra=extra(prefix='stream.', **extra_info))
stats.inc(error=True)
return e
except Exception as e: # pylint: disable=broad-except
extra_info = {**log_info, 'name': stream_name, 'queue': queue}
logger.error(context,
e,
extra=extra(prefix='stream.', **extra_info))
logger.failed(context, extra=extra(prefix='stream.', **extra_info))
stats.inc(error=True)
return e
def test_engine_extra_logger(monkeypatch, mock_app_config): # noqa: F811
logger, extra = _get_engine_extra_logger(monkeypatch, mock_app_config)
context = _event_context(mock_app_config)
logger.info(context,
"Log message",
extra=extra(field1='value1', field2=42))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| INFO | mock_app test mock_event_logging test_host test_pid | Log message " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.warning(context,
"Log message",
extra=extra(field1='value1', field2=42))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| WARNING | mock_app test mock_event_logging test_host test_pid | Log message " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.error(context,
"Log message",
extra=extra(field1='value1', field2=42))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| ERROR | mock_app test mock_event_logging test_host test_pid | Log message " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.debug(context,
"Log message",
extra=extra(field1='value1', field2=42))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| DEBUG | mock_app test mock_event_logging test_host test_pid | Log message " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.start(context, extra=extra(field1='value1', field2=42))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| INFO | mock_app test mock_event_logging test_host test_pid | START " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.done(context,
extra=server_logging.combined(extra(field1='value1',
field2=42)))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| INFO | mock_app test mock_event_logging test_host test_pid | DONE " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.ignored(context,
extra=server_logging.combined(
extra(field1='value1', field2=42)))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| WARNING | mock_app test mock_event_logging test_host test_pid | IGNORED " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"
logger.failed(context,
extra=server_logging.combined(
server_logging.extra_values([],
field1='value1',
field2=42)))
assert MockHandler.formatter.format(MockHandler.record)[24:] \
== "| ERROR | mock_app test mock_event_logging test_host test_pid | FAILED " \
"| extra.field1=value1 | extra.field2=42 " \
"| track.operation_id=test_operation_id " \
"| track.request_id=test_request_id | track.request_ts=2020-01-01T00:00:00Z " \
"| track.session_id=test_session_id | event.app=mock_app.test"