diff --git a/api/.env.example b/api/.env.example index 3230e3d828..9dec564c28 100644 --- a/api/.env.example +++ b/api/.env.example @@ -348,6 +348,7 @@ SENTRY_DSN= # DEBUG DEBUG=false +ENABLE_REQUEST_LOGGING=False SQLALCHEMY_ECHO=false # Notion import configuration, support public and internal diff --git a/api/app_factory.py b/api/app_factory.py index 1c886ac5c7..3a258be28f 100644 --- a/api/app_factory.py +++ b/api/app_factory.py @@ -54,6 +54,7 @@ def initialize_extensions(app: DifyApp): ext_otel, ext_proxy_fix, ext_redis, + ext_request_logging, ext_sentry, ext_set_secretkey, ext_storage, @@ -83,6 +84,7 @@ def initialize_extensions(app: DifyApp): ext_blueprints, ext_commands, ext_otel, + ext_request_logging, ] for ext in extensions: short_name = ext.__name__.split(".")[-1] diff --git a/api/configs/deploy/__init__.py b/api/configs/deploy/__init__.py index 950936d3c6..63f4dfba63 100644 --- a/api/configs/deploy/__init__.py +++ b/api/configs/deploy/__init__.py @@ -17,6 +17,12 @@ class DeploymentConfig(BaseSettings): default=False, ) + # Request logging configuration + ENABLE_REQUEST_LOGGING: bool = Field( + description="Enable request and response body logging", + default=False, + ) + EDITION: str = Field( description="Deployment edition of the application (e.g., 'SELF_HOSTED', 'CLOUD')", default="SELF_HOSTED", diff --git a/api/extensions/ext_request_logging.py b/api/extensions/ext_request_logging.py new file mode 100644 index 0000000000..7c69483e0f --- /dev/null +++ b/api/extensions/ext_request_logging.py @@ -0,0 +1,73 @@ +import json +import logging + +import flask +import werkzeug.http +from flask import Flask +from flask.signals import request_finished, request_started + +from configs import dify_config + +_logger = logging.getLogger(__name__) + + +def _is_content_type_json(content_type: str) -> bool: + if not content_type: + return False + content_type_no_option, _ = werkzeug.http.parse_options_header(content_type) + return content_type_no_option.lower() == "application/json" + + +def _log_request_started(_sender, **_extra): + """Log the start of a request.""" + if not _logger.isEnabledFor(logging.DEBUG): + return + + request = flask.request + if not (_is_content_type_json(request.content_type) and request.data): + _logger.debug("Received Request %s -> %s", request.method, request.path) + return + try: + json_data = json.loads(request.data) + except (TypeError, ValueError): + _logger.exception("Failed to parse JSON request") + return + formatted_json = json.dumps(json_data, ensure_ascii=False, indent=2) + _logger.debug( + "Received Request %s -> %s, Request Body:\n%s", + request.method, + request.path, + formatted_json, + ) + + +def _log_request_finished(_sender, response, **_extra): + """Log the end of a request.""" + if not _logger.isEnabledFor(logging.DEBUG) or response is None: + return + + if not _is_content_type_json(response.content_type): + _logger.debug("Response %s %s", response.status, response.content_type) + return + + response_data = response.get_data(as_text=True) + try: + json_data = json.loads(response_data) + except (TypeError, ValueError): + _logger.exception("Failed to parse JSON response") + return + formatted_json = json.dumps(json_data, ensure_ascii=False, indent=2) + _logger.debug( + "Response %s %s, Response Body:\n%s", + response.status, + response.content_type, + formatted_json, + ) + + +def init_app(app: Flask): + """Initialize the request logging extension.""" + if not dify_config.ENABLE_REQUEST_LOGGING: + return + request_started.connect(_log_request_started, app) + request_finished.connect(_log_request_finished, app) diff --git a/api/tests/unit_tests/extensions/test_ext_request_logging.py b/api/tests/unit_tests/extensions/test_ext_request_logging.py new file mode 100644 index 0000000000..4e71469bcc --- /dev/null +++ b/api/tests/unit_tests/extensions/test_ext_request_logging.py @@ -0,0 +1,265 @@ +import json +import logging +from unittest import mock + +import pytest +from flask import Flask, Response + +from configs import dify_config +from extensions import ext_request_logging +from extensions.ext_request_logging import _is_content_type_json, _log_request_finished, init_app + + +def test_is_content_type_json(): + """ + Test the _is_content_type_json function. + """ + + assert _is_content_type_json("application/json") is True + # content type header with charset option. + assert _is_content_type_json("application/json; charset=utf-8") is True + # content type header with charset option, in uppercase. + assert _is_content_type_json("APPLICATION/JSON; CHARSET=UTF-8") is True + assert _is_content_type_json("text/html") is False + assert _is_content_type_json("") is False + + +_KEY_NEEDLE = "needle" +_VALUE_NEEDLE = _KEY_NEEDLE[::-1] +_RESPONSE_NEEDLE = "response" + + +def _get_test_app(): + app = Flask(__name__) + + @app.route("/", methods=["GET", "POST"]) + def handler(): + return _RESPONSE_NEEDLE + + return app + + +# NOTE(QuantumGhost): Due to the design of Flask, we need to use monkey patch to write tests. + + +@pytest.fixture +def mock_request_receiver(monkeypatch) -> mock.Mock: + mock_log_request_started = mock.Mock() + monkeypatch.setattr(ext_request_logging, "_log_request_started", mock_log_request_started) + return mock_log_request_started + + +@pytest.fixture +def mock_response_receiver(monkeypatch) -> mock.Mock: + mock_log_request_finished = mock.Mock() + monkeypatch.setattr(ext_request_logging, "_log_request_finished", mock_log_request_finished) + return mock_log_request_finished + + +@pytest.fixture +def mock_logger(monkeypatch) -> logging.Logger: + _logger = mock.MagicMock(spec=logging.Logger) + monkeypatch.setattr(ext_request_logging, "_logger", _logger) + return _logger + + +@pytest.fixture +def enable_request_logging(monkeypatch): + monkeypatch.setattr(dify_config, "ENABLE_REQUEST_LOGGING", True) + + +class TestRequestLoggingExtension: + def test_receiver_should_not_be_invoked_if_configuration_is_disabled( + self, + monkeypatch, + mock_request_receiver, + mock_response_receiver, + ): + monkeypatch.setattr(dify_config, "ENABLE_REQUEST_LOGGING", False) + + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.get("/") + + mock_request_receiver.assert_not_called() + mock_response_receiver.assert_not_called() + + def test_receiver_should_be_called_if_enabled( + self, + enable_request_logging, + mock_request_receiver, + mock_response_receiver, + ): + """ + Test the request logging extension with JSON data. + """ + + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.post("/", json={_KEY_NEEDLE: _VALUE_NEEDLE}) + + mock_request_receiver.assert_called_once() + mock_response_receiver.assert_called_once() + + +class TestLoggingLevel: + @pytest.mark.usefixtures("enable_request_logging") + def test_logging_should_be_skipped_if_level_is_above_debug(self, enable_request_logging, mock_logger): + mock_logger.isEnabledFor.return_value = False + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.post("/", json={_KEY_NEEDLE: _VALUE_NEEDLE}) + mock_logger.debug.assert_not_called() + + +class TestRequestReceiverLogging: + @pytest.mark.usefixtures("enable_request_logging") + def test_non_json_request(self, enable_request_logging, mock_logger, mock_response_receiver): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.post("/", data="plain text") + assert mock_logger.debug.call_count == 1 + call_args = mock_logger.debug.call_args[0] + assert "Received Request" in call_args[0] + assert call_args[1] == "POST" + assert call_args[2] == "/" + assert "Request Body" not in call_args[0] + + @pytest.mark.usefixtures("enable_request_logging") + def test_json_request(self, enable_request_logging, mock_logger, mock_response_receiver): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.post("/", json={_KEY_NEEDLE: _VALUE_NEEDLE}) + assert mock_logger.debug.call_count == 1 + call_args = mock_logger.debug.call_args[0] + assert "Received Request" in call_args[0] + assert "Request Body" in call_args[0] + assert call_args[1] == "POST" + assert call_args[2] == "/" + assert _KEY_NEEDLE in call_args[3] + + @pytest.mark.usefixtures("enable_request_logging") + def test_json_request_with_empty_body(self, enable_request_logging, mock_logger, mock_response_receiver): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.post("/", headers={"Content-Type": "application/json"}) + + assert mock_logger.debug.call_count == 1 + call_args = mock_logger.debug.call_args[0] + assert "Received Request" in call_args[0] + assert "Request Body" not in call_args[0] + assert call_args[1] == "POST" + assert call_args[2] == "/" + + @pytest.mark.usefixtures("enable_request_logging") + def test_json_request_with_invalid_json_as_body(self, enable_request_logging, mock_logger, mock_response_receiver): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + client.post( + "/", + headers={"Content-Type": "application/json"}, + data="{", + ) + assert mock_logger.debug.call_count == 0 + assert mock_logger.exception.call_count == 1 + + exception_call_args = mock_logger.exception.call_args[0] + assert exception_call_args[0] == "Failed to parse JSON request" + + +class TestResponseReceiverLogging: + @pytest.mark.usefixtures("enable_request_logging") + def test_non_json_response(self, enable_request_logging, mock_logger): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + response = Response( + "OK", + headers={"Content-Type": "text/plain"}, + ) + _log_request_finished(app, response) + assert mock_logger.debug.call_count == 1 + call_args = mock_logger.debug.call_args[0] + assert "Response" in call_args[0] + assert "200" in call_args[1] + assert call_args[2] == "text/plain" + assert "Response Body" not in call_args[0] + + @pytest.mark.usefixtures("enable_request_logging") + def test_json_response(self, enable_request_logging, mock_logger, mock_response_receiver): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + response = Response( + json.dumps({_KEY_NEEDLE: _VALUE_NEEDLE}), + headers={"Content-Type": "application/json"}, + ) + _log_request_finished(app, response) + assert mock_logger.debug.call_count == 1 + call_args = mock_logger.debug.call_args[0] + assert "Response" in call_args[0] + assert "Response Body" in call_args[0] + assert "200" in call_args[1] + assert call_args[2] == "application/json" + assert _KEY_NEEDLE in call_args[3] + + @pytest.mark.usefixtures("enable_request_logging") + def test_json_request_with_invalid_json_as_body(self, enable_request_logging, mock_logger, mock_response_receiver): + mock_logger.isEnabledFor.return_value = True + app = _get_test_app() + + response = Response( + "{", + headers={"Content-Type": "application/json"}, + ) + _log_request_finished(app, response) + assert mock_logger.debug.call_count == 0 + assert mock_logger.exception.call_count == 1 + + exception_call_args = mock_logger.exception.call_args[0] + assert exception_call_args[0] == "Failed to parse JSON response" + + +class TestResponseUnmodified: + def test_when_request_logging_disabled(self): + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + response = client.post( + "/", + headers={"Content-Type": "application/json"}, + data="{", + ) + assert response.text == _RESPONSE_NEEDLE + assert response.status_code == 200 + + @pytest.mark.usefixtures("enable_request_logging") + def test_when_request_logging_enabled(self, enable_request_logging): + app = _get_test_app() + init_app(app) + + with app.test_client() as client: + response = client.post( + "/", + headers={"Content-Type": "application/json"}, + data="{", + ) + assert response.text == _RESPONSE_NEEDLE + assert response.status_code == 200 diff --git a/docker/.env.example b/docker/.env.example index f461be5a4a..7871f71a98 100644 --- a/docker/.env.example +++ b/docker/.env.example @@ -74,6 +74,10 @@ DEBUG=false # which is convenient for debugging. FLASK_DEBUG=false +# Enable request logging, which will log the request and response information. +# And the log level is DEBUG +ENABLE_REQUEST_LOGGING=False + # A secret key that is used for securely signing the session cookie # and encrypting sensitive information on the database. # You can generate a strong key using `openssl rand -base64 42`. diff --git a/docker/docker-compose.yaml b/docker/docker-compose.yaml index bfdfa701e3..0aca3b749e 100644 --- a/docker/docker-compose.yaml +++ b/docker/docker-compose.yaml @@ -19,6 +19,7 @@ x-shared-env: &shared-api-worker-env LOG_TZ: ${LOG_TZ:-UTC} DEBUG: ${DEBUG:-false} FLASK_DEBUG: ${FLASK_DEBUG:-false} + ENABLE_REQUEST_LOGGING: ${ENABLE_REQUEST_LOGGING:-False} SECRET_KEY: ${SECRET_KEY:-sk-9f73s3ljTXVcMT3Blb3ljTqtsKiGHXVcMT3BlbkFJLK7U} INIT_PASSWORD: ${INIT_PASSWORD:-} DEPLOY_ENV: ${DEPLOY_ENV:-PRODUCTION}