feat: add privacy-safe structured logging

.env.example

@@ -14,3 +14,4 @@ OFFICIAL_RECORDS_CATEGORY=records
 OFFICIAL_IMPORT_REQUIRED=false
 IMPORT_INTERVAL_SECONDS=3600
 RATE_LIMIT_SECRET=change-rate-limit-secret
+LOG_LEVEL=INFO

README.md

@@ -52,6 +52,8 @@ docker compose up --build
 
 Контейнер API сам выполняет `alembic upgrade head`, затем идемпотентный seed. PostgreSQL хранит данные в именованном volume `postgres_data`, а MinIO — в `minio_data`. Compose ожидает readiness PostgreSQL и MinIO перед API, а API-контейнер проверяет `/ready`. Официальный импорт по умолчанию необязателен; при включённом scheduler установите `OFFICIAL_IMPORT_REQUIRED=true`, тогда отсутствующий, неуспешный или просроченный запуск сделает readiness отрицательным.
 
+API и scheduler пишут по одной JSON-записи на событие. HTTP-лог содержит только сгенерированный `request_id`, метод, путь без query string, статус и длительность; IP, заголовок авторизации и пользовательский payload не журналируются. `X-Request-ID` возвращается клиенту. Стандартный access-log Uvicorn отключён. Уровень управляется `LOG_LEVEL`.
+
 Остановка:
 
 ```bash

apps/api/Dockerfile

@@ -6,4 +6,4 @@ RUN pip install --no-cache-dir -r requirements.txt
 COPY apps/api .
 COPY rf4_research ./rf4_research
 EXPOSE 8000
-CMD ["sh", "-c", "alembic upgrade head && python -m app.seed && uvicorn app.main:app --host 0.0.0.0 --port 8000"]
+CMD ["sh", "-c", "alembic upgrade head && python -m app.seed && uvicorn app.main:app --host 0.0.0.0 --port 8000 --no-access-log"]

apps/api/app/config.py

@@ -17,6 +17,7 @@ class Settings(BaseSettings):
     official_import_required: bool = False
     import_interval_seconds: int = Field(default=3600, ge=3600)
     rate_limit_secret: str = "change-rate-limit-secret"
+    log_level: str = "INFO"
     model_config = SettingsConfigDict(env_file=".env", extra="ignore")
 
 

apps/api/app/logging_config.py

@@ -0,0 +1,48 @@
+from __future__ import annotations
+
+import json
+import logging
+import re
+from datetime import datetime, timezone
+
+
+SAFE_FIELDS = (
+    "request_id", "method", "path", "status_code", "duration_ms",
+    "component", "event", "result", "rows_seen", "rows_created",
+    "rows_updated", "not_modified", "interval_seconds", "error_type",
+)
+SENSITIVE = re.compile(
+    r"(?i)(bearer\s+)[^\s]+|((?:token|password|secret|authorization)\s*[=:]\s*)[^\s,;]+"
+)
+
+
+def redact(value: str) -> str:
+    return SENSITIVE.sub(lambda match: f"{match.group(1) or match.group(2)}[REDACTED]", value)
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        payload: dict[str, object] = {
+            "timestamp": datetime.now(timezone.utc).isoformat(),
+            "level": record.levelname.lower(),
+            "logger": record.name,
+            "message": redact(record.getMessage()),
+        }
+        for field in SAFE_FIELDS:
+            value = getattr(record, field, None)
+            if value is not None:
+                payload[field] = value
+        if record.exc_info and "error_type" not in payload:
+            payload["error_type"] = record.exc_info[0].__name__
+        return json.dumps(payload, ensure_ascii=False, separators=(",", ":"), default=str)
+
+
+def configure_logging(level: str = "INFO") -> None:
+    root = logging.getLogger()
+    if not any(getattr(handler, "_rf4_json", False) for handler in root.handlers):
+        handler = logging.StreamHandler()
+        handler.setFormatter(JsonFormatter())
+        handler._rf4_json = True  # type: ignore[attr-defined]
+        root.handlers.clear()
+        root.addHandler(handler)
+    root.setLevel(getattr(logging, level.upper(), logging.INFO))

apps/api/app/main.py

@@ -4,8 +4,11 @@ from collections import Counter
 from datetime import datetime, timedelta, timezone
 import hashlib
 import hmac
+import logging
+import time as time_module
 from typing import Annotated, Literal
 from uuid import UUID
+import uuid
 
 import httpx
 from fastapi import Depends, FastAPI, File, Header, HTTPException, Query, Request, Response, UploadFile
@@ -19,12 +22,15 @@ from .database import get_session
 from .config import settings
 from .community_review import ExternalReviewError, map_observation, publish_observation, reject_observation
 from .importer import ImportSourceError, import_records, normalize
+from .logging_config import configure_logging
 from .models import Bait, BaitKind, CatchReport, ExternalObservation, Fish, ModerationEvent, ModerationStatus, OfficialRecordImport, SourceType, Spot, SubmissionAttempt, Waterbody
 from .readiness import readiness_report
 from .schemas import ActivityOut, AdminCatchReportOut, BaitOut, CatchOut, CatchReportCreate, CatchReportCreated, ExternalObservationDecision, ExternalObservationMapping, ExternalObservationOut, ExternalObservationPublished, FishOut, ImportRunOut, ModerationUpdate, OfficialRecordOut, SpotOut, WaterbodyOut
 from .storage import ScreenshotError, client as storage_client, delete_screenshot, signed_screenshot_url, upload_screenshot
 
 
+configure_logging(settings.log_level)
+logger = logging.getLogger("rf4.api")
 app = FastAPI(title="RF4 Spotter API", version="0.1.0")
 app.add_middleware(
     CORSMiddleware,
@@ -35,6 +41,31 @@ app.add_middleware(
 Db = Annotated[Session, Depends(get_session)]
 
 
+@app.middleware("http")
+async def structured_request_log(request: Request, call_next):
+    request_id = uuid.uuid4().hex
+    started = time_module.perf_counter()
+    status_code = 500
+    try:
+        response = await call_next(request)
+        status_code = response.status_code
+        response.headers["X-Request-ID"] = request_id
+        return response
+    except Exception as exc:
+        logger.error("request failed", extra={"request_id": request_id, "error_type": type(exc).__name__})
+        raise
+    finally:
+        logger.log(
+            logging.DEBUG if request.url.path in {"/health", "/ready"} else logging.INFO,
+            "request completed",
+            extra={
+                "request_id": request_id, "method": request.method,
+                "path": request.url.path, "status_code": status_code,
+                "duration_ms": round((time_module.perf_counter() - started) * 1000, 2),
+            },
+        )
+
+
 @app.get("/health")
 def health() -> dict[str, str]:
     return {"status": "ok"}

apps/api/app/scheduler.py

@@ -10,6 +10,7 @@ from sqlalchemy.orm import Session
 from .config import settings
 from .database import SessionLocal
 from .importer import import_records
+from .logging_config import configure_logging
 from .models import OfficialRecordImport
 
 
@@ -42,20 +43,24 @@ def run_due_import() -> bool:
             category=settings.official_records_category,
         )
         logger.info(
-            "official import completed status=%s seen=%d created=%d updated=%d not_modified=%s",
+            "official import completed",
-            run.status.value, run.rows_seen, run.rows_created, run.rows_updated, run.not_modified,
+            extra={
+                "event": "official_import_completed", "result": run.status.value,
+                "rows_seen": run.rows_seen, "rows_created": run.rows_created,
+                "rows_updated": run.rows_updated, "not_modified": run.not_modified,
+            },
         )
         return True
 
 
 def main() -> None:
-    logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s %(message)s")
+    configure_logging(settings.log_level)
-    logger.info("scheduler started interval_seconds=%d", settings.import_interval_seconds)
+    logger.info("scheduler started", extra={"event": "scheduler_started", "interval_seconds": settings.import_interval_seconds})
     while True:
         try:
             run_due_import()
         except Exception:
-            logger.exception("scheduled official import failed")
+            logger.exception("scheduled official import failed", extra={"event": "official_import_failed"})
         time.sleep(settings.import_interval_seconds)
 
 

apps/api/tests/test_api.py

@@ -56,7 +56,9 @@ def test_invalid_period_is_rejected() -> None:
 
 
 def test_liveness_does_not_probe_dependencies() -> None:
-    assert client.get("/health").json() == {"status": "ok"}
+    response = client.get("/health?token=must-not-be-logged")
+    assert response.json() == {"status": "ok"}
+    assert len(response.headers["X-Request-ID"]) == 32
 
 
 def test_spot_detail_and_catches() -> None:

apps/api/tests/test_logging.py

@@ -0,0 +1,33 @@
+from __future__ import annotations
+
+import json
+import logging
+
+from app.logging_config import JsonFormatter, redact
+
+
+def test_json_formatter_whitelists_fields_and_redacts_secrets() -> None:
+    record = logging.LogRecord(
+        name="rf4.test", level=logging.INFO, pathname=__file__, lineno=1,
+        msg="authorization=Bearer-secret token=top-secret Bearer abc.def",
+        args=(), exc_info=None,
+    )
+    record.request_id = "safe-request-id"
+    record.method = "GET"
+    record.path = "/api/v1/activity"
+    record.player_name = "Must Not Leak"
+    payload = json.loads(JsonFormatter().format(record))
+    assert payload["request_id"] == "safe-request-id"
+    assert payload["method"] == "GET"
+    assert payload["path"] == "/api/v1/activity"
+    assert "player_name" not in payload
+    assert "top-secret" not in payload["message"]
+    assert "abc.def" not in payload["message"]
+    assert payload["message"].count("[REDACTED]") == 3
+
+
+def test_redact_covers_common_credential_forms() -> None:
+    cleaned = redact("password=hunter2 secret: swordfish Authorization: token-value")
+    assert "hunter2" not in cleaned
+    assert "swordfish" not in cleaned
+    assert "token-value" not in cleaned

compose.yaml

@@ -47,6 +47,7 @@ services:
       OFFICIAL_RECORDS_CATEGORY: ${OFFICIAL_RECORDS_CATEGORY:-records}
       OFFICIAL_IMPORT_REQUIRED: ${OFFICIAL_IMPORT_REQUIRED:-false}
       RATE_LIMIT_SECRET: ${RATE_LIMIT_SECRET:-change-rate-limit-secret}
+      LOG_LEVEL: ${LOG_LEVEL:-INFO}
     depends_on:
       db:
         condition: service_healthy
@@ -100,6 +101,7 @@ services:
       OFFICIAL_RECORDS_REGION: ${OFFICIAL_RECORDS_REGION:-RU}
       OFFICIAL_RECORDS_CATEGORY: ${OFFICIAL_RECORDS_CATEGORY:-records}
       IMPORT_INTERVAL_SECONDS: ${IMPORT_INTERVAL_SECONDS:-3600}
+      LOG_LEVEL: ${LOG_LEVEL:-INFO}
     depends_on:
       api:
         condition: service_healthy

docs/ROADMAP.md

@@ -54,7 +54,7 @@
 ## Подготовка MVP к пилоту
 
 - [x] Добавить health/readiness-проверки PostgreSQL, MinIO, API и импорта; отразить их в Compose (`/health` без зависимостей, `/ready` с компонентами и режимом обязательного импорта).
-- [ ] Добавить структурированные логи без пользовательских секретов и персональных технических данных.
+- [x] Добавить структурированные JSON-логи без пользовательских секретов и персональных технических данных (whitelist полей, redaction, request ID; Uvicorn access-log отключён).
 - [ ] Добавить резервное копирование и документированное восстановление PostgreSQL и MinIO.
 - [ ] Провести security-проверку admin-аутентификации, CORS, заголовков, загрузок и управления секретами.
 - [ ] Добавить CI: backend tests, Astro check/build, E2E и проверка миграций на чистой БД.
@@ -91,10 +91,10 @@
 
 Лёгкий пакет по парсерам и фильтрам завершён. Следующий пакет готовит MVP к пилоту:
 
-1. структурированные логи без пользовательских секретов;
+1. CI для тестов, Astro build, E2E и миграций;
-2. CI для тестов, Astro build, E2E и миграций;
+2. backup/restore PostgreSQL и MinIO;
-3. backup/restore PostgreSQL и MinIO;
+3. security-проверка admin-аутентификации, CORS, загрузок и секретов;
-4. security-проверка admin-аутентификации, CORS, загрузок и секретов.
+4. проверка доступности и Lighthouse основных страниц.
 
 После каждого пункта необходимо: