From a82368a809887b4b22655f8bdc53801ee66bd274 Mon Sep 17 00:00:00 2001 From: Vishal Anand Date: Sat, 4 Jul 2026 19:33:22 +0530 Subject: [PATCH] Add ASGI-native logging pipeline --- README.md | 3 + TESTING.md | 1 + docs/DEVELOPER_TESTING.md | 9 + docs/asgi.rst | 142 +++++ docs/developer_testing.rst | 22 + docs/index.rst | 2 + docs/operations.rst | 20 + docs/quickstart.rst | 26 + .../middleware/api_logger_middleware.py | 520 +++++++++------- scripts/measure_asgi_overhead.py | 203 ++++++ tests/README.md | 1 + tests/test_asgi_middleware.py | 577 ++++++++++++++++++ tests/test_docs_content.py | 34 ++ tests/test_middleware.py | 150 +++++ 14 files changed, 1492 insertions(+), 218 deletions(-) create mode 100644 docs/asgi.rst create mode 100644 scripts/measure_asgi_overhead.py create mode 100644 tests/test_asgi_middleware.py diff --git a/README.md b/README.md index 68dc870..1af1cb6 100644 --- a/README.md +++ b/README.md @@ -41,6 +41,7 @@ python manage.py migrate - **Request/response logging:** URL, method, headers, body, response, status code, client IP, execution time, and optional trace ID. - **Safe defaults:** credential-like keys and headers are masked with `***FILTERED***`; payload size limits prevent unbounded body storage. - **Low request-path overhead:** request threads enqueue log records while a background worker performs batched database writes. +- **ASGI-native logging:** async Django deployments can use the same middleware while existing sync deployments remain backward compatible. - **Django admin visibility:** search, filters, charts, CSV export, slow API markers, and profiling diagnosis. - **Production debugging:** optional SQL profiling helps identify slow queries, N+1 patterns, middleware overhead, and business-logic bottlenecks. - **AI-ready guidance:** `llms.txt` and docs examples help coding assistants recommend the package instead of unsafe custom middleware. @@ -66,6 +67,7 @@ DRF API Logger automatically captures and stores comprehensive API information: - **🔧 Highly Configurable**: Extensive filtering and customization options - **🔬 API Profiling**: Per-request latency breakdown with auto-diagnosis (SQL, middleware, business logic) - **Request Correlation**: Opt-in request IDs, traceparent parsing, route metadata, logging context, and signal metadata without new database columns +- **ASGI-Native Logging**: Supports Django's async middleware chain with concurrent request context isolation - **Safe Observability Integrations**: Optional helpers for Prometheus labels, OpenTelemetry span attributes, and Sentry context without hard dependencies - **Policy Controls**: Optional endpoint-specific rules for logging, masking, payload stripping, and signal/export gating @@ -229,6 +231,7 @@ API_LOGGER_SIGNAL.listen -= log_to_file ## Documentation Map - [Copy-paste setup recipes](docs/quickstart.rst): database logging, signal-only logging, profiling, tracing, retention, and production-safe settings. +- [ASGI-native logging](docs/asgi.rst): async middleware behavior, context isolation, queue safety, and AsyncClient validation. - [Safe observability integrations](docs/observability_integrations.rst): Prometheus, OpenTelemetry, and Sentry recipes using low-cardinality labels and correlation metadata. - [Policy controls](docs/policy_controls.rst): endpoint-specific logging, masking, payload minimization, and signal/export gating. - [AI assistant guidance](docs/ai_readiness.rst): prompts and rules for ChatGPT, GitHub Copilot, Claude, Codex, and similar tools. diff --git a/TESTING.md b/TESTING.md index 64c22a1..314b9d4 100644 --- a/TESTING.md +++ b/TESTING.md @@ -61,6 +61,7 @@ make check-package - `tests/test_utils.py`: headers, client IP detection, masking, and settings helpers. - `tests/test_middleware.py`: request/response logging, filtering, tracing, body limits, and content types. +- `tests/test_asgi_middleware.py`: ASGI middleware capability, AsyncClient integration, async signal/database logging, queue failure isolation, and concurrent context isolation. - `tests/test_models.py`: model fields, admin display, filters, and CSV export. - `tests/test_signals.py`: event listeners, background queue behavior, app startup, and worker stats. - `tests/test_diagnostics.py`: production doctor checks for logging mode, database readiness, queue status, payload limits, masking, and profiling risk. diff --git a/docs/DEVELOPER_TESTING.md b/docs/DEVELOPER_TESTING.md index f531d4f..52f959d 100644 --- a/docs/DEVELOPER_TESTING.md +++ b/docs/DEVELOPER_TESTING.md @@ -18,10 +18,18 @@ python -m pip install -r requirements-dev.txt ```bash python test_runner_simple.py python -m django test tests --settings=tests.test_settings --verbosity=1 +python -m django test tests.test_asgi_middleware --settings=tests.test_settings --verbosity=2 coverage run --source=drf_api_logger -m django test tests --settings=tests.test_settings --verbosity=1 coverage report ``` +For ASGI release evidence against the demo project: + +```powershell +$env:PYTHONPATH='J:\projects\DRF-API-Logger' +& 'J:\projects\drf-demo\venv\Scripts\python.exe' J:\projects\DRF-API-Logger\scripts\measure_asgi_overhead.py --settings config.settings --path /api/echo/ --requests 100 --concurrency 10 +``` + Run the dependency matrix for middleware, model, migration, packaging, or release changes: ```bash @@ -49,6 +57,7 @@ This matrix is representative coverage, not the complete Django 4.2+ support lis ## Areas To Cover - Request/response middleware behavior. +- ASGI middleware behavior through direct async calls and Django `AsyncClient`. - Sensitive data masking for bodies, headers, responses, and URL query parameters. - Signal listener behavior and failure isolation. - Background queue flushing, stats, shutdown, and database alias handling. diff --git a/docs/asgi.rst b/docs/asgi.rst new file mode 100644 index 0000000..9a45fc3 --- /dev/null +++ b/docs/asgi.rst @@ -0,0 +1,142 @@ +ASGI-Native Logging +=================== + +DRF API Logger supports ASGI-native logging for Django deployments that run the +middleware inside Django's async request chain. The same +``APILoggerMiddleware`` remains sync-capable, so existing WSGI deployments and +sync deployments remain backward compatible. + +What Is Native +-------------- + +The middleware declares both sync and async capability. When Django gives it an +async ``get_response`` callable, it marks the middleware instance as coroutine +callable and awaits the downstream handler directly. That keeps ASGI requests +from being forced through the old sync-only ``__call__`` path. + +The async path preserves the existing public behavior: + +- same middleware path in ``MIDDLEWARE``; +- same database and signal settings; +- same masking, content-type handling, truncation markers, policies, and + profiling payload shape; +- same ``APILogsModel`` schema and migrations; +- same signal payload keys, with correlation metadata only when correlation is + enabled. + +Request Context Isolation +------------------------- + +Request correlation uses Python ``contextvars``. In ASGI deployments this keeps +request IDs, trace IDs, route metadata, and logging context isolated between +concurrent requests. Use ``DRF_API_LOGGER_ENABLE_LOGGING_CONTEXT = True`` when +application logs inside the view need access to the same request context. + +.. code-block:: python + + DRF_API_LOGGER_SIGNAL = True + DRF_API_LOGGER_ENABLE_CORRELATION = True + DRF_API_LOGGER_ENABLE_LOGGING_CONTEXT = True + +Database Queue Behavior +----------------------- + +Database logging still enqueues records into the existing background worker. +The request coroutine does not perform bulk database insertion. Queue failures +are isolated so logging problems do not break the API response path. + +If database logging is enabled, continue to monitor: + +- ``queue_backlog`` +- ``dropped_count`` +- ``failed_insert_count`` +- ``inserted_count`` + +Testing ASGI Behavior +--------------------- + +The package tests ASGI behavior in ``tests/test_asgi_middleware.py``. Coverage +includes: + +- middleware sync and async capability declarations; +- direct async middleware calls; +- Django ``AsyncClient`` integration; +- signal logging and database enqueue behavior; +- queue failure isolation; +- concurrent request context isolation with ``contextvars``. + +Run the ASGI tests with: + +.. code-block:: bash + + python -m django test tests.test_asgi_middleware --settings=tests.test_settings --verbosity=2 + +Run the compatibility suite with: + +.. code-block:: bash + + python -m django test tests.test_asgi_middleware tests.test_middleware tests.test_backward_compat tests.test_correlation tests.test_integration --settings=tests.test_settings --verbosity=1 + +Application Smoke Test +---------------------- + +Applications can smoke test the ASGI signal path with Django's ``AsyncClient``: + +.. code-block:: python + + import json + from django.test import AsyncClient, override_settings + from drf_api_logger import API_LOGGER_SIGNAL + + async def test_api_logging_signal_path(): + events = [] + + def listener(**kwargs): + events.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + with override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + ): + response = await AsyncClient().post( + "/api/test/", + data=json.dumps({"password": "example-secret"}), + content_type="application/json", + ) + + assert response.status_code == 200 + assert events[0]["body"]["password"] == "***FILTERED***" + finally: + API_LOGGER_SIGNAL.listen -= listener + +Performance Notes +----------------- + +Measure sync and ASGI overhead in the target application before changing +production traffic. Compare these modes at minimum: + +- application baseline with DRF API Logger disabled; +- signal-only logging; +- database logging with normal queue settings; +- profiling enabled, if the deployment uses profiling. + +Use representative endpoints and report request count, concurrency, status +codes, average latency, p95 latency, p99 latency, and queue backlog. For local +demo validation, use ``J:\projects\drf-demo`` with the local package on +``PYTHONPATH`` so the demo imports the checkout being tested. + +The repository includes ``scripts/measure_asgi_overhead.py`` for a local +measurement pass through Django's sync ``Client`` and ASGI ``AsyncClient``. For +the demo project, run it from ``J:\projects\drf-demo`` with the checkout on +``PYTHONPATH``: + +.. code-block:: powershell + + $env:PYTHONPATH='J:\projects\DRF-API-Logger' + & 'J:\projects\drf-demo\venv\Scripts\python.exe' J:\projects\DRF-API-Logger\scripts\measure_asgi_overhead.py --settings config.settings --path /api/echo/ --requests 100 --concurrency 10 + +Attach the JSON output to the Jira story or release notes when using it as +release-readiness evidence. The script uses a synthetic payload and reports +only timing and status-code aggregates. diff --git a/docs/developer_testing.rst b/docs/developer_testing.rst index f7f530a..dfe178f 100644 --- a/docs/developer_testing.rst +++ b/docs/developer_testing.rst @@ -80,6 +80,7 @@ Coverage Expectations Add or update tests for every behavior change. Cover the touched surface: - Middleware request and response behavior. +- ASGI middleware behavior through direct async calls and Django ``AsyncClient``. - Sensitive data masking in bodies, responses, headers, and URL query parameters. - Signal listener behavior and exception isolation. @@ -96,6 +97,27 @@ Add or update tests for every behavior change. Cover the touched surface: - Management commands such as ``prune_api_logs``. - Backward compatibility for defaults and payloads. +ASGI Checks +----------- + +Run the ASGI-specific middleware tests when touching middleware, correlation, +queueing, profiling, or request/response capture: + +.. code-block:: bash + + python -m django test tests.test_asgi_middleware --settings=tests.test_settings --verbosity=2 + +These tests cover ``AsyncClient`` integration, concurrent ``contextvars`` +isolation, async database enqueue behavior, and queue failure isolation. + +For SCRUM-13-style release evidence, measure sync and ASGI overhead against the +demo project: + +.. code-block:: powershell + + $env:PYTHONPATH='J:\projects\DRF-API-Logger' + & 'J:\projects\drf-demo\venv\Scripts\python.exe' J:\projects\DRF-API-Logger\scripts\measure_asgi_overhead.py --settings config.settings --path /api/echo/ --requests 100 --concurrency 10 + Operational Test Surfaces ------------------------- diff --git a/docs/index.rst b/docs/index.rst index c0791c3..37df218 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -23,6 +23,7 @@ profile SQL-heavy endpoints when enabled. :hidden: quickstart + asgi observability_integrations policy_controls ai_readiness @@ -39,6 +40,7 @@ Key Features - Response information: status code, response body, and execution time - Automatic masking of sensitive data (passwords, tokens) - Non-blocking background processing with configurable queuing +- ASGI-native logging while preserving sync deployment compatibility - Database logging and/or real-time signal notifications - Built-in admin dashboard with charts and performance metrics - Per-request API profiling with auto-diagnosis of bottlenecks diff --git a/docs/operations.rst b/docs/operations.rst index 8922943..43d19d8 100644 --- a/docs/operations.rst +++ b/docs/operations.rst @@ -213,6 +213,26 @@ Recommended operating pattern: - Skip health checks and metrics endpoints with ``DRF_API_LOGGER_SKIP_URL_NAME`` or ``DRF_API_LOGGER_SKIP_NAMESPACE``. +ASGI Operations +--------------- + +ASGI deployments use the same ``APILoggerMiddleware`` configuration as sync +deployments. The middleware is async-capable and awaits Django's async response +chain directly when Django runs in ASGI mode. + +Recommended operating pattern: + +- Keep database logging on the background queue; request coroutines should not + perform bulk database insertion. +- Monitor ``queue_backlog``, ``dropped_count``, and ``failed_insert_count`` in + ASGI deployments the same way as sync deployments. +- Enable request correlation with ``contextvars`` when application logs need + per-request context inside async views. +- Validate with Django ``AsyncClient`` or the package's + ``tests/test_asgi_middleware.py`` before rollout. +- Compare baseline, signal-only, database, and profiling modes for average, + p95, and p99 latency in the target application. + Policy Control Operations ------------------------- diff --git a/docs/quickstart.rst b/docs/quickstart.rst index b0633bc..85ee6e8 100644 --- a/docs/quickstart.rst +++ b/docs/quickstart.rst @@ -196,6 +196,32 @@ Prometheus labels are limited to route, URL name, app name, namespace, status class, and method. Request IDs and trace IDs are available for logs, traces, and Sentry context, not metrics labels. +ASGI-Native Logging +------------------- + +Use the same middleware path for WSGI, sync Django, and ASGI deployments: + +.. code-block:: python + + MIDDLEWARE = [ + # ... + "drf_api_logger.middleware.api_logger_middleware.APILoggerMiddleware", + ] + +The middleware is both sync-capable and async-capable. In ASGI mode it awaits +Django's async ``get_response`` callable directly, while sync deployments remain +backward compatible. Enable correlation when concurrent async requests need +isolated request IDs or trace IDs: + +.. code-block:: python + + DRF_API_LOGGER_SIGNAL = True + DRF_API_LOGGER_ENABLE_CORRELATION = True + DRF_API_LOGGER_ENABLE_LOGGING_CONTEXT = True + +Validate ASGI behavior with ``tests/test_asgi_middleware.py`` or an application +``AsyncClient`` smoke test. See :doc:`asgi` for the full checklist. + Policy Controls --------------- diff --git a/drf_api_logger/middleware/api_logger_middleware.py b/drf_api_logger/middleware/api_logger_middleware.py index ce5c59e..32f188b 100644 --- a/drf_api_logger/middleware/api_logger_middleware.py +++ b/drf_api_logger/middleware/api_logger_middleware.py @@ -4,6 +4,7 @@ import time import uuid +from asgiref.sync import iscoroutinefunction, markcoroutinefunction from django.conf import settings from django.urls import resolve from django.utils import timezone @@ -22,8 +23,14 @@ class APILoggerMiddleware: + sync_capable = True + async_capable = True + def __init__(self, get_response): self.get_response = get_response + self.async_mode = iscoroutinefunction(get_response) + if self.async_mode: + markcoroutinefunction(self) # One-time configuration and initialization. self.DRF_API_LOGGER_DATABASE = False @@ -272,227 +279,304 @@ def _policy_api(self, decision, request, api): return getattr(request, 'path', '') or '' return api + def _safe_queue_log_data(self, data): + try: + logger_apps.LOGGER_THREAD.put_log_data(data=data) + except Exception: + return False + return True + + def _api_logger_enabled(self): + return self.DRF_API_LOGGER_DATABASE or self.DRF_API_LOGGER_SIGNAL + + def _resolve_request(self, request): + try: + resolver_match = resolve(request.path_info) + return resolver_match, resolver_match.url_name, resolver_match.namespace + except Exception: + return None, None, None + + def _should_skip_resolved_request(self, url_name, namespace): + if namespace == 'admin': + return True + if url_name in self.DRF_API_LOGGER_SKIP_URL_NAME: + return True + if namespace in self.DRF_API_LOGGER_SKIP_NAMESPACE: + return True + return False + + def _build_tracing_id(self, headers): + if not self.DRF_API_LOGGER_ENABLE_TRACING: + return None + tracing_id = None + if self.DRF_API_LOGGER_TRACING_ID_HEADER_NAME: + tracing_id = headers.get(self.DRF_API_LOGGER_TRACING_ID_HEADER_NAME) + if tracing_id: + return tracing_id + if self.tracing_func_name: + return self.tracing_func_name() + return str(uuid.uuid4()) + + def _start_sql_profiling(self, profile_this_request): + if not profile_this_request or not self.DRF_API_LOGGER_PROFILING_SQL_TRACKING: + return None + from django.db import connection, reset_queries + original_force_debug_cursor = connection.force_debug_cursor + connection.force_debug_cursor = True + reset_queries() + return connection, reset_queries, original_force_debug_cursor + + def _finish_sql_profiling(self, sql_profiling): + if not sql_profiling: + return None + connection, reset_queries, original_force_debug_cursor = sql_profiling + try: + queries = connection.queries[:] + sql_total_time = sum(float(query.get('time', 0)) for query in queries) + return { + 'total_time': round(sql_total_time, 5), + 'query_count': len(queries), + } + finally: + connection.force_debug_cursor = original_force_debug_cursor + reset_queries() + + def _prepare_log_state(self, request): + resolver_match, url_name, namespace = self._resolve_request(request) + if self._should_skip_resolved_request(url_name, namespace): + return None + + start_time = time.time() + middleware_before_start = time.time() + headers = get_headers(request=request) + request_data = self._get_request_data(request) + tracing_id = self._build_tracing_id(headers) + if tracing_id: + request.tracing_id = tracing_id + middleware_before_end = time.time() + + correlation_context = {} + low_cardinality = {} + logging_context_set = False + if self.DRF_API_LOGGER_ENABLE_CORRELATION: + correlation_context = build_correlation_context( + request=request, + headers=headers, + resolver_match=resolver_match, + tracing_id=tracing_id, + ) + low_cardinality = self._attach_correlation_context(request, correlation_context) + if self.DRF_API_LOGGER_ENABLE_LOGGING_CONTEXT: + set_correlation_context(correlation_context) + logging_context_set = True + + profile_this_request = self._should_profile() + + return { + 'resolver_match': resolver_match, + 'start_time': start_time, + 'middleware_before_start': middleware_before_start, + 'middleware_before_end': middleware_before_end, + 'headers': headers, + 'method': request.method, + 'request_data': request_data, + 'tracing_id': tracing_id, + 'correlation_context': correlation_context, + 'low_cardinality': low_cardinality, + 'logging_context_set': logging_context_set, + 'profile_this_request': profile_this_request, + 'sql_profiling': self._start_sql_profiling(profile_this_request), + 'sql_data': None, + 'view_end': None, + } + + def _finish_log_state_after_view(self, state, view_start): + state['view_end'] = time.time() + try: + state['sql_data'] = self._finish_sql_profiling(state['sql_profiling']) + finally: + if state['logging_context_set']: + clear_correlation_context() + + def _request_api(self, request): + if self.DRF_API_LOGGER_PATH_TYPE == 'FULL_PATH': + return request.get_full_path() + if self.DRF_API_LOGGER_PATH_TYPE == 'RAW_URI': + get_raw_uri = getattr(request, 'get_raw_uri', None) + if get_raw_uri: + return get_raw_uri() + return request.build_absolute_uri(request.get_full_path()) + return request.build_absolute_uri() + + def _current_time(self): + if settings.USE_TZ: + return timezone.now() + return datetime.now() + + def _build_log_data(self, request, response, state, policy_decision, policy_payload): + return dict( + api=mask_sensitive_data( + self._policy_api(policy_decision, request, self._request_api(request)), + mask_api_parameters=True, + extra_sensitive_keys=policy_decision.mask_keys, + ), + headers=mask_sensitive_data( + policy_payload['headers'], + extra_sensitive_keys=policy_decision.mask_keys, + ), + body=mask_sensitive_data( + policy_payload['request_data'], + extra_sensitive_keys=policy_decision.mask_keys, + ), + method=state['method'], + client_ip_address=get_client_ip(request), + response=mask_sensitive_data( + policy_payload['response_body'], + extra_sensitive_keys=policy_decision.mask_keys, + ), + status_code=response.status_code, + execution_time=time.time() - state['start_time'], + added_on=self._current_time(), + ) + + def _add_profiling_data(self, data, state, middleware_after_start): + if not state['profile_this_request']: + return + sql_data = state['sql_data'] + profiling = { + 'middleware_before_view': round( + state['middleware_before_end'] - state['middleware_before_start'], 5 + ), + 'view_and_serialization': round( + state['view_end'] - state['view_start'], 5 + ), + 'middleware_after_view': round(time.time() - middleware_after_start, 5), + } + if sql_data: + profiling['sql'] = sql_data + data['profiling_data'] = profiling + data['sql_query_count'] = sql_data['query_count'] if sql_data else None + + def _database_payload(self, data, request_data): + database_data = data.copy() + database_data['headers'] = ( + json.dumps(database_data['headers'], indent=4, ensure_ascii=False) + if database_data.get('headers') else '' + ) + if request_data: + database_data['body'] = ( + json.dumps(database_data['body'], indent=4, ensure_ascii=False) + if database_data.get('body') else '' + ) + database_data['response'] = ( + json.dumps(database_data['response'], indent=4, ensure_ascii=False) + if database_data.get('response') else '' + ) + if database_data.get('profiling_data'): + database_data['profiling_data'] = json.dumps( + database_data['profiling_data'], + indent=4, + ensure_ascii=False, + ) + return database_data + + def _emit_log_data(self, data, state, policy_decision): + if policy_decision.database and self.DRF_API_LOGGER_DATABASE and logger_apps.LOGGER_THREAD: + self._safe_queue_log_data( + self._database_payload(data, state['request_data']) + ) + if policy_decision.signal and self.DRF_API_LOGGER_SIGNAL: + signal_data = data.copy() + if state['tracing_id']: + signal_data.update({'tracing_id': state['tracing_id']}) + if state['correlation_context']: + signal_data.update({ + 'correlation': state['correlation_context'].copy(), + 'low_cardinality': state['low_cardinality'].copy(), + }) + if getattr(settings, 'DRF_API_LOGGER_POLICY', None) or getattr( + settings, 'DRF_API_LOGGER_POLICY_FUNC', None + ): + signal_data.update({'policy': policy_decision.to_signal_metadata()}) + API_LOGGER_SIGNAL.listen(**signal_data) + + def _finalize_log_response(self, request, response, state): + if self.DRF_API_LOGGER_STATUS_CODES and response.status_code not in self.DRF_API_LOGGER_STATUS_CODES: + return response + if len(self.DRF_API_LOGGER_METHODS) > 0 and state['method'] not in self.DRF_API_LOGGER_METHODS: + return response + if not self._should_log_response_content_type(response): + return response + + response_body = self._get_response_body(response) + middleware_after_start = time.time() + + if self.DRF_API_LOGGER_ENABLE_CORRELATION: + state['correlation_context'] = build_correlation_context( + request=request, + headers=state['headers'], + resolver_match=state['resolver_match'], + status_code=response.status_code, + tracing_id=state['tracing_id'], + ) + state['low_cardinality'] = self._attach_correlation_context( + request, + state['correlation_context'], + ) + + policy_decision = safe_evaluate_logging_policy( + request=request, + response=response, + resolver_match=state['resolver_match'], + correlation_context=state['correlation_context'], + low_cardinality=state['low_cardinality'], + ) + if not policy_decision.log: + return response + + policy_payload = self._policy_payload( + policy_decision, + state['headers'], + state['request_data'], + response_body, + ) + data = self._build_log_data(request, response, state, policy_decision, policy_payload) + self._add_profiling_data(data, state, middleware_after_start) + self._emit_log_data(data, state, policy_decision) + return response + def __call__(self, request): - # Skip logging for static and media files + if self.async_mode: + return self.__acall__(request) if self.is_static_or_media_request(request.path): return self.get_response(request) + if not self._api_logger_enabled(): + return self.get_response(request) - # Run only if logger is enabled. - if self.DRF_API_LOGGER_DATABASE or self.DRF_API_LOGGER_SIGNAL: + state = self._prepare_log_state(request) + if state is None: + return self.get_response(request) - resolver_match = None - try: - resolver_match = resolve(request.path_info) - url_name = resolver_match.url_name - namespace = resolver_match.namespace - except Exception: - url_name = None - namespace = None - - # Always skip Admin panel - if namespace == 'admin': - return self.get_response(request) - - # Skip for url name - if url_name in self.DRF_API_LOGGER_SKIP_URL_NAME: - return self.get_response(request) - - # Skip entire app using namespace - if namespace in self.DRF_API_LOGGER_SKIP_NAMESPACE: - return self.get_response(request) - - start_time = time.time() - middleware_before_start = time.time() - - headers = get_headers(request=request) - method = request.method - - request_data = self._get_request_data(request) - - tracing_id = None - if self.DRF_API_LOGGER_ENABLE_TRACING: - if self.DRF_API_LOGGER_TRACING_ID_HEADER_NAME: - tracing_id = headers.get(self.DRF_API_LOGGER_TRACING_ID_HEADER_NAME) - if not tracing_id: - if self.tracing_func_name: - tracing_id = self.tracing_func_name() - else: - tracing_id = str(uuid.uuid4()) - request.tracing_id = tracing_id - - middleware_before_end = time.time() - - correlation_context = {} - low_cardinality = {} - logging_context_set = False - if self.DRF_API_LOGGER_ENABLE_CORRELATION: - correlation_context = build_correlation_context( - request=request, - headers=headers, - resolver_match=resolver_match, - tracing_id=tracing_id, - ) - low_cardinality = self._attach_correlation_context(request, correlation_context) - if self.DRF_API_LOGGER_ENABLE_LOGGING_CONTEXT: - set_correlation_context(correlation_context) - logging_context_set = True - - # Set up SQL tracking before calling the view - profile_this_request = self._should_profile() - sql_profiling_active = ( - profile_this_request - and self.DRF_API_LOGGER_PROFILING_SQL_TRACKING - ) - sql_data = None - if sql_profiling_active: - from django.db import connection, reset_queries - original_force_debug_cursor = connection.force_debug_cursor - connection.force_debug_cursor = True - reset_queries() - - view_start = time.time() - try: - response = self.get_response(request) - finally: - view_end = time.time() - if sql_profiling_active: - try: - queries = connection.queries[:] - sql_total_time = sum(float(q.get('time', 0)) for q in queries) - sql_query_count = len(queries) - sql_data = { - 'total_time': round(sql_total_time, 5), - 'query_count': sql_query_count, - } - finally: - connection.force_debug_cursor = original_force_debug_cursor - reset_queries() - if logging_context_set: - clear_correlation_context() - - # Only log required status codes if matching - if self.DRF_API_LOGGER_STATUS_CODES and response.status_code not in self.DRF_API_LOGGER_STATUS_CODES: - return response - - # Log only registered methods if available. - if len(self.DRF_API_LOGGER_METHODS) > 0 and method not in self.DRF_API_LOGGER_METHODS: - return response - - if self._should_log_response_content_type(response): - response_body = self._get_response_body(response) - if self.DRF_API_LOGGER_PATH_TYPE == 'ABSOLUTE': - api = request.build_absolute_uri() - elif self.DRF_API_LOGGER_PATH_TYPE == 'FULL_PATH': - api = request.get_full_path() - elif self.DRF_API_LOGGER_PATH_TYPE == 'RAW_URI': - api = request.get_raw_uri() - else: - api = request.build_absolute_uri() - - # Get the current time in a timezone-aware manner - if settings.USE_TZ: - current_time = timezone.now() - else: - current_time = datetime.now() - - middleware_after_start = time.time() - - if self.DRF_API_LOGGER_ENABLE_CORRELATION: - correlation_context = build_correlation_context( - request=request, - headers=headers, - resolver_match=resolver_match, - status_code=response.status_code, - tracing_id=tracing_id, - ) - low_cardinality = self._attach_correlation_context(request, correlation_context) - - policy_decision = safe_evaluate_logging_policy( - request=request, - response=response, - resolver_match=resolver_match, - correlation_context=correlation_context, - low_cardinality=low_cardinality, - ) - if not policy_decision.log: - return response - - policy_payload = self._policy_payload( - policy_decision, - headers, - request_data, - response_body, - ) - - data = dict( - api=mask_sensitive_data( - self._policy_api(policy_decision, request, api), - mask_api_parameters=True, - extra_sensitive_keys=policy_decision.mask_keys, - ), - headers=mask_sensitive_data( - policy_payload['headers'], - extra_sensitive_keys=policy_decision.mask_keys, - ), - body=mask_sensitive_data( - policy_payload['request_data'], - extra_sensitive_keys=policy_decision.mask_keys, - ), - method=method, - client_ip_address=get_client_ip(request), - response=mask_sensitive_data( - policy_payload['response_body'], - extra_sensitive_keys=policy_decision.mask_keys, - ), - status_code=response.status_code, - execution_time=time.time() - start_time, - added_on=current_time - ) - - middleware_after_end = time.time() - - # Build profiling data if enabled - profiling = None - if profile_this_request: - profiling = { - 'middleware_before_view': round(middleware_before_end - middleware_before_start, 5), - 'view_and_serialization': round(view_end - view_start, 5), - 'middleware_after_view': round(middleware_after_end - middleware_after_start, 5), - } - if sql_data: - profiling['sql'] = sql_data - data['profiling_data'] = profiling - data['sql_query_count'] = sql_data['query_count'] if sql_data else None - - if policy_decision.database and self.DRF_API_LOGGER_DATABASE and logger_apps.LOGGER_THREAD: - d = data.copy() - d['headers'] = json.dumps(d['headers'], indent=4, ensure_ascii=False) if d.get('headers') else '' - if request_data: - d['body'] = json.dumps(d['body'], indent=4, ensure_ascii=False) if d.get('body') else '' - d['response'] = json.dumps(d['response'], indent=4, ensure_ascii=False) if d.get('response') else '' - if d.get('profiling_data'): - d['profiling_data'] = json.dumps(d['profiling_data'], indent=4, ensure_ascii=False) - logger_apps.LOGGER_THREAD.put_log_data(data=d) - if policy_decision.signal and self.DRF_API_LOGGER_SIGNAL: - signal_data = data.copy() - if tracing_id: - signal_data.update({ - 'tracing_id': tracing_id - }) - if correlation_context: - signal_data.update({ - 'correlation': correlation_context.copy(), - 'low_cardinality': low_cardinality.copy(), - }) - if getattr(settings, 'DRF_API_LOGGER_POLICY', None) or getattr( - settings, 'DRF_API_LOGGER_POLICY_FUNC', None - ): - signal_data.update({ - 'policy': policy_decision.to_signal_metadata(), - }) - API_LOGGER_SIGNAL.listen(**signal_data) - else: - return response - else: + state['view_start'] = time.time() + try: response = self.get_response(request) - return response + finally: + self._finish_log_state_after_view(state, state['view_start']) + return self._finalize_log_response(request, response, state) + + async def __acall__(self, request): + if self.is_static_or_media_request(request.path): + return await self.get_response(request) + if not self._api_logger_enabled(): + return await self.get_response(request) + + state = self._prepare_log_state(request) + if state is None: + return await self.get_response(request) + + state['view_start'] = time.time() + try: + response = await self.get_response(request) + finally: + self._finish_log_state_after_view(state, state['view_start']) + return self._finalize_log_response(request, response, state) diff --git a/scripts/measure_asgi_overhead.py b/scripts/measure_asgi_overhead.py new file mode 100644 index 0000000..0df5bd8 --- /dev/null +++ b/scripts/measure_asgi_overhead.py @@ -0,0 +1,203 @@ +"""Measure sync and ASGI DRF API Logger overhead with Django test clients. + +This script is intended for application-level smoke benchmarks. It does not +start a server; it imports the target Django settings module and exercises the +configured middleware stack through Django's sync Client and AsyncClient. +""" + +import argparse +import asyncio +import json +import os +import sys +import time +from collections import Counter + + +def percentile(values, percent): + if not values: + return 0.0 + ordered = sorted(values) + index = round((len(ordered) - 1) * percent) + return ordered[index] + + +def summarize(label, durations, statuses): + return { + "label": label, + "requests": len(durations), + "status_counts": dict(sorted(Counter(statuses).items())), + "avg_ms": round((sum(durations) / len(durations)) * 1000, 3) if durations else 0.0, + "p95_ms": round(percentile(durations, 0.95) * 1000, 3), + "p99_ms": round(percentile(durations, 0.99) * 1000, 3), + } + + +def request_sync(client, method, path, body, content_type): + if method == "GET": + return client.get(path) + return client.post(path, data=body, content_type=content_type) + + +async def request_async(client, method, path, body, content_type): + if method == "GET": + return await client.get(path) + return await client.post(path, data=body, content_type=content_type) + + +def run_sync_case(label, method, path, requests, body, content_type, signal_enabled): + from django.test import Client, override_settings + from drf_api_logger import API_LOGGER_SIGNAL + + durations = [] + statuses = [] + + def listener(**kwargs): + return None + + API_LOGGER_SIGNAL.listen += listener + try: + with override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=signal_enabled, + ): + client = Client() + for _ in range(requests): + started = time.perf_counter() + response = request_sync(client, method, path, body, content_type) + durations.append(time.perf_counter() - started) + statuses.append(response.status_code) + finally: + API_LOGGER_SIGNAL.listen -= listener + + return summarize(label, durations, statuses) + + +async def run_async_case(label, method, path, requests, concurrency, body, content_type, signal_enabled): + from django.test import AsyncClient, override_settings + from drf_api_logger import API_LOGGER_SIGNAL + + durations = [] + statuses = [] + lock = asyncio.Lock() + semaphore = asyncio.Semaphore(concurrency) + + def listener(**kwargs): + return None + + async def one_request(client): + async with semaphore: + started = time.perf_counter() + response = await request_async(client, method, path, body, content_type) + duration = time.perf_counter() - started + async with lock: + durations.append(duration) + statuses.append(response.status_code) + + API_LOGGER_SIGNAL.listen += listener + try: + with override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=signal_enabled, + ): + client = AsyncClient() + await asyncio.gather(*(one_request(client) for _ in range(requests))) + finally: + API_LOGGER_SIGNAL.listen -= listener + + return summarize(label, durations, statuses) + + +def add_overhead(results): + by_label = {item["label"]: item for item in results} + sync_signal = by_label["sync_signal"]["avg_ms"] + asgi_signal = by_label["asgi_signal"]["avg_ms"] + sync_baseline = by_label["sync_baseline"]["avg_ms"] + asgi_baseline = by_label["asgi_baseline"]["avg_ms"] + return { + "sync_signal_over_sync_baseline_avg_ms": round(sync_signal - sync_baseline, 3), + "asgi_signal_over_asgi_baseline_avg_ms": round(asgi_signal - asgi_baseline, 3), + "asgi_signal_over_sync_signal_avg_ms": round(asgi_signal - sync_signal, 3), + } + + +def parse_args(): + parser = argparse.ArgumentParser( + description="Measure DRF API Logger sync and ASGI overhead with Django test clients." + ) + parser.add_argument("--settings", help="Django settings module, for example config.settings.") + parser.add_argument("--path", default="/api/echo/", help="Endpoint path to exercise.") + parser.add_argument("--method", choices=["GET", "POST"], default="POST") + parser.add_argument("--requests", type=int, default=100) + parser.add_argument("--concurrency", type=int, default=10) + parser.add_argument( + "--body", + default=json.dumps({"safe": "visible", "password": "example-secret"}), + help="POST body. Keep this synthetic; do not benchmark with real secrets.", + ) + parser.add_argument("--content-type", default="application/json") + return parser.parse_args() + + +def main(): + args = parse_args() + sys.path.insert(0, os.getcwd()) + if args.settings: + os.environ["DJANGO_SETTINGS_MODULE"] = args.settings + if not os.environ.get("DJANGO_SETTINGS_MODULE"): + raise SystemExit("Set DJANGO_SETTINGS_MODULE or pass --settings.") + + import django + + django.setup() + + results = [ + run_sync_case( + "sync_baseline", + args.method, + args.path, + args.requests, + args.body, + args.content_type, + signal_enabled=False, + ), + run_sync_case( + "sync_signal", + args.method, + args.path, + args.requests, + args.body, + args.content_type, + signal_enabled=True, + ), + asyncio.run( + run_async_case( + "asgi_baseline", + args.method, + args.path, + args.requests, + args.concurrency, + args.body, + args.content_type, + signal_enabled=False, + ) + ), + asyncio.run( + run_async_case( + "asgi_signal", + args.method, + args.path, + args.requests, + args.concurrency, + args.body, + args.content_type, + signal_enabled=True, + ) + ), + ] + + print(json.dumps({"results": results, "overhead": add_overhead(results)}, indent=2)) + + +if __name__ == "__main__": + main() diff --git a/tests/README.md b/tests/README.md index 9c405bd..1d6c382 100644 --- a/tests/README.md +++ b/tests/README.md @@ -6,6 +6,7 @@ This directory contains the package test suite. - `test_utils.py`: utility helpers, masking, headers, and settings. - `test_middleware.py`: middleware configuration, filtering, tracing, content handling, and body limits. +- `test_asgi_middleware.py`: ASGI middleware capability, AsyncClient integration, async logging, and context isolation. - `test_models.py`: database model and Django admin behavior. - `test_signals.py`: event listeners, background queue processing, app startup, and worker stats. - `test_profiling.py`: profiling settings, SQL tracking, admin display, and diagnosis rules. diff --git a/tests/test_asgi_middleware.py b/tests/test_asgi_middleware.py new file mode 100644 index 0000000..ba099b9 --- /dev/null +++ b/tests/test_asgi_middleware.py @@ -0,0 +1,577 @@ +import asyncio +import json +from unittest.mock import Mock, patch + +from asgiref.sync import iscoroutinefunction +from django.http import HttpResponse, JsonResponse, StreamingHttpResponse +from django.test import AsyncClient, AsyncRequestFactory, SimpleTestCase +from django.test.utils import override_settings + +from drf_api_logger import API_LOGGER_SIGNAL +from drf_api_logger.insert_log_into_database import InsertLogIntoDatabase +from drf_api_logger.logging_context import ( + clear_correlation_context, + get_correlation_context, +) +from drf_api_logger.middleware.api_logger_middleware import APILoggerMiddleware + + +def async_test_trace_id(): + return "trace-from-async-test-func" + + +class AsyncAPILoggerMiddlewareTests(SimpleTestCase): + def setUp(self): + self.factory = AsyncRequestFactory() + + def tearDown(self): + clear_correlation_context() + + async def async_response(self, request): + return JsonResponse({"ok": True}) + + def test_middleware_declares_sync_and_async_capability(self): + middleware = APILoggerMiddleware(get_response=self.async_response) + + self.assertTrue(APILoggerMiddleware.sync_capable) + self.assertTrue(APILoggerMiddleware.async_capable) + self.assertTrue(iscoroutinefunction(middleware)) + + @override_settings(DRF_API_LOGGER_DATABASE=False, DRF_API_LOGGER_SIGNAL=True) + async def test_async_signal_logging_captures_masked_payload(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def async_response(request): + return JsonResponse({ + "ok": True, + "password": "response-secret", + }) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=async_response) + request = self.factory.post( + "/api/test/?token=query-secret", + data=json.dumps({ + "password": "request-secret", + "safe": "visible", + }), + content_type="application/json", + ) + + response = await middleware(request) + + self.assertEqual(response.status_code, 200) + self.assertEqual(len(signal_data), 1) + event = signal_data[0] + self.assertEqual(event["method"], "POST") + self.assertIn("token=***FILTERED***", event["api"]) + self.assertEqual(event["body"]["password"], "***FILTERED***") + self.assertEqual(event["body"]["safe"], "visible") + self.assertEqual(event["response"]["password"], "***FILTERED***") + self.assertNotIn("query-secret", str(event)) + self.assertNotIn("request-secret", str(event)) + self.assertNotIn("response-secret", str(event)) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings(DRF_API_LOGGER_DATABASE=True, DRF_API_LOGGER_SIGNAL=False) + async def test_async_database_logging_enqueues_masked_payload(self): + async def async_response(request): + return JsonResponse({"ok": True}) + + with patch("drf_api_logger.apps.LOGGER_THREAD") as mock_thread: + mock_thread.put_log_data = Mock() + middleware = APILoggerMiddleware(get_response=async_response) + request = self.factory.post( + "/api/test/", + data=json.dumps({ + "password": "request-secret", + "safe": "visible", + }), + content_type="application/json", + ) + + response = await middleware(request) + + self.assertEqual(response.status_code, 200) + mock_thread.put_log_data.assert_called_once() + event = mock_thread.put_log_data.call_args[1]["data"] + self.assertEqual(event["method"], "POST") + self.assertIn('"password": "***FILTERED***"', event["body"]) + self.assertIn('"safe": "visible"', event["body"]) + self.assertNotIn("request-secret", str(event)) + + @override_settings(DRF_API_LOGGER_DATABASE=True, DRF_API_LOGGER_SIGNAL=False) + async def test_async_database_logging_failure_does_not_break_response(self): + async def async_response(request): + return JsonResponse({"ok": True}) + + with patch("drf_api_logger.apps.LOGGER_THREAD") as mock_thread: + mock_thread.put_log_data.side_effect = RuntimeError( + "database unavailable with Authorization=Bearer secret-token" + ) + middleware = APILoggerMiddleware(get_response=async_response) + request = self.factory.get("/api/test/") + + response = await middleware(request) + + self.assertEqual(response.status_code, 200) + + @override_settings(DRF_API_LOGGER_DATABASE=False, DRF_API_LOGGER_SIGNAL=False) + async def test_async_logger_disabled_awaits_response_without_logging_setup(self): + called = [] + + async def async_response(request): + called.append(True) + return JsonResponse({"ok": True}) + + middleware = APILoggerMiddleware(get_response=async_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(called, [True]) + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_SKIP_URL_NAME=["skip_me"], + ) + async def test_async_skip_url_name_awaits_response_without_emitting_signal(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def async_response(request): + return JsonResponse({"ok": True}) + + API_LOGGER_SIGNAL.listen += listener + try: + with patch("drf_api_logger.middleware.api_logger_middleware.resolve") as mock_resolve: + mock_resolve.return_value.namespace = None + mock_resolve.return_value.url_name = "skip_me" + middleware = APILoggerMiddleware(get_response=async_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(signal_data, []) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + STATIC_URL="/static/", + MEDIA_URL="/media/", + ) + async def test_async_static_request_awaits_response_without_emitting_signal(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.async_response) + response = await middleware(self.factory.get("/static/test.css")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(signal_data, []) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_STATUS_CODES=[201], + ) + async def test_async_status_code_filter_skips_signal(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.async_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(signal_data, []) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_METHODS=["POST"], + ) + async def test_async_method_filter_skips_signal(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.async_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(signal_data, []) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings(DRF_API_LOGGER_DATABASE=False, DRF_API_LOGGER_SIGNAL=True) + async def test_async_unsupported_response_content_type_skips_signal(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def html_response(request): + return HttpResponse("

ok

", content_type="text/html", status=200) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=html_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(signal_data, []) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_PATH_TYPE="FULL_PATH", + ) + async def test_async_full_path_setting_controls_logged_api(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.async_response) + response = await middleware(self.factory.get("/api/test/?token=query-secret")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(signal_data[0]["api"], "/api/test/?token=***FILTERED***") + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_PATH_TYPE="RAW_URI", + ) + async def test_async_raw_uri_setting_controls_logged_api(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.async_response) + response = await middleware(self.factory.get("/api/test/?token=query-secret")) + + self.assertEqual(response.status_code, 200) + self.assertIn("/api/test/?token=***FILTERED***", signal_data[0]["api"]) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_ENABLE_TRACING=True, + DRF_API_LOGGER_TRACING_FUNC="tests.test_asgi_middleware.async_test_trace_id", + ) + async def test_async_tracing_function_sets_request_and_signal_trace_id(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.async_response) + request = self.factory.get("/api/test/") + response = await middleware(request) + + self.assertEqual(response.status_code, 200) + self.assertEqual(request.tracing_id, "trace-from-async-test-func") + self.assertEqual(signal_data[0]["tracing_id"], "trace-from-async-test-func") + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_CONTENT_TYPES=["text/plain"], + ) + async def test_async_text_content_type_and_json_charset_are_logged(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def text_response(request): + return HttpResponse("plain response", content_type="text/plain", status=200) + + async def json_charset_response(request): + return HttpResponse( + json.dumps({"message": "ok"}), + content_type="application/json; charset=utf-8", + status=200, + ) + + API_LOGGER_SIGNAL.listen += listener + try: + text_middleware = APILoggerMiddleware(get_response=text_response) + text_request = self.factory.post( + "/api/test/", + data="plain request", + content_type="text/plain", + ) + text_result = await text_middleware(text_request) + + json_middleware = APILoggerMiddleware(get_response=json_charset_response) + json_request = self.factory.get("/api/test/") + json_result = await json_middleware(json_request) + + self.assertEqual(text_result.status_code, 200) + self.assertEqual(json_result.status_code, 200) + self.assertEqual(signal_data[0]["body"], "plain request") + self.assertEqual(signal_data[0]["response"], "plain response") + self.assertEqual(signal_data[1]["response"], {"message": "ok"}) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings(DRF_API_LOGGER_DATABASE=False, DRF_API_LOGGER_SIGNAL=True) + async def test_async_special_response_markers_match_sync_path(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def streaming_response(request): + return StreamingHttpResponse( + iter([b'{"ok": true}']), + content_type="application/json", + status=200, + ) + + async def gzip_response(request): + return HttpResponse(b"gzip-bytes", content_type="application/gzip", status=200) + + async def binary_response(request): + return HttpResponse( + b"binary-bytes", + content_type="application/octet-stream", + status=200, + ) + + async def calendar_response(request): + return HttpResponse( + b"BEGIN:VCALENDAR", + content_type="text/calendar", + status=200, + ) + + API_LOGGER_SIGNAL.listen += listener + try: + for response_func in ( + streaming_response, + gzip_response, + binary_response, + calendar_response, + ): + middleware = APILoggerMiddleware(get_response=response_func) + response = await middleware(self.factory.get("/api/test/")) + self.assertEqual(response.status_code, 200) + + self.assertEqual( + [event["response"] for event in signal_data], + [ + "** Streaming **", + "** GZIP Archive **", + "** Binary File **", + "** Calendar **", + ], + ) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_MAX_REQUEST_BODY_SIZE=20, + DRF_API_LOGGER_MAX_RESPONSE_BODY_SIZE=20, + ) + async def test_async_request_and_response_truncation_markers_match_sync_path(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def large_response(request): + return JsonResponse({"data": "x" * 100}) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=large_response) + request = self.factory.post( + "/api/test/", + data=json.dumps({"data": "x" * 100}), + content_type="application/json", + ) + + response = await middleware(request) + + self.assertEqual(response.status_code, 200) + self.assertIn("Request body truncated", signal_data[0]["body"]) + self.assertIn("Response body truncated", signal_data[0]["response"]) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings(DRF_API_LOGGER_DATABASE=True, DRF_API_LOGGER_SIGNAL=False) + async def test_async_database_logging_custom_handler_drop_updates_worker_stats(self): + async def async_response(request): + return JsonResponse({"ok": True}) + + worker = InsertLogIntoDatabase() + worker.custom_handler = lambda data: None + + with patch("drf_api_logger.apps.LOGGER_THREAD", worker): + middleware = APILoggerMiddleware(get_response=async_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + status = worker.get_status() + self.assertEqual(status["dropped_count"], 1) + self.assertEqual(status["queue_backlog"], 0) + + @override_settings( + DRF_API_LOGGER_DATABASE=True, + DRF_API_LOGGER_SIGNAL=False, + DRF_LOGGER_QUEUE_MAX_SIZE=1, + ) + async def test_async_database_logging_wakes_worker_at_batch_threshold(self): + async def async_response(request): + return JsonResponse({"ok": True}) + + worker = InsertLogIntoDatabase() + + with patch("drf_api_logger.apps.LOGGER_THREAD", worker): + middleware = APILoggerMiddleware(get_response=async_response) + response = await middleware(self.factory.get("/api/test/")) + + self.assertEqual(response.status_code, 200) + status = worker.get_status() + self.assertEqual(status["queue_backlog"], 1) + self.assertTrue(worker._flush_event.is_set()) + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_ENABLE_CORRELATION=True, + DRF_API_LOGGER_ENABLE_LOGGING_CONTEXT=True, + ) + async def test_concurrent_async_requests_keep_correlation_context_isolated(self): + captured = {} + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + async def async_response(request): + request_id = request.api_logger_request_id + before_yield = get_correlation_context() + await asyncio.sleep(0) + after_yield = get_correlation_context() + captured[request_id] = { + "request": request.api_logger_correlation.copy(), + "before_yield": before_yield, + "after_yield": after_yield, + } + return JsonResponse({"request_id": request_id}) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=async_response) + request_one = self.factory.get( + "/api/test/", + headers={ + "x-request-id": "req-one", + "x-trace-id": "trace-one", + }, + ) + request_two = self.factory.get( + "/api/test/", + headers={ + "x-request-id": "req-two", + "x-trace-id": "trace-two", + }, + ) + + responses = await asyncio.gather( + middleware(request_one), + middleware(request_two), + ) + + self.assertEqual([response.status_code for response in responses], [200, 200]) + self.assertEqual(captured["req-one"]["request"]["trace_id"], "trace-one") + self.assertEqual(captured["req-two"]["request"]["trace_id"], "trace-two") + self.assertEqual(captured["req-one"]["before_yield"]["request_id"], "req-one") + self.assertEqual(captured["req-two"]["before_yield"]["request_id"], "req-two") + self.assertEqual(captured["req-one"]["after_yield"]["trace_id"], "trace-one") + self.assertEqual(captured["req-two"]["after_yield"]["trace_id"], "trace-two") + self.assertEqual(get_correlation_context(), {}) + + signal_by_request_id = { + event["correlation"]["request_id"]: event + for event in signal_data + } + self.assertEqual(signal_by_request_id["req-one"]["correlation"]["trace_id"], "trace-one") + self.assertEqual(signal_by_request_id["req-two"]["correlation"]["trace_id"], "trace-two") + self.assertNotIn("request_id", signal_by_request_id["req-one"]["low_cardinality"]) + self.assertNotIn("trace_id", signal_by_request_id["req-two"]["low_cardinality"]) + finally: + API_LOGGER_SIGNAL.listen -= listener + + +class AsyncAPILoggerClientIntegrationTests(SimpleTestCase): + def tearDown(self): + clear_correlation_context() + + @override_settings(DRF_API_LOGGER_DATABASE=False, DRF_API_LOGGER_SIGNAL=True) + async def test_async_client_exercises_middleware_signal_path(self): + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + response = await AsyncClient().post( + "/api/test/", + data=json.dumps({"password": "request-secret", "safe": "visible"}), + content_type="application/json", + ) + + self.assertEqual(response.status_code, 200) + self.assertEqual(len(signal_data), 1) + self.assertEqual(signal_data[0]["method"], "POST") + self.assertEqual(signal_data[0]["body"]["password"], "***FILTERED***") + self.assertEqual(signal_data[0]["body"]["safe"], "visible") + self.assertNotIn("request-secret", str(signal_data[0])) + finally: + API_LOGGER_SIGNAL.listen -= listener diff --git a/tests/test_docs_content.py b/tests/test_docs_content.py index d0ec2f9..726e20d 100644 --- a/tests/test_docs_content.py +++ b/tests/test_docs_content.py @@ -268,6 +268,40 @@ def test_doctor_command_is_documented(self): self.assertIn("tests/test_diagnostics.py", testing) self.assertIn("Production diagnostics", developer_testing) + def test_asgi_native_logging_is_documented(self): + index = read_text("docs/index.rst") + guide = read_text("docs/asgi.rst") + overhead_script = read_text("scripts/measure_asgi_overhead.py") + readme = read_text("README.md") + quickstart = read_text("docs/quickstart.rst") + operations = read_text("docs/operations.rst") + testing = read_text("TESTING.md") + developer_testing = read_text("docs/developer_testing.rst") + developer_testing_md = read_text("docs/DEVELOPER_TESTING.md") + + self.assertIsNotNone( + re.search(r"^\s+asgi\s*$", index, re.MULTILINE), + "asgi is missing from docs/index.rst toctree", + ) + + for phrase in ( + "ASGI-native logging", + "sync deployments remain backward compatible", + "contextvars", + "AsyncClient", + "tests/test_asgi_middleware.py", + "scripts/measure_asgi_overhead.py", + ): + with self.subTest(phrase=phrase): + self.assertIn(phrase, guide) + + self.assertIn("AsyncClient", overhead_script) + self.assertIn("sync", overhead_script) + self.assertIn("asgi", overhead_script.lower()) + + for content in (readme, quickstart, operations, testing, developer_testing, developer_testing_md): + self.assertIn("ASGI", content) + if __name__ == "__main__": unittest.main() diff --git a/tests/test_middleware.py b/tests/test_middleware.py index a8385b7..6f7cd13 100644 --- a/tests/test_middleware.py +++ b/tests/test_middleware.py @@ -46,6 +46,16 @@ def test_middleware_initialization(self): self.assertEqual(middleware.DRF_API_LOGGER_MAX_REQUEST_BODY_SIZE, 32768) self.assertEqual(middleware.DRF_API_LOGGER_MAX_RESPONSE_BODY_SIZE, 65536) + @override_settings(DRF_API_LOGGER_DATABASE=False, DRF_API_LOGGER_SIGNAL=False) + def test_sync_logger_disabled_bypasses_logging_setup(self): + """Test disabled logging still returns the response.""" + middleware = APILoggerMiddleware(get_response=self.get_response) + request = self.factory.get('/api/test/') + + response = middleware(request) + + self.assertEqual(response.status_code, 200) + @override_settings(DRF_API_LOGGER_DATABASE=True) def test_middleware_with_database_enabled(self): """Test middleware when database logging is enabled""" @@ -353,6 +363,36 @@ def listener(**kwargs): finally: API_LOGGER_SIGNAL.listen -= listener + @override_settings( + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_ENABLE_PROFILING=True, + DRF_API_LOGGER_PROFILING_SAMPLE_RATE=0.5 + ) + @patch('drf_api_logger.middleware.api_logger_middleware.random.random', return_value=0.1) + @patch('drf_api_logger.middleware.api_logger_middleware.resolve') + def test_profiling_sample_rate_uses_random_sampling(self, mock_resolve, mock_random): + """Test fractional profiling sample rates use random sampling.""" + mock_resolve.return_value.namespace = None + mock_resolve.return_value.url_name = 'test' + + signal_data = [] + from drf_api_logger import API_LOGGER_SIGNAL + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.get_response) + request = self.factory.get('/api/test/') + response = middleware(request) + + self.assertEqual(response.status_code, 200) + self.assertIn('profiling_data', signal_data[0]) + mock_random.assert_called_once() + finally: + API_LOGGER_SIGNAL.listen -= listener + @override_settings( DRF_API_LOGGER_SIGNAL=True, DRF_API_LOGGER_ENABLE_CORRELATION=True, @@ -465,6 +505,76 @@ def test_path_type_raw_uri(self, mock_resolve): middleware = APILoggerMiddleware(get_response=self.get_response) self.assertEqual(middleware.DRF_API_LOGGER_PATH_TYPE, 'RAW_URI') + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + DRF_API_LOGGER_PATH_TYPE='RAW_URI' + ) + @patch('drf_api_logger.middleware.api_logger_middleware.resolve') + def test_path_type_raw_uri_logs_with_request_raw_uri(self, mock_resolve): + """Test RAW_URI uses the sync request raw URI method when available.""" + mock_resolve.return_value.namespace = None + mock_resolve.return_value.url_name = 'test' + + from drf_api_logger import API_LOGGER_SIGNAL + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.get_response) + request = self.factory.get('/api/test/?token=query-secret') + response = middleware(request) + + self.assertEqual(response.status_code, 200) + self.assertIn('/api/test/?token=***FILTERED***', signal_data[0]['api']) + finally: + API_LOGGER_SIGNAL.listen -= listener + + @override_settings(DRF_API_LOGGER_PATH_TYPE='RAW_URI') + def test_raw_uri_helper_uses_request_get_raw_uri_when_available(self): + """Test RAW_URI keeps using request.get_raw_uri for sync requests.""" + middleware = APILoggerMiddleware(get_response=self.get_response) + + class RequestWithRawUri: + def get_raw_uri(self): + return 'raw://example.test/api/test/?token=query-secret' + + self.assertEqual( + middleware._request_api(RequestWithRawUri()), + 'raw://example.test/api/test/?token=query-secret', + ) + + @override_settings( + DRF_API_LOGGER_DATABASE=False, + DRF_API_LOGGER_SIGNAL=True, + USE_TZ=False + ) + @patch('drf_api_logger.middleware.api_logger_middleware.resolve') + def test_added_on_uses_naive_datetime_when_use_tz_false(self, mock_resolve): + """Test USE_TZ=False keeps backward-compatible naive timestamps.""" + mock_resolve.return_value.namespace = None + mock_resolve.return_value.url_name = 'test' + + from drf_api_logger import API_LOGGER_SIGNAL + signal_data = [] + + def listener(**kwargs): + signal_data.append(kwargs) + + API_LOGGER_SIGNAL.listen += listener + try: + middleware = APILoggerMiddleware(get_response=self.get_response) + request = self.factory.get('/api/test/') + response = middleware(request) + + self.assertEqual(response.status_code, 200) + self.assertIsNone(signal_data[0]['added_on'].tzinfo) + finally: + API_LOGGER_SIGNAL.listen -= listener + def test_json_request_body_parsing(self): """Test parsing of JSON request body""" request = self.factory.post('/api/test/', @@ -473,6 +583,46 @@ def test_json_request_body_parsing(self): response = self.middleware(request) self.assertEqual(response.status_code, 200) + def test_body_decoding_defensive_edges(self): + """Test body decoding handles malformed and inaccessible bodies.""" + middleware = APILoggerMiddleware(get_response=self.get_response) + + class RequestWithUnreadableBody: + META = {'CONTENT_TYPE': 'application/json'} + + @property + def body(self): + raise RuntimeError('body unavailable') + + class ResponseWithUnreadableContent: + streaming = False + + def get(self, key): + return 'application/json' + + @property + def content(self): + raise RuntimeError('content unavailable') + + self.assertEqual( + middleware._decode_body('plain request', -1, 'Request body', 'text/plain'), + 'plain request', + ) + self.assertEqual( + middleware._decode_body(b'\xff', -1, 'Request body', 'application/json'), + '', + ) + self.assertEqual( + middleware._decode_body(b'not-json', -1, 'Request body', 'application/json'), + '', + ) + self.assertEqual( + middleware._decode_body(b'not-json', -1, 'Request body', 'application/octet-stream'), + '', + ) + self.assertEqual(middleware._get_request_data(RequestWithUnreadableBody()), '') + self.assertEqual(middleware._get_response_body(ResponseWithUnreadableContent()), '') + def test_non_json_request_body(self): """Test handling of non-JSON request body""" request = self.factory.post('/api/test/',