From 29f7403cd4a935f908c652a551f26d6ea043b096 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Sun, 21 Mar 2021 13:05:20 +0100 Subject: [PATCH 1/9] Fixing dead links in README.md --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 2c0e9b0..efb770e 100644 --- a/README.md +++ b/README.md @@ -227,7 +227,7 @@ ResponseAdapter | Helper class help to extract logging-relevant information from FrameworkConfigurator | Class to perform logging configuration for given framework as needed | no AppRequestInstrumentationConfigurator | Class to perform request instrumentation logging configuration | no -Take a look at [**json_logging/base_framework.py**](blob/master/json_logging/framework_base.py), [**json_logging.flask**](tree/master/json_logging/framework/flask) and [**json_logging.sanic**](/tree/master/json_logging/framework/sanic) packages for reference implementations. +Take a look at [**json_logging/base_framework.py**](json_logging/framework_base.py), [**json_logging.flask**](json_logging/framework/flask) and [**json_logging.sanic**](json_logging/framework/sanic) packages for reference implementations. # 6. FAQ & Troubleshooting 1. I configured everything, but no logs are printed out? From 0497f34a3a3d932c58d51dc64d2fcc09f48c9b29 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Sun, 21 Mar 2021 23:49:15 +0100 Subject: [PATCH 2/9] Added a test for get_correlation_id() to flask implementation --- tests/test_flask.py | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/tests/test_flask.py b/tests/test_flask.py index 2c33a17..dfaa43a 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -63,6 +63,10 @@ def log_exception(): logger.exception("Error occurred", exc_info=e) return {} + @app.route("/get-correlation-id") + def get_correlation_id(): + return {'correlation_id': json_logging.get_correlation_id()} + with app.test_client() as test_client: yield test_client, handler @@ -121,6 +125,16 @@ def test_correlation_id_generated(client_and_log_handler): ), "autogenerated UUID doesn't have expected format" +def test_get_correlation_id(client_and_log_handler): + """Test if json_logging.get_correlation_id() finds a given correlation ID""" + api_client, handler = client_and_log_handler + + response = api_client.get("/get-correlation-id", headers={"X-Correlation-Id": "abc-def"}) + + assert response.status_code == 200 + assert response.json["correlation_id"] == "abc-def" + + def test_extra_property(client_and_log_handler): """Test adding an extra property to a log message""" api_client, handler = client_and_log_handler From a1057e33674438ff628531238b163ad50d625878 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Mon, 22 Mar 2021 01:49:14 +0100 Subject: [PATCH 3/9] Added tests for request log, remove all imports of json_logging --- json_logging/util.py | 2 +- tests/helpers/imports.py | 9 +++++++++ tests/test_flask.py | 32 ++++++++++++++++++++++++++++++-- 3 files changed, 40 insertions(+), 3 deletions(-) create mode 100644 tests/helpers/imports.py diff --git a/json_logging/util.py b/json_logging/util.py index 81d9e4f..d11bb6d 100644 --- a/json_logging/util.py +++ b/json_logging/util.py @@ -120,7 +120,7 @@ def __new__(cls, *args, **kw): return cls._instance - def get_correlation_id(self, request=None,within_formatter=False): + def get_correlation_id(self, request=None, within_formatter=False): """ Gets the correlation id from the header of the request. \ It tries to search from json_logging.CORRELATION_ID_HEADERS list, one by one.\n diff --git a/tests/helpers/imports.py b/tests/helpers/imports.py new file mode 100644 index 0000000..a1d6234 --- /dev/null +++ b/tests/helpers/imports.py @@ -0,0 +1,9 @@ +"""Helper functions related to module imports""" +import sys + + +def undo_imports_from_package(package: str): + """Removes all imported modules from the given package from sys.modules""" + for k in sorted(sys.modules.keys(), key=lambda s: len(s), reverse=True): + if k == package or k.startswith(package + '.'): + del sys.modules[k] diff --git a/tests/test_flask.py b/tests/test_flask.py index dfaa43a..9fd16c5 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -10,6 +10,7 @@ from helpers import constants from helpers.handler import FormattedMessageCollectorHandler +from helpers.imports import undo_imports_from_package LOGGER_NAME = "flask-test" @@ -29,7 +30,7 @@ def client_and_log_handler(): # Add json_logging json_logging.init_flask(enable_json=True) - json_logging.init_request_instrument(app) + json_logging.init_request_instrument(app, exclude_url_patterns=["/no-request-instrumentation"]) # Prepare test endpoints @app.route("/log/levels/debug") @@ -67,12 +68,16 @@ def log_exception(): def get_correlation_id(): return {'correlation_id': json_logging.get_correlation_id()} + @app.route('/no-request-instrumentation') + def excluded_from_request_instrumentation(): + return {} + with app.test_client() as test_client: yield test_client, handler # Tear down test environment logger.removeHandler(handler) - del sys.modules["json_logging"] # "de-import" because json_logging maintains global state + undo_imports_from_package("json_logging") # Necessary because of json-logging's global state @pytest.mark.parametrize("level", ["debug", "info", "error"]) @@ -162,3 +167,26 @@ def test_exception_logged_with_stack_trace(client_and_log_handler): assert "Traceback (most recent call last):" in msg["exc_info"], "Not a stack trace" assert "RuntimeError" in msg["exc_info"], "Exception type not logged" assert len(msg["exc_info"].split("\n")) > 2, "Stacktrace doesn't have multiple lines" + + +def test_request_instrumentation(client_and_log_handler): + api_client, _ = client_and_log_handler + request_logger = logging.getLogger("flask-request-logger") + handler = FormattedMessageCollectorHandler() + request_logger.addHandler(handler) + + response = api_client.get("/log/levels/debug") + + assert response.status_code == 200 + assert len(handler.messages) == 1 + +def test_excluded_from_request_instrumentation(client_and_log_handler): + api_client, _ = client_and_log_handler + request_logger = logging.getLogger("flask-request-logger") + handler = FormattedMessageCollectorHandler() + request_logger.addHandler(handler) + + response = api_client.get("/no-request-instrumentation") + + assert response.status_code == 200 + assert len(handler.messages) == 0 From 859e030fd756b1227c199c5949e46753fbba4cd7 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Mon, 22 Mar 2021 02:47:21 +0100 Subject: [PATCH 4/9] FastAPI backend including tests --- example/fastapi_sample_app.py | 55 ++++++ json_logging/__init__.py | 12 ++ json_logging/framework/fastapi/__init__.py | 137 +++++++++++++++ test-requirements.txt | 3 + tests/test_fastapi.py | 194 +++++++++++++++++++++ tests/test_flask.py | 4 +- 6 files changed, 404 insertions(+), 1 deletion(-) create mode 100644 example/fastapi_sample_app.py create mode 100644 json_logging/framework/fastapi/__init__.py create mode 100644 tests/test_fastapi.py diff --git a/example/fastapi_sample_app.py b/example/fastapi_sample_app.py new file mode 100644 index 0000000..0d8c515 --- /dev/null +++ b/example/fastapi_sample_app.py @@ -0,0 +1,55 @@ +import logging + +import fastapi + +import json_logging + +app = fastapi.FastAPI() + +# init the logger as usual +logger = logging.getLogger(__name__) + +@app.get('/') +async def home(): + logger.info("test log statement") + logger.info("test log statement with extra props", extra={'props': {"extra_property": 'extra_value'}}) + correlation_id = json_logging.get_correlation_id() + return "hello world" \ + "\ncorrelation_id : " + correlation_id + + +@app.get('/exception') +def exception(): + try: + raise RuntimeError + except BaseException as e: + logger.error("Error occurred", exc_info=e) + logger.exception("Error occurred", exc_info=e) + return "Error occurred, check log for detail" + + +@app.get('/exclude_from_request_instrumentation') +def exclude_from_request_instrumentation(): + return "this request wont log request instrumentation information" + + +if __name__ == "__main__": + import uvicorn + logging_config = { + 'version': 1, + 'disable_existing_loggers': False, + 'handlers': { + 'default_handler': { + 'class': 'logging.StreamHandler', + 'level': 'DEBUG', + }, + }, + 'loggers': { + '': { + 'handlers': ['default_handler'], + } + } + } + json_logging.init_fastapi(enable_json=True) + json_logging.init_request_instrument(app, exclude_url_patterns=[r'^/exclude_from_request_instrumentation']) + uvicorn.run(app, host='0.0.0.0', port=5000, log_level="debug", log_config=logging_config) diff --git a/json_logging/__init__.py b/json_logging/__init__.py index d92721c..e67914a 100644 --- a/json_logging/__init__.py +++ b/json_logging/__init__.py @@ -395,3 +395,15 @@ def init_quart(custom_formatter=None, enable_json=False): def init_connexion(custom_formatter=None, enable_json=False): __init(framework_name='connexion', custom_formatter=custom_formatter, enable_json=enable_json) + + +# register FastAPI support +import json_logging.framework.fastapi as fastapi_support + +register_framework_support('fastapi', app_configurator=None, + app_request_instrumentation_configurator=fastapi_support.FastAPIAppRequestInstrumentationConfigurator, + request_adapter_class=fastapi_support.FastAPIRequestAdapter, + response_adapter_class=fastapi_support.FastAPIResponseAdapter) + +def init_fastapi(custom_formatter=None, enable_json=False): + __init(framework_name='fastapi', custom_formatter=custom_formatter, enable_json=enable_json) diff --git a/json_logging/framework/fastapi/__init__.py b/json_logging/framework/fastapi/__init__.py new file mode 100644 index 0000000..66ec03b --- /dev/null +++ b/json_logging/framework/fastapi/__init__.py @@ -0,0 +1,137 @@ +# coding=utf-8 +import logging + +from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint +from starlette.requests import Request +from starlette.responses import Response +from starlette.types import ASGIApp + +import json_logging +import json_logging.framework +from json_logging.framework_base import AppRequestInstrumentationConfigurator, RequestAdapter, ResponseAdapter + +from json_logging.util import is_not_match_any_pattern + + +def is_fastapi_present(): + # noinspection PyPep8,PyBroadException + try: + import fastapi + import starlette + return True + except: + return False + + +if is_fastapi_present(): + import fastapi + import starlette.requests + import starlette.responses + + +class JSONLoggingASGIMiddleware(BaseHTTPMiddleware): + def __init__(self, app: ASGIApp, exclude_url_patterns=tuple()) -> None: + super().__init__(app) + self.request_logger = logging.getLogger('fastapi-request-logger') + self.exclude_url_patterns = exclude_url_patterns + logging.getLogger("uvicorn.access").propagate = False + + async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response: + log_request = is_not_match_any_pattern(request.url.path, self.exclude_url_patterns) + + if not log_request: + return await call_next(request) + + request_info = json_logging.RequestInfo(request) + response = await call_next(request) + request_info.update_response_status(response) + self.request_logger.info( + "", extra={"request_info": request_info, "type": "request"} + ) + return response + + +class FastAPIAppRequestInstrumentationConfigurator(AppRequestInstrumentationConfigurator): + def config(self, app, exclude_url_patterns=tuple()): + if not is_fastapi_present(): + raise RuntimeError("fastapi is not available in system runtime") + if not isinstance(app, fastapi.FastAPI): + raise RuntimeError("app is not a valid fastapi.FastAPI instance") + + # Disable standard logging + logging.getLogger('uvicorn.access').disabled = True + + # noinspection PyAttributeOutsideInit + self.request_logger = logging.getLogger('fastapi-request-logger') + + app.add_middleware(JSONLoggingASGIMiddleware, exclude_url_patterns=exclude_url_patterns) + + +class FastAPIRequestAdapter(RequestAdapter): + @staticmethod + def get_request_class_type(): + return starlette.requests.Request + + @staticmethod + def support_global_request_object(): + return False + + @staticmethod + def get_current_request(): + raise NotImplementedError + + def get_remote_user(self, request: starlette.requests.Request): + try: + return request.user + except AssertionError: + return json_logging.EMPTY_VALUE + + def get_http_header(self, request: starlette.requests.Request, header_name, default=None): + try: + if header_name in request.headers: + return request.headers.get(header_name) + except: + pass + return default + + def set_correlation_id(self, request_, value): + request_.state.correlation_id = value + + def get_correlation_id_in_request_context(self, request: starlette.requests.Request): + try: + return request.state.correlation_id + except AttributeError: + return None + + def get_protocol(self, request: starlette.requests.Request): + protocol = str(request.scope.get('type', '')) + http_version = str(request.scope.get('http_version', '')) + if protocol.lower() == 'http' and http_version: + return protocol.upper() + "/" + http_version + return json_logging.EMPTY_VALUE + + def get_path(self, request: starlette.requests.Request): + return request.url.path + + def get_content_length(self, request: starlette.requests.Request): + return request.headers.get('content-length', json_logging.EMPTY_VALUE) + + def get_method(self, request: starlette.requests.Request): + return request.method + + def get_remote_ip(self, request: starlette.requests.Request): + return request.client.host + + def get_remote_port(self, request: starlette.requests.Request): + return request.client.port + + +class FastAPIResponseAdapter(ResponseAdapter): + def get_status_code(self, response: starlette.responses.Response): + return response.status_code + + def get_response_size(self, response: starlette.responses.Response): + return response.headers.get('content-length', json_logging.EMPTY_VALUE) + + def get_content_type(self, response: starlette.responses.Response): + return response.headers.get('content-type', json_logging.EMPTY_VALUE) diff --git a/test-requirements.txt b/test-requirements.txt index 3011d14..7aff89f 100644 --- a/test-requirements.txt +++ b/test-requirements.txt @@ -3,6 +3,9 @@ flask connexion[swagger-ui] quart sanic +fastapi +uvicorn +requests flake8 pytest -e . diff --git a/tests/test_fastapi.py b/tests/test_fastapi.py new file mode 100644 index 0000000..a9431a3 --- /dev/null +++ b/tests/test_fastapi.py @@ -0,0 +1,194 @@ +"""Test suite for the flask backend""" +import json +import logging +import pathlib +import re + +import fastapi +import fastapi.testclient +import pytest +from helpers import constants +from helpers.handler import FormattedMessageCollectorHandler +from helpers.imports import undo_imports_from_package + +LOGGER_NAME = "fastapi-test" + + +@pytest.fixture +def client_and_log_handler(): + import json_logging + + # Init app + app = fastapi.FastAPI() + + # Init std logging + logger = logging.getLogger(LOGGER_NAME) + logger.setLevel(logging.DEBUG) + handler = FormattedMessageCollectorHandler() + logger.addHandler(handler) + + # Add json_logging + json_logging.init_fastapi(enable_json=True) + json_logging.init_request_instrument(app, exclude_url_patterns=["^/no-request-instrumentation"]) + + # Prepare test endpoints + @app.get("/log/levels/debug") + async def log_debug(): + logger.debug("debug message") + return {} + + @app.get("/log/levels/info") + async def log_info(): + logger.info("info message") + return {} + + @app.get("/log/levels/error") + async def log_error(): + logger.error("error message") + return {} + + @app.get("/log/extra_property") + async def extra_property(): + logger.info( + "test log statement with extra props", + extra={"props": {"extra_property": "extra_value"}}, + ) + return {} + + @app.get("/log/exception") + async def log_exception(): + try: + raise RuntimeError() + except BaseException as e: + logger.exception("Error occurred", exc_info=e) + return {} + + @app.get("/get-correlation-id") + async def get_correlation_id(): + return {'correlation_id': json_logging.get_correlation_id()} + + @app.get('/no-request-instrumentation') + async def excluded_from_request_instrumentation(): + return {} + + test_client = fastapi.testclient.TestClient(app) + yield test_client, handler + + # Tear down test environment + logger.removeHandler(handler) + undo_imports_from_package("json_logging") # Necessary because of json-logging's global state + + +@pytest.mark.parametrize("level", ["debug", "info", "error"]) +def test_record_format_per_log_level(client_and_log_handler, level): + """Test if log messages are formatted correctly for all log levels""" + api_client, handler = client_and_log_handler + + response = api_client.get("/log/levels/" + level) + + assert response.status_code == 200 + assert len(handler.messages) == 1 + msg = json.loads(handler.messages[0]) + assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES + assert msg["module"] == __name__ + assert msg["level"] == level.upper() + assert msg["logger"] == LOGGER_NAME + assert msg["type"] == "log" + assert msg["msg"] == level + " message" + assert re.match( + r"^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(\.\d+.*)?$", msg["written_at"] + ), "The field 'written_at' does not contain an iso timestamp" + + +def test_correlation_id_given(client_and_log_handler): + """Test if a given correlation ID is added to the logs""" + api_client, handler = client_and_log_handler + + response = api_client.get("/log/levels/debug", headers={"X-Correlation-Id": "abc-def"}) + + assert response.status_code == 200 + assert len(handler.messages) == 1 + msg = json.loads(handler.messages[0]) + assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES + assert msg["correlation_id"] == "abc-def" + + +def test_correlation_id_generated(client_and_log_handler): + """Test if a missing correlation ID is replaced by an autogenerated UUID""" + api_client, handler = client_and_log_handler + + response = api_client.get("/log/levels/debug") + + assert response.status_code == 200 + assert len(handler.messages) == 1 + msg = json.loads(handler.messages[0]) + assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES + assert re.match( + r"^[0-9a-f]{8}-[0-9a-f]{4}-[0-5][0-9a-f]{3}-[089ab][0-9a-f]{3}-[0-9a-f]{12}$", + msg["correlation_id"], + ), "autogenerated UUID doesn't have expected format" + + +def test_get_correlation_id(client_and_log_handler): + """Test if json_logging.get_correlation_id() finds a given correlation ID""" + api_client, handler = client_and_log_handler + + response = api_client.get("/get-correlation-id", headers={"X-Correlation-Id": "abc-def"}) + + assert response.status_code == 200 + assert response.json()["correlation_id"] == "abc-def" + + +def test_extra_property(client_and_log_handler): + """Test adding an extra property to a log message""" + api_client, handler = client_and_log_handler + + response = api_client.get("/log/extra_property") + + assert response.status_code == 200 + assert len(handler.messages) == 1 + msg = json.loads(handler.messages[0]) + assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"extra_property"}) + assert msg["extra_property"] == "extra_value" + + +def test_exception_logged_with_stack_trace(client_and_log_handler): + """Test if the details of a stack trace are logged""" + api_client, handler = client_and_log_handler + + response = api_client.get("/log/exception") + + assert response.status_code == 200 + assert len(handler.messages) == 1 + msg = json.loads(handler.messages[0]) + assert set(msg.keys()) == constants.STANDARD_MSG_ATTRIBUTES.union({"exc_info", "filename"}) + assert msg["filename"] == pathlib.Path(__file__).name, "File name for exception not logged" + assert "Traceback (most recent call last):" in msg["exc_info"], "Not a stack trace" + assert "RuntimeError" in msg["exc_info"], "Exception type not logged" + assert len(msg["exc_info"].split("\n")) > 2, "Stacktrace doesn't have multiple lines" + + +def test_request_instrumentation(client_and_log_handler): + """Test if a request log is written""" + api_client, _ = client_and_log_handler + request_logger = logging.getLogger("fastapi-request-logger") + handler = FormattedMessageCollectorHandler() + request_logger.addHandler(handler) + + response = api_client.get("/log/levels/debug") + + assert response.status_code == 200 + assert len(handler.messages) == 1 + + +def test_excluded_from_request_instrumentation(client_and_log_handler): + """Test if endpoints can be excluded from the request log""" + api_client, _ = client_and_log_handler + request_logger = logging.getLogger("fastapi-request-logger") + handler = FormattedMessageCollectorHandler() + request_logger.addHandler(handler) + + response = api_client.get("/no-request-instrumentation") + + assert response.status_code == 200 + assert len(handler.messages) == 0 diff --git a/tests/test_flask.py b/tests/test_flask.py index 9fd16c5..72b39ef 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -3,7 +3,6 @@ import logging import pathlib import re -import sys import flask import pytest @@ -170,6 +169,7 @@ def test_exception_logged_with_stack_trace(client_and_log_handler): def test_request_instrumentation(client_and_log_handler): + """Test if a request log is written""" api_client, _ = client_and_log_handler request_logger = logging.getLogger("flask-request-logger") handler = FormattedMessageCollectorHandler() @@ -180,7 +180,9 @@ def test_request_instrumentation(client_and_log_handler): assert response.status_code == 200 assert len(handler.messages) == 1 + def test_excluded_from_request_instrumentation(client_and_log_handler): + """Test if endpoints can be excluded from the request log""" api_client, _ = client_and_log_handler request_logger = logging.getLogger("flask-request-logger") handler = FormattedMessageCollectorHandler() From 9a4c31292b0348af724e9bd23a3fbb53da8a904c Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Mon, 22 Mar 2021 03:00:42 +0100 Subject: [PATCH 5/9] Adding and example in the README.md --- README.md | 27 +++++++++++++++++++++++++-- 1 file changed, 25 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index efb770e..cf98b80 100644 --- a/README.md +++ b/README.md @@ -23,7 +23,7 @@ If you're using Cloud Foundry, it might worth to check out the library [SAP/cf-p 2. Lightweight, no dependencies, minimal configuration needed (1 LoC to get it working) 3. Seamlessly integrate with Python native **logging** module. Support both Python 2.7.x and 3.x 4. Auto extract **correlation-id** for distributed tracing [\[1\]](#1-what-is-correlation-idrequest-id) -5. Support HTTP request instrumentation. Built in support for [Flask](https://github.com/pallets/flask/), [Sanic](https://github.com/channelcat/sanic), [Quart](https://gitlab.com/pgjones/quart), [Connexion](https://github.com/zalando/connexion). Extensible to support other web frameworks. PR welcome :smiley: . +5. Support HTTP request instrumentation. Built in support for [FastAPI](https://fastapi.tiangolo.com/), [Flask](https://github.com/pallets/flask/), [Sanic](https://github.com/channelcat/sanic), [Quart](https://gitlab.com/pgjones/quart), [Connexion](https://github.com/zalando/connexion). Extensible to support other web frameworks. PR welcome :smiley: . 6. Highly customizable: support inject arbitrary extra properties to JSON log message, override logging formatter, etc. 7. Production ready, has been used in production since 2017 @@ -52,8 +52,31 @@ logger.info("test logging statement") ``` ## 2.2 Web application log -### Flask +### FastAPI +```python +import datetime, logging, sys, json_logging, fastapi, uvicorn + +app = fastapi.FastAPI() +json_logging.init_fastapi(enable_json=True) +json_logging.init_request_instrument(app) + +# init the logger as usual +logger = logging.getLogger("test-logger") +logger.setLevel(logging.DEBUG) +logger.addHandler(logging.StreamHandler(sys.stdout)) +@app.get('/') +def home(): + logger.info("test log statement") + logger.info("test log statement with extra props", extra={'props': {"extra_property": 'extra_value'}}) + correlation_id = json_logging.get_correlation_id() + return "Hello world : " + str(datetime.datetime.now()) + +if __name__ == "__main__": + uvicorn.run(app, host='0.0.0.0', port=5000) +``` + +### Flask ```python import datetime, logging, sys, json_logging, flask From 9eda892ad6fbfa1a6dbf2cfa7bf34c288f3eadab Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Thu, 25 Mar 2021 00:22:01 +0100 Subject: [PATCH 6/9] Removing fastapi imports from standard import tree (cherry picked from commit 4c96cb8647096395395e167033da69d2186d6366) --- json_logging/__init__.py | 9 +- json_logging/framework/fastapi/__init__.py | 126 +----------------- .../framework/fastapi/implementation.py | 122 +++++++++++++++++ 3 files changed, 128 insertions(+), 129 deletions(-) create mode 100644 json_logging/framework/fastapi/implementation.py diff --git a/json_logging/__init__.py b/json_logging/__init__.py index e67914a..4c3adf2 100644 --- a/json_logging/__init__.py +++ b/json_logging/__init__.py @@ -400,10 +400,11 @@ def init_connexion(custom_formatter=None, enable_json=False): # register FastAPI support import json_logging.framework.fastapi as fastapi_support -register_framework_support('fastapi', app_configurator=None, - app_request_instrumentation_configurator=fastapi_support.FastAPIAppRequestInstrumentationConfigurator, - request_adapter_class=fastapi_support.FastAPIRequestAdapter, - response_adapter_class=fastapi_support.FastAPIResponseAdapter) +if fastapi_support.is_fastapi_present(): + register_framework_support('fastapi', app_configurator=None, + app_request_instrumentation_configurator=fastapi_support.FastAPIAppRequestInstrumentationConfigurator, + request_adapter_class=fastapi_support.FastAPIRequestAdapter, + response_adapter_class=fastapi_support.FastAPIResponseAdapter) def init_fastapi(custom_formatter=None, enable_json=False): __init(framework_name='fastapi', custom_formatter=custom_formatter, enable_json=enable_json) diff --git a/json_logging/framework/fastapi/__init__.py b/json_logging/framework/fastapi/__init__.py index 66ec03b..a0fa384 100644 --- a/json_logging/framework/fastapi/__init__.py +++ b/json_logging/framework/fastapi/__init__.py @@ -1,17 +1,3 @@ -# coding=utf-8 -import logging - -from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint -from starlette.requests import Request -from starlette.responses import Response -from starlette.types import ASGIApp - -import json_logging -import json_logging.framework -from json_logging.framework_base import AppRequestInstrumentationConfigurator, RequestAdapter, ResponseAdapter - -from json_logging.util import is_not_match_any_pattern - def is_fastapi_present(): # noinspection PyPep8,PyBroadException @@ -24,114 +10,4 @@ def is_fastapi_present(): if is_fastapi_present(): - import fastapi - import starlette.requests - import starlette.responses - - -class JSONLoggingASGIMiddleware(BaseHTTPMiddleware): - def __init__(self, app: ASGIApp, exclude_url_patterns=tuple()) -> None: - super().__init__(app) - self.request_logger = logging.getLogger('fastapi-request-logger') - self.exclude_url_patterns = exclude_url_patterns - logging.getLogger("uvicorn.access").propagate = False - - async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response: - log_request = is_not_match_any_pattern(request.url.path, self.exclude_url_patterns) - - if not log_request: - return await call_next(request) - - request_info = json_logging.RequestInfo(request) - response = await call_next(request) - request_info.update_response_status(response) - self.request_logger.info( - "", extra={"request_info": request_info, "type": "request"} - ) - return response - - -class FastAPIAppRequestInstrumentationConfigurator(AppRequestInstrumentationConfigurator): - def config(self, app, exclude_url_patterns=tuple()): - if not is_fastapi_present(): - raise RuntimeError("fastapi is not available in system runtime") - if not isinstance(app, fastapi.FastAPI): - raise RuntimeError("app is not a valid fastapi.FastAPI instance") - - # Disable standard logging - logging.getLogger('uvicorn.access').disabled = True - - # noinspection PyAttributeOutsideInit - self.request_logger = logging.getLogger('fastapi-request-logger') - - app.add_middleware(JSONLoggingASGIMiddleware, exclude_url_patterns=exclude_url_patterns) - - -class FastAPIRequestAdapter(RequestAdapter): - @staticmethod - def get_request_class_type(): - return starlette.requests.Request - - @staticmethod - def support_global_request_object(): - return False - - @staticmethod - def get_current_request(): - raise NotImplementedError - - def get_remote_user(self, request: starlette.requests.Request): - try: - return request.user - except AssertionError: - return json_logging.EMPTY_VALUE - - def get_http_header(self, request: starlette.requests.Request, header_name, default=None): - try: - if header_name in request.headers: - return request.headers.get(header_name) - except: - pass - return default - - def set_correlation_id(self, request_, value): - request_.state.correlation_id = value - - def get_correlation_id_in_request_context(self, request: starlette.requests.Request): - try: - return request.state.correlation_id - except AttributeError: - return None - - def get_protocol(self, request: starlette.requests.Request): - protocol = str(request.scope.get('type', '')) - http_version = str(request.scope.get('http_version', '')) - if protocol.lower() == 'http' and http_version: - return protocol.upper() + "/" + http_version - return json_logging.EMPTY_VALUE - - def get_path(self, request: starlette.requests.Request): - return request.url.path - - def get_content_length(self, request: starlette.requests.Request): - return request.headers.get('content-length', json_logging.EMPTY_VALUE) - - def get_method(self, request: starlette.requests.Request): - return request.method - - def get_remote_ip(self, request: starlette.requests.Request): - return request.client.host - - def get_remote_port(self, request: starlette.requests.Request): - return request.client.port - - -class FastAPIResponseAdapter(ResponseAdapter): - def get_status_code(self, response: starlette.responses.Response): - return response.status_code - - def get_response_size(self, response: starlette.responses.Response): - return response.headers.get('content-length', json_logging.EMPTY_VALUE) - - def get_content_type(self, response: starlette.responses.Response): - return response.headers.get('content-type', json_logging.EMPTY_VALUE) + from .implementation import FastAPIAppRequestInstrumentationConfigurator, FastAPIRequestAdapter, FastAPIResponseAdapter diff --git a/json_logging/framework/fastapi/implementation.py b/json_logging/framework/fastapi/implementation.py new file mode 100644 index 0000000..7d5f5cc --- /dev/null +++ b/json_logging/framework/fastapi/implementation.py @@ -0,0 +1,122 @@ +import logging + +import json_logging +import json_logging.framework +from json_logging.framework_base import AppRequestInstrumentationConfigurator, RequestAdapter, ResponseAdapter + +from json_logging.util import is_not_match_any_pattern + +import fastapi +import starlette.requests +import starlette.responses + +from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint +from starlette.requests import Request +from starlette.responses import Response +from starlette.types import ASGIApp + + +class JSONLoggingASGIMiddleware(BaseHTTPMiddleware): + def __init__(self, app: ASGIApp, exclude_url_patterns=tuple()) -> None: + super().__init__(app) + self.request_logger = logging.getLogger('fastapi-request-logger') + self.exclude_url_patterns = exclude_url_patterns + logging.getLogger("uvicorn.access").propagate = False + + async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response: + log_request = is_not_match_any_pattern(request.url.path, self.exclude_url_patterns) + + if not log_request: + return await call_next(request) + + request_info = json_logging.RequestInfo(request) + response = await call_next(request) + request_info.update_response_status(response) + self.request_logger.info( + "", extra={"request_info": request_info, "type": "request"} + ) + return response + + +class FastAPIAppRequestInstrumentationConfigurator(AppRequestInstrumentationConfigurator): + def config(self, app, exclude_url_patterns=tuple()): + if not isinstance(app, fastapi.FastAPI): + raise RuntimeError("app is not a valid fastapi.FastAPI instance") + + # Disable standard logging + logging.getLogger('uvicorn.access').disabled = True + + # noinspection PyAttributeOutsideInit + self.request_logger = logging.getLogger('fastapi-request-logger') + + app.add_middleware(JSONLoggingASGIMiddleware, exclude_url_patterns=exclude_url_patterns) + + +class FastAPIRequestAdapter(RequestAdapter): + @staticmethod + def get_request_class_type(): + return starlette.requests.Request + + @staticmethod + def support_global_request_object(): + return False + + @staticmethod + def get_current_request(): + raise NotImplementedError + + def get_remote_user(self, request: starlette.requests.Request): + try: + return request.user + except AssertionError: + return json_logging.EMPTY_VALUE + + def get_http_header(self, request: starlette.requests.Request, header_name, default=None): + try: + if header_name in request.headers: + return request.headers.get(header_name) + except: + pass + return default + + def set_correlation_id(self, request_, value): + request_.state.correlation_id = value + + def get_correlation_id_in_request_context(self, request: starlette.requests.Request): + try: + return request.state.correlation_id + except AttributeError: + return None + + def get_protocol(self, request: starlette.requests.Request): + protocol = str(request.scope.get('type', '')) + http_version = str(request.scope.get('http_version', '')) + if protocol.lower() == 'http' and http_version: + return protocol.upper() + "/" + http_version + return json_logging.EMPTY_VALUE + + def get_path(self, request: starlette.requests.Request): + return request.url.path + + def get_content_length(self, request: starlette.requests.Request): + return request.headers.get('content-length', json_logging.EMPTY_VALUE) + + def get_method(self, request: starlette.requests.Request): + return request.method + + def get_remote_ip(self, request: starlette.requests.Request): + return request.client.host + + def get_remote_port(self, request: starlette.requests.Request): + return request.client.port + + +class FastAPIResponseAdapter(ResponseAdapter): + def get_status_code(self, response: starlette.responses.Response): + return response.status_code + + def get_response_size(self, response: starlette.responses.Response): + return response.headers.get('content-length', json_logging.EMPTY_VALUE) + + def get_content_type(self, response: starlette.responses.Response): + return response.headers.get('content-type', json_logging.EMPTY_VALUE) From 15db3c309ebcea04926995564626b0cdbdc454b1 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Thu, 25 Mar 2021 00:23:22 +0100 Subject: [PATCH 7/9] Adding smoketests for the API examples This runs every API example in a minimal environment where the dependencies for the other API frameworks are missing. This test guarantees that json-logging works for each individual framework. --- .github/workflows/code_quality.yml | 27 ++++++++++- README.md | 2 +- tests/README.md | 11 +++++ tests/smoketests/fastapi/api.py | 20 ++++++++ tests/smoketests/fastapi/requirements.txt | 5 ++ tests/smoketests/flask/api.py | 20 ++++++++ tests/smoketests/flask/requirements.txt | 4 ++ tests/smoketests/quart/api.py | 21 ++++++++ tests/smoketests/quart/requirements.txt | 4 ++ tests/smoketests/sanic/api.py | 24 ++++++++++ tests/smoketests/sanic/requirements.txt | 4 ++ tests/smoketests/test_run_smoketest.py | 58 +++++++++++++++++++++++ 12 files changed, 197 insertions(+), 3 deletions(-) create mode 100644 tests/README.md create mode 100644 tests/smoketests/fastapi/api.py create mode 100644 tests/smoketests/fastapi/requirements.txt create mode 100644 tests/smoketests/flask/api.py create mode 100644 tests/smoketests/flask/requirements.txt create mode 100644 tests/smoketests/quart/api.py create mode 100644 tests/smoketests/quart/requirements.txt create mode 100644 tests/smoketests/sanic/api.py create mode 100644 tests/smoketests/sanic/requirements.txt create mode 100644 tests/smoketests/test_run_smoketest.py diff --git a/.github/workflows/code_quality.yml b/.github/workflows/code_quality.yml index 9a6b56e..9256df9 100644 --- a/.github/workflows/code_quality.yml +++ b/.github/workflows/code_quality.yml @@ -35,7 +35,6 @@ jobs: runs-on: ubuntu-latest strategy: - max-parallel: 4 matrix: python-version: ["3.7", "3.8", "3.9"] @@ -52,4 +51,28 @@ jobs: pip install -r test-requirements.txt - name: Run tests run: | - pytest + pytest --ignore tests/smoketests + + backendSmoketests: + name: Individual Backend Smoketests + runs-on: ubuntu-latest + + strategy: + matrix: + backend: ["fastapi", "flask", "quart", "sanic"] + + steps: + - name: Set up Python ${{ matrix.python-version }} + uses: actions/setup-python@v2 + with: + python-version: 3.9 + - name: "Git checkout" + uses: actions/checkout@v2 + - name: Install dependencies + run: | + python -m pip install --upgrade pip + pip install -r tests/smoketests/${{ matrix.backend }}/requirements.txt + - name: Run tests + run: | + export backend=${{ matrix.backend }} + pytest tests/smoketests/test_run_smoketest.py diff --git a/README.md b/README.md index cf98b80..78c216d 100644 --- a/README.md +++ b/README.md @@ -125,7 +125,7 @@ async def home(request): return sanic.response.text("hello world") if __name__ == "__main__": - app.run(host="0.0.0.0", port=8000) + app.run(host="0.0.0.0", port=5000) ``` ### Quart diff --git a/tests/README.md b/tests/README.md new file mode 100644 index 0000000..4617c1b --- /dev/null +++ b/tests/README.md @@ -0,0 +1,11 @@ +# Organization of the test folder + +``` +├───helpers Shared functionality for all tests +├───smoketests A test script to run all API examples and see if they work +│ ├───fastapi +│ ├───flask +│ ├───quart +│ └───sanic +└───test_*.py Unit tests +``` diff --git a/tests/smoketests/fastapi/api.py b/tests/smoketests/fastapi/api.py new file mode 100644 index 0000000..dd6dbb7 --- /dev/null +++ b/tests/smoketests/fastapi/api.py @@ -0,0 +1,20 @@ +import datetime, logging, sys, json_logging, fastapi, uvicorn + +app = fastapi.FastAPI() +json_logging.init_fastapi(enable_json=True) +json_logging.init_request_instrument(app) + +# init the logger as usual +logger = logging.getLogger("test-logger") +logger.setLevel(logging.DEBUG) +logger.addHandler(logging.StreamHandler(sys.stdout)) + +@app.get('/') +def home(): + logger.info("test log statement") + logger.info("test log statement with extra props", extra={'props': {"extra_property": 'extra_value'}}) + correlation_id = json_logging.get_correlation_id() + return "Hello world : " + str(datetime.datetime.now()) + +if __name__ == "__main__": + uvicorn.run(app, host='0.0.0.0', port=5000) diff --git a/tests/smoketests/fastapi/requirements.txt b/tests/smoketests/fastapi/requirements.txt new file mode 100644 index 0000000..a1963dc --- /dev/null +++ b/tests/smoketests/fastapi/requirements.txt @@ -0,0 +1,5 @@ +fastapi +uvicorn +requests +pytest +-e . diff --git a/tests/smoketests/flask/api.py b/tests/smoketests/flask/api.py new file mode 100644 index 0000000..89e5ff8 --- /dev/null +++ b/tests/smoketests/flask/api.py @@ -0,0 +1,20 @@ +import datetime, logging, sys, json_logging, flask + +app = flask.Flask(__name__) +json_logging.init_flask(enable_json=True) +json_logging.init_request_instrument(app) + +# init the logger as usual +logger = logging.getLogger("test-logger") +logger.setLevel(logging.DEBUG) +logger.addHandler(logging.StreamHandler(sys.stdout)) + +@app.route('/') +def home(): + logger.info("test log statement") + logger.info("test log statement with extra props", extra={'props': {"extra_property": 'extra_value'}}) + correlation_id = json_logging.get_correlation_id() + return "Hello world : " + str(datetime.datetime.now()) + +if __name__ == "__main__": + app.run(host='0.0.0.0', port=int(5000), use_reloader=False) diff --git a/tests/smoketests/flask/requirements.txt b/tests/smoketests/flask/requirements.txt new file mode 100644 index 0000000..4e1f60b --- /dev/null +++ b/tests/smoketests/flask/requirements.txt @@ -0,0 +1,4 @@ +flask +requests +pytest +-e . diff --git a/tests/smoketests/quart/api.py b/tests/smoketests/quart/api.py new file mode 100644 index 0000000..f7728fa --- /dev/null +++ b/tests/smoketests/quart/api.py @@ -0,0 +1,21 @@ +import asyncio, logging, sys, json_logging, quart + +app = quart.Quart(__name__) +json_logging.init_quart(enable_json=True) +json_logging.init_request_instrument(app) + +# init the logger as usual +logger = logging.getLogger("test logger") +logger.setLevel(logging.DEBUG) +logger.addHandler(logging.StreamHandler(sys.stdout)) + +@app.route('/') +async def home(): + logger.info("test log statement") + logger.info("test log statement with extra props", extra={'props': {"extra_property": 'extra_value'}}) + correlation_id = json_logging.get_correlation_id() + return "Hello world" + +if __name__ == "__main__": + loop = asyncio.get_event_loop() + app.run(host='0.0.0.0', port=int(5000), use_reloader=False, loop=loop) diff --git a/tests/smoketests/quart/requirements.txt b/tests/smoketests/quart/requirements.txt new file mode 100644 index 0000000..21b37c1 --- /dev/null +++ b/tests/smoketests/quart/requirements.txt @@ -0,0 +1,4 @@ +quart +requests +pytest +-e . diff --git a/tests/smoketests/sanic/api.py b/tests/smoketests/sanic/api.py new file mode 100644 index 0000000..7dffc62 --- /dev/null +++ b/tests/smoketests/sanic/api.py @@ -0,0 +1,24 @@ +import logging, sys, json_logging, sanic + +app = sanic.Sanic(name="sanic-web-app") +json_logging.init_sanic(enable_json=True) +json_logging.init_request_instrument(app) + +# init the logger as usual +logger = logging.getLogger("sanic-integration-test-app") +logger.setLevel(logging.DEBUG) +logger.addHandler(logging.StreamHandler(sys.stdout)) + +@app.route("/") +async def home(request): + logger.info("test log statement") + logger.info("test log statement with extra props", extra={'props': {"extra_property": 'extra_value'}}) + # this will be faster + correlation_id = json_logging.get_correlation_id(request=request) + # this will be slower, but will work in context you cant get a reference of request object + correlation_id_without_request_obj = json_logging.get_correlation_id() + + return sanic.response.text("hello world") + +if __name__ == "__main__": + app.run(host="0.0.0.0", port=5000) diff --git a/tests/smoketests/sanic/requirements.txt b/tests/smoketests/sanic/requirements.txt new file mode 100644 index 0000000..0050908 --- /dev/null +++ b/tests/smoketests/sanic/requirements.txt @@ -0,0 +1,4 @@ +sanic +requests +pytest +-e . diff --git a/tests/smoketests/test_run_smoketest.py b/tests/smoketests/test_run_smoketest.py new file mode 100644 index 0000000..9cea99c --- /dev/null +++ b/tests/smoketests/test_run_smoketest.py @@ -0,0 +1,58 @@ +"""Test module to run all example APIs and see if they work independently of each other + +These tests are meant to be executed independently with only the minimal environment. +This way it becomes clear if json_logging works without the dependencies of API frameworks one +doesn't intend to use. +""" + +import os +import signal +import subprocess +import sys +import time +from pathlib import Path + +import pytest +import requests + + +def collect_backends(): + """Generator function which returns all test backends one by one + + If the environment variable "backend" is set, only this one backend is returned + """ + preset_backend = os.environ.get('backend') + if preset_backend: + yield preset_backend + else: + for folder in Path(__file__).parent.iterdir(): + if folder.is_dir(): + yield str(folder.name) + + +@pytest.mark.parametrize('backend', collect_backends(), ids=collect_backends()) +def test_api_example(backend): + """For each of the examples start the API and see if the root endpoint is reachable""" + api_process = subprocess.Popen( + [sys.executable, Path(__file__).parent / backend / "api.py"], + stdout=sys.stdout, + stderr=subprocess.STDOUT, + ) + try: + deadline = time.perf_counter() + 10.0 + while time.perf_counter() < deadline: + time.sleep(1) + session = requests.Session() + session.trust_env = False + os.environ['NO_PROXY'] = 'localhost' + os.environ['no_proxy'] = 'localhost' + try: + response = requests.get("http://localhost:5000/", timeout=1) + assert response.status_code == 200 + return + except requests.exceptions.Timeout: + pass + assert False, "API did not respond" + finally: + api_process.send_signal(signal.SIGTERM) + api_process.wait(timeout=5.0) From 94bcdc7289eb51f8793d23992d9ae0c6ed0252e1 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Thu, 25 Mar 2021 01:57:23 +0100 Subject: [PATCH 8/9] Increasing timeouts (cherry picked from commit 4d9d596e227846dcd5ce83f9d7e1832c25cb164c) --- tests/smoketests/test_run_smoketest.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/smoketests/test_run_smoketest.py b/tests/smoketests/test_run_smoketest.py index 9cea99c..0a2c4b6 100644 --- a/tests/smoketests/test_run_smoketest.py +++ b/tests/smoketests/test_run_smoketest.py @@ -39,9 +39,9 @@ def test_api_example(backend): stderr=subprocess.STDOUT, ) try: - deadline = time.perf_counter() + 10.0 + deadline = time.perf_counter() + 15.0 while time.perf_counter() < deadline: - time.sleep(1) + time.sleep(3) session = requests.Session() session.trust_env = False os.environ['NO_PROXY'] = 'localhost' From 0fd9df09263151b2a778858260421ba3cc7738b6 Mon Sep 17 00:00:00 2001 From: chr1st1ank Date: Thu, 25 Mar 2021 08:01:29 +0100 Subject: [PATCH 9/9] Add logger.SetLevel() for the fastapi example. Only then it works in the IPython shell --- example/fastapi_sample_app.py | 1 + 1 file changed, 1 insertion(+) diff --git a/example/fastapi_sample_app.py b/example/fastapi_sample_app.py index 0d8c515..3909ebe 100644 --- a/example/fastapi_sample_app.py +++ b/example/fastapi_sample_app.py @@ -8,6 +8,7 @@ # init the logger as usual logger = logging.getLogger(__name__) +logger.setLevel(logging.DEBUG) @app.get('/') async def home():