From 2270b1adddd99eaf844be9288f464374a5104045 Mon Sep 17 00:00:00 2001 From: Dominik Schubert Date: Tue, 14 May 2024 14:34:25 +0200 Subject: [PATCH 1/3] stream JSON logs into a file --- localstack/aws/app.py | 2 + localstack/aws/handlers/logging.py | 22 +++++++--- localstack/logging/setup.py | 51 +++++++++++++++++++++++ localstack/services/lambda_/provider.py | 2 + tests/aws/services/lambda_/test_lambda.py | 1 + 5 files changed, 73 insertions(+), 5 deletions(-) diff --git a/localstack/aws/app.py b/localstack/aws/app.py index d6f67e3d27875..f288a04d90002 100644 --- a/localstack/aws/app.py +++ b/localstack/aws/app.py @@ -1,3 +1,4 @@ + from localstack import config from localstack.aws import handlers from localstack.aws.api import RequestContext @@ -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/logging.py b/localstack/aws/handlers/logging.py index 2113b67fa5176..dd808bd859b88 100644 --- a/localstack/aws/handlers/logging.py +++ b/localstack/aws/handlers/logging.py @@ -72,11 +72,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 +96,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 +122,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 +151,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), diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index 41f538ce59897..3be8e78e8125a 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -1,8 +1,10 @@ +import json import logging import sys import warnings from localstack import config, constants +from localstack_snapshot.util.encoding import CustomJsonEncoder from .format import AddFormattedAttributes, DefaultFormatter @@ -86,6 +88,32 @@ def create_default_handler(log_level: int): log_handler.addFilter(AddFormattedAttributes()) 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: """ @@ -109,6 +137,29 @@ def setup_logging(log_level=logging.INFO) -> None: for logger, level in default_log_levels.items(): logging.getLogger(logger).setLevel(level) + 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) + + # loki_handler = LokiHandler() + # loki_handler.setLevel(logging.DEBUG) + # logging.root.addHandler(loki_handler) + + # silence noisy libs by default + logging.getLogger("werkzeug").setLevel(logging.CRITICAL) + logging.getLogger("stevedore").setLevel(logging.CRITICAL) + logging.getLogger("botocore").setLevel(logging.CRITICAL) + # aws_logger = logging.getLogger("localstack.request.aws") + # http_logger = logging.getLogger("localstack.request.http") + # logging.getLogger("localstack.request.http").setLevel(logging.DEBUG) + # logging.getLogger("localstack.request.http").addHandler(file_handler) + + # logging.getLogger("localstack.request.aws").addHandler(file_handler) + # logging.getLogger("localstack.request.aws").addHandler(loki_handler) + def setup_hypercorn_logger(hypercorn_config) -> None: """ diff --git a/localstack/services/lambda_/provider.py b/localstack/services/lambda_/provider.py index 6cc56acde0f56..0e45423a869e5 100644 --- a/localstack/services/lambda_/provider.py +++ b/localstack/services/lambda_/provider.py @@ -719,6 +719,7 @@ def create_function( context: RequestContext, request: CreateFunctionRequest, ) -> FunctionConfiguration: + LOG.warning("Function being created", extra={"function_name": request['FunctionName'], "customthing": {"names": "joeldominik"}}) zip_file = request.get("Code", {}).get("ZipFile") if zip_file and len(zip_file) > config.LAMBDA_LIMITS_CODE_SIZE_ZIPPED: raise RequestEntityTooLargeException( @@ -765,6 +766,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) diff --git a/tests/aws/services/lambda_/test_lambda.py b/tests/aws/services/lambda_/test_lambda.py index 668f99032ab53..b05714d3b9a4c 100644 --- a/tests/aws/services/lambda_/test_lambda.py +++ b/tests/aws/services/lambda_/test_lambda.py @@ -441,6 +441,7 @@ def test_runtime_introspection_x86(self, create_lambda_function, snapshot, aws_c timeout=9, Architectures=[Architecture.x86_64], ) + # logging.getLogger("localstack.request.http").debug("?jsds2024") invoke_result = aws_client.lambda_.invoke(FunctionName=func_name) snapshot.match("invoke_runtime_x86_introspection", invoke_result) From 9efd456bc962e7c831500547fe2e3ee751fb154b Mon Sep 17 00:00:00 2001 From: Dominik Schubert Date: Wed, 15 May 2024 09:20:42 +0200 Subject: [PATCH 2/3] add custom raw request logger before parsing and svc loading --- localstack/aws/app.py | 2 +- localstack/aws/handlers/__init__.py | 1 + localstack/aws/handlers/logging.py | 23 ++++++++++++++++++++++- 3 files changed, 24 insertions(+), 2 deletions(-) diff --git a/localstack/aws/app.py b/localstack/aws/app.py index f288a04d90002..5658a80d8b50f 100644 --- a/localstack/aws/app.py +++ b/localstack/aws/app.py @@ -1,4 +1,3 @@ - from localstack import config from localstack.aws import handlers from localstack.aws.api import RequestContext @@ -29,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, 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 dd808bd859b88..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__) @@ -164,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), + }, + ) From f19f45c3467ebb6c041c1a6f5489e68e18914843 Mon Sep 17 00:00:00 2001 From: Dominik Schubert Date: Wed, 15 May 2024 09:46:02 +0200 Subject: [PATCH 3/3] minor cleanup --- localstack/logging/setup.py | 20 ++++++-------------- localstack/services/lambda_/provider.py | 1 - tests/aws/services/lambda_/test_lambda.py | 1 - 3 files changed, 6 insertions(+), 16 deletions(-) diff --git a/localstack/logging/setup.py b/localstack/logging/setup.py index 3be8e78e8125a..49796a181ac83 100644 --- a/localstack/logging/setup.py +++ b/localstack/logging/setup.py @@ -3,9 +3,10 @@ import sys import warnings -from localstack import config, constants from localstack_snapshot.util.encoding import CustomJsonEncoder +from localstack import config, constants + from .format import AddFormattedAttributes, DefaultFormatter # The log levels for modules are evaluated incrementally for logging granularity, @@ -88,6 +89,7 @@ def create_default_handler(log_level: int): log_handler.addFilter(AddFormattedAttributes()) 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 @@ -114,7 +116,6 @@ def format(self, record: logging.LogRecord) -> str: return json.dumps(data, cls=CustomJsonEncoder) - def setup_logging(log_level=logging.INFO) -> None: """ Configures the python logging environment for LocalStack. @@ -137,28 +138,19 @@ 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) - - # loki_handler = LokiHandler() - # loki_handler.setLevel(logging.DEBUG) - # logging.root.addHandler(loki_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) - # aws_logger = logging.getLogger("localstack.request.aws") - # http_logger = logging.getLogger("localstack.request.http") - # logging.getLogger("localstack.request.http").setLevel(logging.DEBUG) - # logging.getLogger("localstack.request.http").addHandler(file_handler) - - # logging.getLogger("localstack.request.aws").addHandler(file_handler) - # logging.getLogger("localstack.request.aws").addHandler(loki_handler) def setup_hypercorn_logger(hypercorn_config) -> None: diff --git a/localstack/services/lambda_/provider.py b/localstack/services/lambda_/provider.py index 0e45423a869e5..8c9700ef1209b 100644 --- a/localstack/services/lambda_/provider.py +++ b/localstack/services/lambda_/provider.py @@ -719,7 +719,6 @@ def create_function( context: RequestContext, request: CreateFunctionRequest, ) -> FunctionConfiguration: - LOG.warning("Function being created", extra={"function_name": request['FunctionName'], "customthing": {"names": "joeldominik"}}) zip_file = request.get("Code", {}).get("ZipFile") if zip_file and len(zip_file) > config.LAMBDA_LIMITS_CODE_SIZE_ZIPPED: raise RequestEntityTooLargeException( diff --git a/tests/aws/services/lambda_/test_lambda.py b/tests/aws/services/lambda_/test_lambda.py index b05714d3b9a4c..668f99032ab53 100644 --- a/tests/aws/services/lambda_/test_lambda.py +++ b/tests/aws/services/lambda_/test_lambda.py @@ -441,7 +441,6 @@ def test_runtime_introspection_x86(self, create_lambda_function, snapshot, aws_c timeout=9, Architectures=[Architecture.x86_64], ) - # logging.getLogger("localstack.request.http").debug("?jsds2024") invoke_result = aws_client.lambda_.invoke(FunctionName=func_name) snapshot.match("invoke_runtime_x86_introspection", invoke_result)