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)