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 2c0e9b0..78c216d 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 @@ -102,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 @@ -227,7 +250,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? diff --git a/example/fastapi_sample_app.py b/example/fastapi_sample_app.py new file mode 100644 index 0000000..3909ebe --- /dev/null +++ b/example/fastapi_sample_app.py @@ -0,0 +1,56 @@ +import logging + +import fastapi + +import json_logging + +app = fastapi.FastAPI() + +# init the logger as usual +logger = logging.getLogger(__name__) +logger.setLevel(logging.DEBUG) + +@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..4c3adf2 100644 --- a/json_logging/__init__.py +++ b/json_logging/__init__.py @@ -395,3 +395,16 @@ 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 + +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 new file mode 100644 index 0000000..a0fa384 --- /dev/null +++ b/json_logging/framework/fastapi/__init__.py @@ -0,0 +1,13 @@ + +def is_fastapi_present(): + # noinspection PyPep8,PyBroadException + try: + import fastapi + import starlette + return True + except: + return False + + +if is_fastapi_present(): + 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) 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/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/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/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/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..0a2c4b6 --- /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() + 15.0 + while time.perf_counter() < deadline: + time.sleep(3) + 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) 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 2c33a17..72b39ef 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -3,13 +3,13 @@ import logging import pathlib import re -import sys import flask import pytest from helpers import constants from helpers.handler import FormattedMessageCollectorHandler +from helpers.imports import undo_imports_from_package LOGGER_NAME = "flask-test" @@ -29,7 +29,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") @@ -63,12 +63,20 @@ 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()} + + @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"]) @@ -121,6 +129,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 @@ -148,3 +166,29 @@ 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): + """Test if a request log is written""" + 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): + """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() + request_logger.addHandler(handler) + + response = api_client.get("/no-request-instrumentation") + + assert response.status_code == 200 + assert len(handler.messages) == 0