Merge pull request #300 from cmu-delphi/development

Development

Author: dmytrotsko

src/epiportal/logging_formatters.py

@@ -0,0 +1,65 @@
+"""
+Logging formatters for Elasticsearch-compatible structured output.
+"""
+
+import json
+import logging
+from datetime import datetime, timezone
+
+
+# Standard LogRecord attributes - excluded from extra when building JSON
+_RECORD_ATTRS = frozenset(
+    {
+        "name",
+        "msg",
+        "args",
+        "created",
+        "filename",
+        "funcName",
+        "levelname",
+        "levelno",
+        "lineno",
+        "module",
+        "msecs",
+        "pathname",
+        "process",
+        "processName",
+        "relativeCreated",
+        "stack_info",
+        "exc_info",
+        "exc_text",
+        "thread",
+        "threadName",
+        "message",
+        "asctime",
+        "taskName",
+    }
+)
+
+
+class JsonFormatter(logging.Formatter):
+    """
+    Format log records as single-line JSON for Elasticsearch.
+
+    Each log line is a valid JSON object with @timestamp, level, logger, message,
+    and any extra fields passed via logger.info(..., extra={...}).
+    """
+
+    def format(self, record: logging.LogRecord) -> str:
+        log_obj = {
+            "@timestamp": datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%S.%f")[:-3] + "Z",
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+        }
+
+        # Add extra fields (passed via extra= in log calls)
+        for key, value in record.__dict__.items():
+            if key not in _RECORD_ATTRS and value is not None:
+                log_obj[key] = value
+
+        # Add exception info if present
+        if record.exc_info:
+            log_obj["exception"] = self.formatException(record.exc_info)
+
+        return json.dumps(log_obj, default=str)

src/epiportal/middleware.py

@@ -2,15 +2,16 @@
 Request logging middleware that captures comprehensive data from all HTTP requests.
 """
 
-import json
-import logging
 import time
 import uuid
 from typing import Any
 
+from delphi_utils import get_structured_logger
 from django.utils.deprecation import MiddlewareMixin
 
-logger = logging.getLogger("epiportal.requests")
+from epiportal.utils import get_client_ip
+
+logger = get_structured_logger("epiportal.requests")
 
 # Headers that may contain sensitive data - values will be redacted
 SENSITIVE_HEADERS = frozenset(
@@ -26,14 +27,11 @@
     )
 )
 
-# Maximum bytes of request/response body to log (prevents log bloat)
-MAX_BODY_LOG_SIZE = 4096
-
 # Path segments to exclude from request logging (matched anywhere in path)
 LOG_EXCLUDE_PATH_PATTERNS = (
-    "get_table_stats_info",
-    "get_related_indicators",
-    "get_available_geos",
+    # "get_table_stats_info",
+    # "get_related_indicators",
+    # "get_available_geos",
 )
 
 
@@ -43,15 +41,6 @@ def _should_log_request(request) -> bool:
     return not any(pattern in path for pattern in LOG_EXCLUDE_PATH_PATTERNS)
 
 
-def _get_client_ip(request) -> str:
-    """Extract client IP, respecting X-Forwarded-For when behind proxies."""
-    x_forwarded_for = request.META.get("HTTP_X_FORWARDED_FOR")
-    if x_forwarded_for:
-        # Take the leftmost (original client) IP
-        return x_forwarded_for.split(",")[0].strip()
-    return request.META.get("REMOTE_ADDR", "")
-
-
 def _sanitize_headers(meta: dict) -> dict[str, str]:
     """Extract HTTP headers from META, redacting sensitive ones."""
     headers = {}
@@ -65,19 +54,6 @@ def _sanitize_headers(meta: dict) -> dict[str, str]:
     return headers
 
 
-def _safe_body_preview(body: bytes | None, max_size: int = MAX_BODY_LOG_SIZE) -> str | None:
-    """Return a safe preview of request/response body, truncated if large."""
-    if body is None or len(body) == 0:
-        return None
-    try:
-        decoded = body.decode("utf-8", errors="replace")
-        if len(decoded) > max_size:
-            return decoded[:max_size] + f"... [truncated, total {len(body)} bytes]"
-        return decoded
-    except Exception:
-        return f"[binary, {len(body)} bytes]"
-
-
 class RequestLoggingMiddleware(MiddlewareMixin):
     """
     Middleware that logs every HTTP request with comprehensive request and response data.
@@ -111,7 +87,7 @@ def process_response(self, request, response):
                 "full_uri": request.build_absolute_uri(),
                 "query_string": request.META.get("QUERY_STRING") or "",
                 "query_params": dict(request.GET) if request.GET else {},
-                "client_ip": _get_client_ip(request),
+                "client_ip": get_client_ip(request),
                 "referer": request.META.get("HTTP_REFERER", ""),
                 "user_agent": request.META.get("HTTP_USER_AGENT", ""),
                 "content_type": request.content_type or "",
@@ -128,31 +104,10 @@ def process_response(self, request, response):
             else:
                 log_data["user"] = "anonymous"
 
-            # Request body (for methods that typically have one)
-            if request.method in ("POST", "PUT", "PATCH"):
-                try:
-                    body = getattr(request, "_body", None) or request.body
-                    log_data["request_body_preview"] = _safe_body_preview(body)
-                except Exception as e:
-                    log_data["request_body_error"] = str(e)
-
-            # Response body (for API responses, avoid huge HTML)
-            if (
-                "application/json" in (response.get("Content-Type") or "")
-                and hasattr(response, "content")
-            ):
-                log_data["response_body_preview"] = _safe_body_preview(response.content)
-
             if duration_ms is not None:
                 log_data["duration_ms"] = round(duration_ms, 2)
 
