diff --git a/.env.example b/.env.example index 6785edd..f0246d5 100644 --- a/.env.example +++ b/.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 diff --git a/README.md b/README.md index f3eeebc..5f78880 100644 --- a/README.md +++ b/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 diff --git a/apps/api/Dockerfile b/apps/api/Dockerfile index e888dc4..403006e 100644 --- a/apps/api/Dockerfile +++ b/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"] diff --git a/apps/api/app/config.py b/apps/api/app/config.py index 98615c0..afa0693 100644 --- a/apps/api/app/config.py +++ b/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") diff --git a/apps/api/app/logging_config.py b/apps/api/app/logging_config.py new file mode 100644 index 0000000..7171708 --- /dev/null +++ b/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)) diff --git a/apps/api/app/main.py b/apps/api/app/main.py index a6d4ac2..29a3d11 100644 --- a/apps/api/app/main.py +++ b/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"} diff --git a/apps/api/app/scheduler.py b/apps/api/app/scheduler.py index 01650bc..6e7c582 100644 --- a/apps/api/app/scheduler.py +++ b/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", - run.status.value, run.rows_seen, run.rows_created, run.rows_updated, run.not_modified, + "official import completed", + 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") - logger.info("scheduler started interval_seconds=%d", settings.import_interval_seconds) + configure_logging(settings.log_level) + 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) diff --git a/apps/api/tests/test_api.py b/apps/api/tests/test_api.py index 9b31e9f..449d8ef 100644 --- a/apps/api/tests/test_api.py +++ b/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: diff --git a/apps/api/tests/test_logging.py b/apps/api/tests/test_logging.py new file mode 100644 index 0000000..5914cec --- /dev/null +++ b/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 diff --git a/compose.yaml b/compose.yaml index cf1befa..9e06fe4 100644 --- a/compose.yaml +++ b/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 diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index 4db9647..794cafb 100644 --- a/docs/ROADMAP.md +++ b/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. структурированные логи без пользовательских секретов; -2. CI для тестов, Astro build, E2E и миграций; -3. backup/restore PostgreSQL и MinIO; -4. security-проверка admin-аутентификации, CORS, загрузок и секретов. +1. CI для тестов, Astro build, E2E и миграций; +2. backup/restore PostgreSQL и MinIO; +3. security-проверка admin-аутентификации, CORS, загрузок и секретов; +4. проверка доступности и Lighthouse основных страниц. После каждого пункта необходимо: