diff --git a/localstack/aws/app.py b/localstack/aws/app.py index d6f67e3d27875..5658a80d8b50f 100644 --- a/localstack/aws/app.py +++ b/localstack/aws/app.py @@ -28,6 +28,7 @@ def __init__(self, service_manager: ServiceManager = None) -> None: # the main request handler chain self.request_handlers.extend( [ + handlers.log_request, handlers.push_request_context, handlers.add_internal_request_params, handlers.handle_runtime_shutdown, @@ -45,6 +46,7 @@ def __init__(self, service_manager: ServiceManager = None) -> None: handlers.add_region_from_header, handlers.add_account_id, handlers.parse_service_request, + # TODO: add logger that initializes a request "trace" metric_collector.record_parsed_request, handlers.serve_custom_service_request_handlers, load_service, # once we have the service request we can make sure we load the service diff --git a/localstack/aws/handlers/__init__.py b/localstack/aws/handlers/__init__.py index 36fe11b8a15e5..778d7f5497946 100644 --- a/localstack/aws/handlers/__init__.py +++ b/localstack/aws/handlers/__init__.py @@ -45,3 +45,4 @@ set_close_connection_header = legacy.set_close_connection_header push_request_context = legacy.push_request_context pop_request_context = legacy.pop_request_context +log_request = logging.RequestLogger() diff --git a/localstack/aws/handlers/logging.py b/localstack/aws/handlers/logging.py index 2113b67fa5176..ea524f96c8e53 100644 --- a/localstack/aws/handlers/logging.py +++ b/localstack/aws/handlers/logging.py @@ -9,7 +9,6 @@ from localstack.http import Response from localstack.http.request import restore_payload from localstack.logging.format import AwsTraceLoggingFormatter, TraceLoggingFormatter -from localstack.logging.setup import create_default_handler LOG = logging.getLogger(__name__) @@ -72,11 +71,12 @@ def internal_http_logger(self): # make sure loggers are loaded after logging config is loaded def _prepare_logger(self, logger: logging.Logger, formatter: Type): - if logger.isEnabledFor(logging.DEBUG): - logger.propagate = False - handler = create_default_handler(logger.level) - handler.setFormatter(formatter()) - logger.addHandler(handler) + # TODO: uncommenting this will block .http and .aws logs from being propagated + # if logger.isEnabledFor(logging.DEBUG): + # logger.propagate = False + # handler = create_default_handler(logger.level) + # handler.setFormatter(formatter()) + # logger.addHandler(handler) return logger def _log(self, context: RequestContext, response: Response): @@ -95,6 +95,10 @@ def _log(self, context: RequestContext, response: Response): response.status_code, context.service_exception.code, extra={ + "request_id": context.request_id, + "service": context.service.service_name, + "operation": context.operation.name, + "status_code": response.status_code, # context "account_id": context.account_id, "region": context.region, @@ -117,6 +121,10 @@ def _log(self, context: RequestContext, response: Response): context.operation.name, response.status_code, extra={ + "request_id": context.request_id, + "service": context.service.service_name, + "operation": context.operation.name, + "status_code": response.status_code, # context "account_id": context.account_id, "region": context.region, @@ -142,6 +150,9 @@ def _log(self, context: RequestContext, response: Response): context.request.path, response.status_code, extra={ + "request_id": context.request_id or "NOREQUESTID", + "http_method": context.request.method, + "status_code": response.status_code, # request "input_type": "Request", "input": restore_payload(context.request), @@ -152,3 +163,25 @@ def _log(self, context: RequestContext, response: Response): "response_headers": dict(response.headers), }, ) + + +class RequestLogger: + def __call__(self, _: HandlerChain, context: RequestContext, response: Response): + if context.request.path == "/health" or context.request.path == "/_localstack/health": + # special case so the health check doesn't spam the logs + return + + logger = logging.getLogger("localstack.request.raw_http") + logger.info( + "%s %s", + context.request.method, + context.request.path, + extra={ + "request_id": context.request_id or "NOREQUESTID", + "http_method": context.request.method, + # request + "input_type": "Request", + "input": restore_payload(context.request), # TODO: remove? + "request_headers": dict(context.request.headers), + }, + ) diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index 41f538ce59897..49796a181ac83 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -1,7 +1,10 @@ +import json import logging import sys import warnings +from localstack_snapshot.util.encoding import CustomJsonEncoder + from localstack import config, constants from .format import AddFormattedAttributes, DefaultFormatter @@ -87,6 +90,32 @@ def create_default_handler(log_level: int): return log_handler +class JsonFormatter(logging.Formatter): + def format(self, record: logging.LogRecord) -> str: + # TODO: extras are currently flat at root level and not nested + data = {} + skip_kw = ["msg", "message", "args", "exc_info"] + for k, v in record.__dict__.items(): + if k in skip_kw: + continue + if v is not None: + data[k] = v + data["message"] = record.getMessage() + + if record.exc_info: + data["error_type"] = record.exc_info[0].__name__ + data["error_msg"] = str(record.exc_info[1]) + if record.exc_text: + data["exc_text"] = record.exc_text + + # import re + # reg = re.compile(r"./localstack/services/([^/])") + # if "localstack/services/" in record.pathname: + # service = record.pathname.split("") + # data["service"] = + return json.dumps(data, cls=CustomJsonEncoder) + + def setup_logging(log_level=logging.INFO) -> None: """ Configures the python logging environment for LocalStack. @@ -109,6 +138,20 @@ def setup_logging(log_level=logging.INFO) -> None: for logger, level in default_log_levels.items(): logging.getLogger(logger).setLevel(level) + # Configure JSON logs + # TODO: make configurable/opt-in + logging.basicConfig(level=logging.DEBUG) + file_handler = logging.FileHandler("/tmp/localstack.log", mode="w", encoding="utf-8") + + file_handler.setFormatter(JsonFormatter()) + logging.root.addHandler(file_handler) + logging.root.setLevel(logging.DEBUG) # FIXME + + # silence noisy libs by default + logging.getLogger("werkzeug").setLevel(logging.CRITICAL) + logging.getLogger("stevedore").setLevel(logging.CRITICAL) + logging.getLogger("botocore").setLevel(logging.CRITICAL) + def setup_hypercorn_logger(hypercorn_config) -> None: """ diff --git a/localstack/services/lambda_/provider.py b/localstack/services/lambda_/provider.py index 6cc56acde0f56..8c9700ef1209b 100644 --- a/localstack/services/lambda_/provider.py +++ b/localstack/services/lambda_/provider.py @@ -765,6 +765,7 @@ def create_function( f"Value {request.get('Runtime')} at 'runtime' failed to satisfy constraint: Member must satisfy enum value set: {VALID_RUNTIMES} or be a valid ARN", Type="User", ) + request_function_name = request["FunctionName"] # Validate FunctionName: # a) Function name: just function name (max 64 chars)