def handle_message(self, message, bound_handlers) -> MessageHandlingResult:
"""
Handle a message.
"""
with self.opaque.initialize(self.sqs_message_context, message):
handler = None
with elapsed_time(self.opaque):
try:
self.validate_message(message)
handler = self.find_handler(message, bound_handlers)
instance = MessageHandlingResult.invoke(
handler=self.wrap_handler(handler),
message=message,
)
except Exception as error:
instance = MessageHandlingResult.from_error(
message=message,
error=error,
)
instance.elapsed_time = self.opaque["elapsed_time"]
instance.log(
logger=self.choose_logger(handler),
opaque=self.opaque,
)
instance.resolve(message)
return instance
def _audit_request(options, func, request_context, *args,
**kwargs): # noqa: C901
"""
Run a request function under audit.
"""
logger = getLogger("audit")
request_info = RequestInfo(options, func, request_context)
response = None
request_info.capture_request()
try:
# process the request
with elapsed_time(request_info.timing):
response = func(*args, **kwargs)
except Exception as error:
request_info.capture_error(error)
raise
else:
request_info.capture_response(response)
return response
finally:
if not should_skip_logging(func):
request_info.log(logger)
def handle_message(self, message, bound_handlers):
"""
Handle a single message.
"""
message_id = message.message_id
media_type = message.media_type
content = message.content
if content is None:
self.logger.debug("Skipping message with unparsed type: {}".format(media_type))
return False
with self.opaque.initialize(self.sqs_message_context, content, message_id=message_id):
try:
handler = self.sqs_message_handler_registry.find(media_type, bound_handlers)
except KeyError:
# no handlers
self.logger.debug("Skipping message with no registered handler: {}".format(media_type))
return False
extra = self.sqs_message_context(content)
extra.update(dict(
handler=titleize(handler.__class__.__name__),
uri=content.get("uri"),
))
with elapsed_time(extra):
result = self.invoke_handler(handler, media_type, content)
self.logger.info(
"Handled {handler}",
extra=extra
)
return result
def handle_message(self, message, bound_handlers) -> MessageHandlingResult:
"""
Handle a message.
"""
with self.opaque.initialize(self.sqs_message_context, message):
handler = None
with elapsed_time(self.opaque):
try:
self.validate_message(message)
handler = self.find_handler(message, bound_handlers)
instance = MessageHandlingResult.invoke(
handler=self.wrap_handler(handler),
message=message,
)
except Exception as error:
instance = MessageHandlingResult.from_error(
message=message,
error=error,
)
instance.elapsed_time = self.opaque["elapsed_time"]
instance.log(
logger=self.choose_logger(handler),
opaque=self.opaque,
)
instance.resolve(message)
return instance
def publish_message(self, pubsub_message: PubsubMessage):
extra = dict(media_type=pubsub_message.media_type,
**pubsub_message.opaque_data)
self.logger.debug("Publishing message with media type {media_type}",
extra=extra)
publish_result = "SUCCESS"
publish_exception = None
with elapsed_time(extra):
try:
result = self.sns_client.publish(
TopicArn=pubsub_message.topic_arn,
Message=pubsub_message.message,
MessageAttributes=pubsub_message.message_attributes,
)
except Exception as e:
publish_exception = e
publish_result = "FAILURE"
self.pubsub_producer_metrics(publish_result=publish_result, **extra)
if publish_exception:
raise Exception(
f"Could not publish message, SNS producer error: {publish_exception}"
)
self.logger.debug("Published message with media type {media_type}",
extra=extra)
# This is another layer of protection for the message send
# If result is not defined, it will exit with an error here
return result["MessageId"]
def publish_message(self, media_type, message, topic_arn, opaque_data):
extra = dict(media_type=media_type, **opaque_data)
self.logger.debug("Publishing message with media type {media_type}",
extra=extra)
with elapsed_time(extra):
result = self.sns_client.publish(
TopicArn=topic_arn,
Message=message,
)
self.logger.info("Published message with media type {media_type}",
extra=extra)
return result["MessageId"]
def publish_message(self, media_type, message, topic_arn, opaque_data):
extra = dict(
media_type=media_type,
**opaque_data
)
self.logger.debug("Publishing message with media type {media_type}", extra=extra)
with elapsed_time(extra):
result = self.sns_client.publish(
TopicArn=topic_arn,
Message=message,
)
self.logger.info("Published message with media type {media_type}", extra=extra)
return result["MessageId"]
async def audit_request(graph, options: AuditOptions, request: Request,
call_next):
"""
Audit request
"""
logger = getLogger(AUDIT_LOGGER_NAME)
request_context = graph.request_context(request)
request_info = RequestInfo(options, request, request_context,
graph.metadata)
logging_info: LoggingInfo = graph.logging_data_map.get_entry(
request.url.path, request.method)
if logging_info.is_empty():
# if logging info is empty then we don't produce any logs and return early
return await call_next(request)
request_info.set_operation_and_func_name(logging_info)
with elapsed_time(request_info.timing):
response = await call_next(request)
request_error = getattr(request.state, "error", None)
if request_error is None:
await request_info.capture_response(response)
else:
request_info.capture_error(request_error)
if not should_skip_logging(request):
if request_info.status_code == 500:
# something actually went wrong; investigate
logger.error(request_info.to_dict())
else:
# usually log at INFO; a raised exception can be an error or
# expected behavior (e.g. 404)
if not request_info.options.log_as_debug:
logger.info(request_info.to_dict())
else:
logger.debug(request_info.to_dict())
# Setting request state for future middleware functions
request.state.request_info = request_info
return response
def handle_message(self, message, bound_handlers) -> MessageHandlingResult:
"""
Handle a message.
"""
with self.opaque.initialize(self.sqs_message_context, message):
handler = None
start_handle_time = time()
with elapsed_time(self.opaque):
try:
self.validate_message(message)
handler = self.find_handler(message, bound_handlers)
instance = MessageHandlingResult.invoke(
handler=self.wrap_handler(handler),
message=message,
)
except Exception as error:
instance = MessageHandlingResult.from_error(
message=message,
error=error,
)
instance.elapsed_time = self.opaque["elapsed_time"]
published_time = self.opaque.get(PUBLISHED_KEY)
if published_time:
instance.handle_start_time = start_handle_time - float(
published_time)
instance.log(
logger=self.choose_logger(handler),
opaque=self.opaque,
)
instance.error_reporting(
sentry_config=self.sentry_config,
opaque=self.opaque,
)
instance.resolve(message)
return instance
def publish_message(self, pubsub_message: PubsubMessage):
extra = dict(media_type=pubsub_message.media_type,
**pubsub_message.opaque_data)
self.logger.debug("Publishing message with media type {media_type}",
extra=extra)
publish_result = "SUCCESS"
publish_exception = None
with trace_outgoing_message(
pubsub_message.topic_arn) as tracer, elapsed_time(extra):
try:
add_trace_to_message(tracer, pubsub_message)
result = self.sns_client.publish(
TopicArn=pubsub_message.topic_arn,
Message=pubsub_message.message,
MessageAttributes=pubsub_message.message_attributes,
)
tracer.set_vendor_message_id(result["MessageId"])
request_id = pubsub_message.opaque_data.get("X-Request-Id")
if request_id:
tracer.set_correlation_id(request_id)
except Exception as e:
publish_exception = e
publish_result = "FAILURE"
self.pubsub_producer_metrics(publish_result=publish_result, **extra)
if publish_exception:
raise Exception(
f"Could not publish message, SNS producer error: {publish_exception}"
) from publish_exception
self.logger.debug("Published message with media type {media_type}",
extra=extra)
# This is another layer of protection for the message send
# If result is not defined, it will exit with an error here
return result["MessageId"]
def test_elapsed_time():
target = dict()
with elapsed_time(target):
sleep(0.1)
assert_that(target["elapsed_time"], is_(close_to(0.1, 0.01)))
def test_elapsed_time():
target = dict()
with elapsed_time(target):
sleep(0.1)
assert_that(target["elapsed_time"], is_(close_to(0.1, 0.01)))
def _audit_request(options, func, request_context, *args,
**kwargs): # noqa: C901
"""
Run a request function under audit.
"""
logger = getLogger("audit")
response = None
# always include these fields
audit_dict = dict(
operation=request.endpoint,
func=func.__name__,
method=request.method,
)
# include request body on debug (if any)
if all((
current_app.debug,
options.include_request_body,
request.get_json(force=True, silent=True),
)):
request_body = request.get_json(force=True)
else:
request_body = None
response_body = None
# include headers (conditionally)
if request_context is not None:
audit_dict.update(request_context())
# process the request
try:
with elapsed_time(audit_dict):
response = func(*args, **kwargs)
except Exception as error:
status_code = extract_status_code(error)
success = 0 < status_code < 400
audit_dict.update(
success=success,
message=extract_error_message(error)[:2048],
context=extract_context(error),
stack_trace=None if success else format_exc(limit=10),
status_code=status_code,
)
raise
else:
body, status_code = parse_response(response)
audit_dict.update(
success=True,
status_code=status_code,
)
# include response body on debug (if any)
if all((
current_app.debug,
options.include_response_body,
body,
)):
try:
response_body = loads(body)
except (TypeError, ValueError):
# not json
audit_dict["response_body"] = body
return response
finally:
# determine whether to show/hide body based on the g values set during func
if not g.get("hide_body"):
if request_body:
for field in g.get("hide_request_fields", []):
try:
del request_body[field]
except KeyError:
pass
audit_dict["request_body"] = request_body
if response_body:
for field in g.get("hide_response_fields", []):
try:
del response_body[field]
except KeyError:
pass
audit_dict["response_body"] = response_body
# always log at INFO; a raised exception can be an error or expected behavior (e.g. 404)
if not should_skip_logging(func):
logger.info(audit_dict)