feat: audit log and structured logging

rwxd · rwxd · commit 35918c0eacbc · 2026-03-26T14:38:55.000+01:00
WIP

feat: audit log and structured logging
diff --git a/Dockerfile b/Dockerfile
@@ -2,11 +2,15 @@ FROM docker.io/python:3.13.5-slim
 
 WORKDIR /app
 
+# hadolint ignore=DL3008
+RUN apt-get update \
+    && apt-get install -y --no-install-recommends jq && rm -rf /var/lib/apt/lists/*
+
 COPY requirements.txt /app
 ENV PATH=/venv/bin:$PATH
 RUN : \
-	&& python3 -m venv /venv \
-	&& pip --no-cache-dir install -r requirements.txt
+    && python3 -m venv /venv \
+    && pip --no-cache-dir install -r requirements.txt
 
 COPY . /app
 
@@ -18,9 +22,9 @@ ENV PYTHONUNBUFFERED=1
 
 # Creates a non-root user with an explicit UID and adds permission to access the /app folder
 RUN : \
-	&& adduser -u 1000 --disabled-password --gecos "" appuser \
-	&& chown -R appuser /app && chmod -R 0750 /app
+    && adduser -u 1000 --disabled-password --gecos "" appuser \
+    && chown -R appuser /app && chmod -R 0750 /app
 USER appuser
 
 
-CMD ["uvicorn", "--host", "*", "--port", "8000", "powerdns_api_proxy.proxy:app"]
+CMD ["python", "-m", "powerdns_api_proxy"]
diff --git a/Makefile b/Makefile
@@ -19,7 +19,7 @@ integration: ## run integration tests
 	python -m pytest -vvl --setup-show -vvl tests/integration/ --showlocals
 
 run: ## run project
-	uvicorn --host 0.0.0.0 --port 8000 --reload powerdns_api_proxy.proxy:app
+	python -m powerdns_api_proxy --reload
 
 clean: ## clean cache and temp dirs
 	rm -rf ./.mypy_cache ./.pytest_cache
@@ -38,4 +38,4 @@ pre-commit: ## run pre-commit
 	pre-commit run
 
 run-docker-debug: build-docker ## run debug with docker on port 8000
-	docker run --rm -it -v "${PWD}:/app" -p 8000:8000 -e "PROXY_CONFIG_PATH=${PROXY_CONFIG_PATH}" --rm $(PROJECT_NAME):test uvicorn --host 0.0.0.0 --port 8000 --reload powerdns_api_proxy.proxy:app
+	docker run --rm -it -v "${PWD}:/app" -p 8000:8000 -e "PROXY_CONFIG_PATH=${PROXY_CONFIG_PATH}" --rm $(PROJECT_NAME):test python -m powerdns_api_proxy --reload
diff --git a/README.md b/README.md
@@ -15,7 +15,12 @@ Within a zone, the token can be limited to one or more records.
 Containers are available under [Packages](https://github.com/akquinet/powerdns-api-proxy/pkgs/container/powerdns-api-proxy).
 
 ```bash
-docker run -v config:/config -e PROXY_CONFIG_PATH=/config/config.yaml -e LOG_LEVEL=WARNING --name powerdns-api-proxy ghcr.io/akquinet/powerdns-api-proxy:latest
+docker run -v config:/config \
+  -e PROXY_CONFIG_PATH=/config/config.yaml \
+  -e LOG_LEVEL=INFO \
+  -e LOG_FORMAT=json \
+  --name powerdns-api-proxy \
+  ghcr.io/akquinet/powerdns-api-proxy:latest
 ```
 
 ### Authentication
@@ -303,6 +308,78 @@ index_enabled: false # default is true
 index_html: "<html><body><h1>PowerDNS API Proxy</h1></body></html>"
 ```
 
+## Logging
+
+### Environment Variables
+
+```bash
+LOG_LEVEL=DEBUG       # Optional: DEBUG, INFO, WARNING, ERROR (default: DEBUG)
+LOG_FORMAT=json       # Optional: "text" (default) or "json" for structured logging
+ALLOWED_HOSTS=0.0.0.0 # Optional: Host to bind to (default: 0.0.0.0)
+LISTEN_PORT=8000      # Optional: Port to listen on (default: 8000)
+```
+
+When `LOG_FORMAT=json` is set, all logs (application and uvicorn access logs) will be output in JSON format.
+
+Set `AUDIT_LOGGING=false` to disable automatic audit logging of API requests.
+
+### Audit Logging
+
+All API operations (GET, POST, PUT, PATCH, DELETE) are automatically logged to stderr with structured data via middleware.
+
+This includes both successful operations and forbidden attempts (HTTP 403).
+
+Each audit log entry contains:
+
+* `timestamp`: ISO 8601 timestamp
+* `level`: Log level (INFO)
+* `event_type`: "audit" for easy filtering
+* `audit`: Structured audit data object containing:
+  * `environment`: Name of the authenticated environment/token
+  * `method`: HTTP method (GET, POST, PUT, PATCH, DELETE)
+  * `path`: Resource path that was accessed/modified
+  * `status_code`: HTTP response status code
+  * `payload`: Request payload (optional, for write operations; omitted for sensitive endpoints like `/cryptokeys` and `/tsigkeys`)
+  * `query_params`: Query parameters (optional, for GET requests)
+
+#### Text Format (default)
+
+```
+INFO - 2026-03-26 12:03:21,323 - powerdns_api_proxy - proxy.py - audit - 70 - AUDIT: Test1 PATCH /zones/example.com 204 payload={'rrsets': []}
+INFO - 2026-03-26 12:03:21,323 - powerdns_api_proxy - proxy.py - audit - 70 - AUDIT: Test1 GET /zones 200 query_params={'rrsets': 'true'}
+INFO - 2026-03-26 12:03:21,323 - powerdns_api_proxy - proxy.py - audit - 70 - AUDIT: Test1 DELETE /zones/test.com 403
+```
+
+#### JSON Format (set LOG_FORMAT=json)
+
+```json
+{"timestamp": "2026-03-26T11:39:29", "level": "INFO", "event_type": "audit", "audit": {"environment": "Test1", "method": "PATCH", "path": "/zones/example.com", "status_code": 204, "payload": {"rrsets": [...]}}}
+```
+
+#### Analyzing Audit Logs
+
+With JSON format enabled, you can use `jq` to filter and analyze audit logs:
+
+```bash
+# Filter only audit events
+docker logs powerdns-api-proxy 2>&1 | jq 'select(.event_type == "audit")'
+
+# Filter by environment
+docker logs powerdns-api-proxy 2>&1 | jq 'select(.event_type == "audit" and .audit.environment == "Test1")'
+
+# Filter by HTTP method
+docker logs powerdns-api-proxy 2>&1 | jq 'select(.event_type == "audit" and .audit.method == "PATCH")'
+
+# Filter by zone
+docker logs powerdns-api-proxy 2>&1 | jq 'select(.event_type == "audit" and (.audit.path | contains("/zones/example.com")))'
+
+# Extract only key audit fields
+docker logs powerdns-api-proxy 2>&1 | jq 'select(.event_type == "audit") | {timestamp, environment: .audit.environment, method: .audit.method, path: .audit.path, status: .audit.status_code}'
+
+# Show failed attempts (403)
+docker logs powerdns-api-proxy 2>&1 | jq 'select(.event_type == "audit" and .audit.status_code == 403)'
+```
+
 ## Development
 
 ### Install requirements
diff --git a/powerdns_api_proxy/__main__.py b/powerdns_api_proxy/__main__.py
@@ -1,6 +1,22 @@
+import os
+import sys
+import uvicorn
+from powerdns_api_proxy.uvicorn_config import LOGGING_CONFIG
+
+
 def main() -> int:
-    print("Please start me with uvicorn :)")
-    return 1
+    host = os.getenv("ALLOWED_HOSTS", "0.0.0.0")
+    port = int(os.getenv("LISTEN_PORT", "8000"))
+    reload = "--reload" in sys.argv
+
+    uvicorn.run(
+        "powerdns_api_proxy.proxy:app",
+        host=host,
+        port=port,
+        log_config=LOGGING_CONFIG,
+        reload=reload,
+    )
+    return 0
 
 
 if __name__ == "__main__":
diff --git a/powerdns_api_proxy/config.py b/powerdns_api_proxy/config.py
@@ -35,7 +35,9 @@ def load_config(path: Optional[Path] = None) -> ProxyConfig:
     with open(path) as f:
         data = safe_load(f)
 
-    return ProxyConfig(**data)
+    config = ProxyConfig(**data)
+
+    return config
 
 
 def token_defined(config: ProxyConfig, token: str) -> bool:
diff --git a/powerdns_api_proxy/logging.py b/powerdns_api_proxy/logging.py
@@ -1,16 +1,96 @@
 import logging
 import logging.handlers
+import json
 from os import getenv
 from sys import stderr
 
 LOG_LEVEL = getenv("LOG_LEVEL") or "DEBUG"
+LOG_FORMAT = getenv("LOG_FORMAT", "text")  # text or json
 
 logging_format = (
     "%(levelname)s - %(asctime)s - %(name)s - "
     + "%(filename)s - %(funcName)s - %(lineno)s - %(message)s"
 )
 
-default_formatter = logging.Formatter(logging_format)
+
+class JSONFormatter(logging.Formatter):
+    """Format log records as JSON for structured logging"""
+
+    def format(self, record: logging.LogRecord) -> str:
+        log_data: dict[str, str | int | dict] = {
+            "timestamp": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"),
+            "level": record.levelname,
+        }
+
+        # Special handling for audit logs
+        if hasattr(record, "audit"):
+            log_data["event_type"] = "audit"
+            log_data["audit"] = record.audit
+        else:
+            # Regular logs include full context
+            log_data["event_type"] = "log"
+            log_data["logger"] = record.name
+            log_data["message"] = record.getMessage()
+            log_data["module"] = record.module
+            log_data["function"] = record.funcName
+            log_data["line"] = record.lineno
+
+            if record.exc_info:
+                log_data["exception"] = self.formatException(record.exc_info)
+
+        return json.dumps(log_data)
+
+
+class AuditLogger(logging.Logger):
+    """Custom logger with audit() method"""
+
+    def audit(
+        self,
+        environment: str,
+        method: str,
+        path: str,
+        status_code: int,
+        payload: dict | None = None,
+        query_params: dict | None = None,
+    ):
+        """Log audit events with structured data"""
+        # Skip payload logging for sensitive endpoints
+        if payload is not None and any(
+            sensitive in path for sensitive in ["/cryptokeys", "/tsigkeys"]
+        ):
+            payload = None
+
+        audit_data = {
+            "environment": environment,
+            "method": method,
+            "path": path,
+            "status_code": status_code,
+        }
+        if payload is not None:
+            audit_data["payload"] = payload
+        if query_params is not None and query_params:
+            audit_data["query_params"] = query_params
+
+        # Build message with optional query_params/payload info
+        msg_parts = [f"AUDIT: {environment} {method} {path} {status_code}"]
+        if query_params:
+            msg_parts.append(f"query_params={query_params}")
+        if payload is not None:
+            msg_parts.append(f"payload={payload}")
+
+        self.info(
+            " ".join(msg_parts),
+            extra={"audit": audit_data},
+            stacklevel=2,
+        )
+
+
+logging.setLoggerClass(AuditLogger)
+
+if LOG_FORMAT == "json":
+    default_formatter: logging.Formatter = JSONFormatter()
+else:
+    default_formatter = logging.Formatter(logging_format)
 
 default_stream_handler = logging.StreamHandler(stderr)
 default_stream_handler.setLevel(LOG_LEVEL)
@@ -22,7 +102,7 @@
 file_handler.setLevel("DEBUG")
 file_handler.setFormatter(default_formatter)
 
-logger = logging.getLogger("powerdns_api_proxy")
+logger: AuditLogger = logging.getLogger("powerdns_api_proxy")  # type: ignore
 logger.addHandler(default_stream_handler)
 logger.addHandler(file_handler)
 
diff --git a/powerdns_api_proxy/middleware.py b/powerdns_api_proxy/middleware.py
@@ -0,0 +1,66 @@
+import json
+import os
+
+from fastapi import Request, Response
+from starlette.middleware.base import BaseHTTPMiddleware
+
+from powerdns_api_proxy.config import get_environment_for_token, load_config
+from powerdns_api_proxy.logging import logger
+
+_config = load_config()
+
+
+class AuditMiddleware(BaseHTTPMiddleware):
+    """Middleware to automatically log all API requests and their response status code"""
+
+    async def dispatch(self, request: Request, call_next):
+        if os.getenv("AUDIT_LOGGING", "true").lower() == "false":
+            return await call_next(request)
+
+        if not request.url.path.startswith("/api/v1/"):
+            return await call_next(request)
+
+        environment_name = "UNAUTHENTICATED"
+        try:
+            token = request.headers.get("X-API-Key", "")
+            if token:
+                environment = get_environment_for_token(_config, token)
+                environment_name = environment.name
+        except Exception:
+            pass
+
+        # Store request body for logging (only for write operations)
+        payload = None
+        if request.method in ["POST", "PUT", "PATCH"]:
+            try:
+                # Read raw request body bytes; FastAPI/Starlette will cache the body for downstream handlers
+                body_bytes = await request.body()
+                if body_bytes:
+                    payload = json.loads(body_bytes)
+            except Exception:
+                pass
+
+        query_params = dict(request.query_params) if request.query_params else None
+
+        path = request.url.path.replace("/api/v1/servers/localhost", "")
+        status_code = 500
+        try:
+            # Call the actual endpoint
+            response: Response = await call_next(request)
+            status_code = response.status_code
+            return response
+        except Exception:
+            # Ensure that exceptions are logged as 500 responses while allowing
+            # FastAPI/Starlette's normal exception handling to proceed.
+            logger.exception("Unhandled exception during request processing")
+            raise
+        finally:
+            # Log the request, even if an exception occurred
+            logger.audit(
+                environment_name,
+                request.method,
+                path,
+                status_code,
+                payload,
+                query_params,
+            )
diff --git a/powerdns_api_proxy/proxy.py b/powerdns_api_proxy/proxy.py
@@ -3,7 +3,14 @@
 from http import HTTPStatus
 from typing import Literal
 
-from fastapi import APIRouter, Depends, FastAPI, Header, Request, Response
+from fastapi import (
+    APIRouter,
+    Depends,
+    FastAPI,
+    Header,
+    Request,
+    Response,
+)
 from fastapi.responses import HTMLResponse, JSONResponse
 from prometheus_fastapi_instrumentator import Instrumentator, metrics
 from starlette.exceptions import HTTPException as StarletteHTTPException
@@ -29,6 +36,7 @@
     UpstreamException,
 )
 from powerdns_api_proxy.logging import logger
+from powerdns_api_proxy.middleware import AuditMiddleware
 from powerdns_api_proxy.metrics import http_requests_total_environment
 from powerdns_api_proxy.models import (
     ResponseAllowed,
@@ -73,6 +81,8 @@ async def _startup(app: FastAPI):
         openapi_url=None,
     )
 
+app.add_middleware(AuditMiddleware)
+
 if config.metrics_enabled:
     instrumentator = Instrumentator(
         should_group_status_codes=False,
diff --git a/powerdns_api_proxy/uvicorn_config.py b/powerdns_api_proxy/uvicorn_config.py
diff --git a/tests/unit/logging_test.py b/tests/unit/logging_test.py
diff --git a/tests/unit/middleware_test.py b/tests/unit/middleware_test.py