-            logger.info(
-                "%s %s %s | %s",
-                request.method,
-                request.path,
-                response.status_code,
-                json.dumps(log_data, default=str),
-            )
+            logger.info("request", **log_data)
 
         except Exception as e:
             logger.exception("Error in request logging middleware: %s", e)

src/epiportal/settings.py

@@ -244,29 +244,20 @@
             'formatter': 'simple',
             'stream': sys.stdout,
         },
-        'request_console': {
-            'class': 'logging.StreamHandler',
-            'formatter': 'request_verbose',
-            'stream': sys.stdout,
-        },
     },
     'loggers': {
         'django': {
             'handlers': ['console'],
             'level': 'INFO',
             'propagate': True,
         },
-        'epiportal.requests': {
-            'handlers': ['request_console'],
-            'level': 'INFO',
-            'propagate': False,
-        },
     },
 }
 
 if DEBUG:
     for logger in LOGGING['loggers']:
-        LOGGING['loggers'][logger]['handlers'] = ['console']
+        if logger != 'epiportal.requests':
+            LOGGING['loggers'][logger]['handlers'] = ['console']
 
 
 # DRF Spectacular settings

src/epiportal/utils.py

@@ -0,0 +1,35 @@
+"""
+Shared utilities for epiportal.
+"""
+
+from django.conf import settings
+
+
+def get_client_ip(request) -> str:
+    """
+    Extract the real client IP from a request, respecting X-Forwarded-For when behind proxies.
+
+    Use this everywhere you need the client IP (logging, rate limiting, etc.) to ensure
+    consistent behavior. Requires PROXY_DEPTH to be set correctly for your production
+    proxy chain (e.g. 2 for AWS ALB + nginx).
+    """
+    if not settings.REVERSE_PROXY_DEPTH:
+        return request.META.get("REMOTE_ADDR", "")
+
+    x_forwarded_for = request.META.get("HTTP_X_FORWARDED_FOR")
+    if x_forwarded_for:
+        full_proxy_chain = [s.strip() for s in x_forwarded_for.split(",")]
+        depth = (
+            settings.REVERSE_PROXY_DEPTH
+            if settings.REVERSE_PROXY_DEPTH > 0
+            else len(full_proxy_chain)
+        )
+        trusted = full_proxy_chain[-depth:] if depth else full_proxy_chain
+        if trusted:
+            return trusted[0]
+
+    x_real_ip = request.META.get("HTTP_X_REAL_IP")
+    if x_real_ip:
+        return x_real_ip.strip()
+
+    return request.META.get("REMOTE_ADDR", "")

src/indicatorsets/utils.py

@@ -6,8 +6,9 @@
 
 import requests
 from django.conf import settings
-from django.http import JsonResponse
 from django.core.cache import cache
+from django.http import JsonResponse
+from epiportal.utils import get_client_ip
 from epiweeks import Week
 from delphi_utils import get_structured_logger
 
@@ -681,36 +682,6 @@ def generate_query_code_flusurv(flusurv_geos, start_date, end_date):
     return python_code_blocks, r_code_blocks
 
 
-def get_real_ip_addr(req):  # `req` should be a Flask.request object
-    if settings.REVERSE_PROXY_DEPTH:
-        # we only expect/trust (up to) "REVERSE_PROXY_DEPTH" number of proxies between this server and the outside world.
-        # a REVERSE_PROXY_DEPTH of 0 means not proxied, i.e. server is globally directly reachable.
-        # a negative proxy depth is a special case to trust the whole chain -- not generally recommended unless the
-        # most-external proxy is configured to disregard "X-Forwarded-For" from outside.
-        # really, ONLY trust the following headers if reverse proxied!!!
-        x_forwarded_for = req.META.get("HTTP_X_FORWARDED_FOR")
-
-        if x_forwarded_for:
-            full_proxy_chain = x_forwarded_for.split(",")
-            # eliminate any extra addresses at the front of this list, as they could be spoofed.
-            if settings.REVERSE_PROXY_DEPTH > 0:
-                depth = settings.REVERSE_PROXY_DEPTH
-            else:
-                # special case for -1/negative: setting `depth` to 0 will not strip any items from the chain
-                depth = 0
-            trusted_proxy_chain = full_proxy_chain[-depth:]
-            # accept the first (or only) address in the remaining trusted part of the chain as the actual remote address
-            return trusted_proxy_chain[0].strip()
-
-        # fall back to "X-Real-Ip" if "X-Forwarded-For" isnt present
-        x_real_ip = req.META.get("HTTP_X_REAL_IP")
-        if x_real_ip:
-            return x_real_ip
-
-    # if we are not proxied (or we are proxied but the headers werent present and we fell through to here), just use the remote ip addr as the true client address
-    return req.META.get("REMOTE_ADDR")
-
-
 def log_form_stats(request, data, form_mode):
     log_data = {
         "form_mode": form_mode,
@@ -729,7 +700,7 @@ def log_form_stats(request, data, form_mode):
         ),
         "api_key_used": bool(data.get("api_key")),
         "api_key": data.get("api_key", "Not provided"),
-        "user_ip": get_real_ip_addr(request),
+        "user_ip": get_client_ip(request),
         "user_ga_id": data.get("clientId", "Not available"),
     }
 
@@ -805,7 +776,7 @@ def log_form_data(request, data, form_mode):
         "epiweeks": get_epiweek(data.get("start_date", ""), data.get("end_date", "")) if data.get("start_date") and data.get("end_date") else [],  # fmt: skip
         "api_key_used": bool(data.get("apiKey")),
         "api_key": data.get("apiKey", "Not provided"),
-        "user_ip": get_real_ip_addr(request),
+        "user_ip": get_client_ip(request),
         "user_ga_id": data.get("clientId", "Not available"),
     }
     form_data_logger.info("form_data", **log_data)