WIP: Introduce experimental JSON logging

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

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

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),
+            },
+        )

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:
     """

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)