diff --git a/Dockerfile b/Dockerfile index 8b73e9d..c947689 100644 --- 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 index 8f59068..3f8b533 100644 --- 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 index c778ccc..01d79cb 100644 --- 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: "

PowerDNS API Proxy

" ``` +## 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 +LISTEN_HOST=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 index 3abb5ad..3821c62 100644 --- 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("LISTEN_HOST", "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 index fc52dfa..5cf5e2c 100644 --- 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 index 963eac5..e467f04 100644 --- 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 new file mode 100644 index 0000000..10847c7 --- /dev/null +++ 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 index 7566bb8..8e7623c 100644 --- 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 new file mode 100644 index 0000000..819775d --- /dev/null +++ b/powerdns_api_proxy/uvicorn_config.py @@ -0,0 +1,75 @@ +import os + +LOG_FORMAT = os.getenv("LOG_FORMAT", "text") + +if LOG_FORMAT == "json": + LOGGING_CONFIG = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "default": { + "()": "powerdns_api_proxy.logging.JSONFormatter", + }, + "access": { + "()": "powerdns_api_proxy.logging.JSONFormatter", + }, + }, + "handlers": { + "default": { + "formatter": "default", + "class": "logging.StreamHandler", + "stream": "ext://sys.stderr", + }, + "access": { + "formatter": "access", + "class": "logging.StreamHandler", + "stream": "ext://sys.stderr", + }, + }, + "loggers": { + "uvicorn": {"handlers": ["default"], "level": "INFO"}, + "uvicorn.error": {"level": "INFO"}, + "uvicorn.access": { + "handlers": ["access"], + "level": "INFO", + "propagate": False, + }, + }, + } +else: + LOGGING_CONFIG = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "default": { + "()": "uvicorn.logging.DefaultFormatter", + "fmt": "%(levelprefix)s %(message)s", + "use_colors": None, + }, + "access": { + "()": "uvicorn.logging.AccessFormatter", + "fmt": '%(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s', + }, + }, + "handlers": { + "default": { + "formatter": "default", + "class": "logging.StreamHandler", + "stream": "ext://sys.stderr", + }, + "access": { + "formatter": "access", + "class": "logging.StreamHandler", + "stream": "ext://sys.stderr", + }, + }, + "loggers": { + "uvicorn": {"handlers": ["default"], "level": "INFO"}, + "uvicorn.error": {"level": "INFO"}, + "uvicorn.access": { + "handlers": ["access"], + "level": "INFO", + "propagate": False, + }, + }, + } diff --git a/tests/unit/logging_test.py b/tests/unit/logging_test.py new file mode 100644 index 0000000..b719404 --- /dev/null +++ b/tests/unit/logging_test.py @@ -0,0 +1,136 @@ +import json +import logging +from io import StringIO + +import pytest + +from powerdns_api_proxy.logging import AuditLogger, JSONFormatter + + +@pytest.fixture +def json_logger(): + """Create a logger with JSON formatter and string stream""" + logger = AuditLogger("test") + logger.setLevel(logging.INFO) + + handler = logging.StreamHandler() + handler.setFormatter(JSONFormatter()) + stream = StringIO() + handler.stream = stream + logger.addHandler(handler) + + return logger, stream + + +def test_audit_log_text_format(caplog): + logger = logging.getLogger("test_audit_text") + logger.setLevel(logging.INFO) + logger.__class__ = AuditLogger + + with caplog.at_level(logging.INFO, logger="test_audit_text"): + logger.audit("Test1", "PATCH", "/zones/example.com", 204, {"rrsets": []}) + + record = caplog.records[0] + assert "AUDIT: Test1 PATCH /zones/example.com 204" in record.message + assert "payload={'rrsets': []}" in record.message + assert record.audit["environment"] == "Test1" + assert record.audit["status_code"] == 204 + + +def test_audit_log_text_format_with_query_params(caplog): + logger = logging.getLogger("test_audit_query_text") + logger.setLevel(logging.INFO) + logger.__class__ = AuditLogger + + with caplog.at_level(logging.INFO, logger="test_audit_query_text"): + logger.audit("Test1", "GET", "/search-data", 200, query_params={"q": "test"}) + + record = caplog.records[0] + assert "AUDIT: Test1 GET /search-data 200" in record.message + assert "query_params={'q': 'test'}" in record.message + + +def test_audit_log_text_format_no_extras(caplog): + logger = logging.getLogger("test_audit_plain") + logger.setLevel(logging.INFO) + logger.__class__ = AuditLogger + + with caplog.at_level(logging.INFO, logger="test_audit_plain"): + logger.audit("Test1", "DELETE", "/zones/test.com", 403) + + record = caplog.records[0] + assert record.message == "AUDIT: Test1 DELETE /zones/test.com 403" + assert "payload" not in record.message + assert "query_params" not in record.message + + +def test_audit_log_json_format(json_logger): + logger, stream = json_logger + + logger.audit("Test1", "DELETE", "/zones/test.com", 403) + log_data = json.loads(stream.getvalue().split("\n")[0]) + + assert log_data["event_type"] == "audit" + assert log_data["audit"] == { + "environment": "Test1", + "method": "DELETE", + "path": "/zones/test.com", + "status_code": 403, + } + assert "message" not in log_data + assert "module" not in log_data + + stream.truncate(0) + stream.seek(0) + payload = {"rrsets": [{"name": "test.example.com"}]} + logger.audit("Test1", "PATCH", "/zones/example.com", 204, payload) + log_data = json.loads(stream.getvalue()) + assert log_data["audit"]["payload"] == payload + + stream.truncate(0) + stream.seek(0) + query_params = {"q": "example.com", "max": 10} + logger.audit("Test1", "GET", "/search-data", 200, query_params=query_params) + log_data = json.loads(stream.getvalue()) + assert log_data["audit"]["query_params"] == query_params + assert log_data["audit"]["method"] == "GET" + + +def test_regular_log_json_format(json_logger): + logger, stream = json_logger + logger.info("Regular log message") + + log_data = json.loads(stream.getvalue()) + + assert log_data["event_type"] == "log" + assert log_data["message"] == "Regular log message" + assert "module" in log_data + assert "audit" not in log_data + + +def test_audit_log_skips_sensitive_payloads(caplog): + logger = logging.getLogger("test_audit_cryptokeys") + logger.setLevel(logging.INFO) + logger.__class__ = AuditLogger + + with caplog.at_level(logging.INFO, logger="test_audit_cryptokeys"): + logger.audit( + "Test1", "POST", "/zones/example.com/cryptokeys", 201, {"content": "secret"} + ) + + record = caplog.records[0] + assert record.message == "AUDIT: Test1 POST /zones/example.com/cryptokeys 201" + assert "payload" not in record.audit + + +def test_audit_log_skips_tsigkeys_payloads(caplog): + logger = logging.getLogger("test_audit_tsigkeys") + logger.setLevel(logging.INFO) + logger.__class__ = AuditLogger + + with caplog.at_level(logging.INFO, logger="test_audit_tsigkeys"): + logger.audit("Test1", "PUT", "/tsigkeys/key1", 200, {"key": "secret"}) + + record = caplog.records[0] + assert record.message == "AUDIT: Test1 PUT /tsigkeys/key1 200" + assert "payload" not in record.audit diff --git a/tests/unit/middleware_test.py b/tests/unit/middleware_test.py new file mode 100644 index 0000000..b6b875e --- /dev/null +++ b/tests/unit/middleware_test.py @@ -0,0 +1,55 @@ +import pytest +from fastapi.testclient import TestClient + +from powerdns_api_proxy.proxy import app + + +@pytest.fixture +def client(): + return TestClient(app) + + +def test_middleware_logs_get_request(client, caplog): + # This will fail auth but middleware should still log + client.get( + "/api/v1/servers/localhost/zones", + headers={"X-API-Key": "invalid"}, + ) + + # Check audit log was created + audit_records = [r for r in caplog.records if hasattr(r, "audit")] + assert len(audit_records) > 0 + + audit = audit_records[0].audit + assert audit["method"] == "GET" + assert "/zones" in audit["path"] + + +def test_middleware_logs_post_request_with_payload(client, caplog): + payload = {"name": "test.com", "kind": "Native"} + + client.post( + "/api/v1/servers/localhost/zones", + json=payload, + headers={"X-API-Key": "invalid"}, + ) + + audit_records = [r for r in caplog.records if hasattr(r, "audit")] + assert len(audit_records) > 0 + + audit = audit_records[0].audit + assert audit["method"] == "POST" + assert audit["payload"] == payload + + +def test_middleware_logs_query_params(client, caplog): + client.get( + "/api/v1/servers/localhost/zones?rrsets=true", + headers={"X-API-Key": "invalid"}, + ) + + audit_records = [r for r in caplog.records if hasattr(r, "audit")] + assert len(audit_records) > 0 + + audit = audit_records[0].audit + assert audit["query_params"] == {"rrsets": "true"}