From be67902b453fa708777b163d0d85ae9084e20221 Mon Sep 17 00:00:00 2001 From: vrubelroman Date: Thu, 9 Jul 2026 20:10:10 +0000 Subject: [PATCH] Add structured logging throughout the backend Request-level logging middleware (method/path/status/duration), per-module loggers in routes/services (nearby search radius expansion, 404s, name search), LOG_LEVEL setting wired through docker-compose, and seed_loader converted from print() to logging. Verified: pytest passes, and manually confirmed log lines appear for both successful and 404 requests via `docker compose logs api`. Co-Authored-By: Claude Sonnet 5 --- .env.example | 1 + backend/app/api/routes/cities.py | 5 +++++ backend/app/api/routes/nearby.py | 7 +++++++ backend/app/api/routes/places.py | 7 +++++++ backend/app/config.py | 1 + backend/app/core/logging.py | 29 +++++++++++++++++++++++++++ backend/app/main.py | 19 +++++++++++++++++- backend/app/services/geocoding.py | 8 +++++++- backend/app/services/nearby_search.py | 19 ++++++++++++++++++ backend/seed/seed_loader.py | 21 +++++++++++++++++-- docker-compose.yml | 1 + 11 files changed, 114 insertions(+), 4 deletions(-) diff --git a/.env.example b/.env.example index fb6fe50..ed3000c 100644 --- a/.env.example +++ b/.env.example @@ -1,3 +1,4 @@ POSTGRES_USER=guidecity POSTGRES_PASSWORD=changeme POSTGRES_DB=guidecity +LOG_LEVEL=INFO diff --git a/backend/app/api/routes/cities.py b/backend/app/api/routes/cities.py index a573996..9f920e4 100644 --- a/backend/app/api/routes/cities.py +++ b/backend/app/api/routes/cities.py @@ -1,3 +1,5 @@ +import logging + from fastapi import APIRouter, Depends from geoalchemy2 import Geometry from sqlalchemy import cast, func, select @@ -8,6 +10,8 @@ from app.models.city import City from app.schemas.city import CityOut from app.schemas.common import LatLon, LocalizedName +logger = logging.getLogger("guidecity.cities") + router = APIRouter(tags=["cities"]) @@ -31,4 +35,5 @@ def list_cities(db: Session = Depends(get_db)) -> list[CityOut]: center=center, ) ) + logger.debug("listed %d cities", len(out)) return out diff --git a/backend/app/api/routes/nearby.py b/backend/app/api/routes/nearby.py index 09b9306..68f6e39 100644 --- a/backend/app/api/routes/nearby.py +++ b/backend/app/api/routes/nearby.py @@ -1,3 +1,5 @@ +import logging + from fastapi import APIRouter, Depends, Query from sqlalchemy.orm import Session @@ -8,6 +10,8 @@ from app.schemas.nearby import NearbyPlace, NearbyResponse from app.schemas.place import ContentOut from app.services.nearby_search import find_nearby +logger = logging.getLogger("guidecity.nearby") + router = APIRouter(tags=["nearby"]) @@ -32,6 +36,9 @@ def nearby( ), db: Session = Depends(get_db), ) -> NearbyResponse: + if speed is not None or heading is not None: + logger.debug("nearby called with reserved v2 params speed=%s heading=%s (ignored)", speed, heading) + result = find_nearby( db, lat=lat, diff --git a/backend/app/api/routes/places.py b/backend/app/api/routes/places.py index 26e545a..7393c2a 100644 --- a/backend/app/api/routes/places.py +++ b/backend/app/api/routes/places.py @@ -1,3 +1,5 @@ +import logging + from fastapi import APIRouter, Depends, HTTPException, Query from geoalchemy2 import Geometry from sqlalchemy import and_, cast, func, select @@ -13,6 +15,8 @@ from app.schemas.common import LatLon from app.schemas.place import ContentOut, PlaceDetail, PlaceListItem from app.services.geocoding import search_places +logger = logging.getLogger("guidecity.places") + router = APIRouter(tags=["places"]) @@ -56,6 +60,7 @@ def get_place( ) row = db.execute(stmt).first() if row is None: + logger.warning("place_id=%d not found for lang=%s length=%s", place_id, lang, length) raise HTTPException(status_code=404, detail="Place not found") place, content, lon, lat = row @@ -84,6 +89,7 @@ def list_city_places( ) -> list[PlaceListItem]: city = db.scalar(select(City).where(City.slug == city_slug)) if city is None: + logger.warning("city_slug=%r not found", city_slug) raise HTTPException(status_code=404, detail="City not found") stmt = ( @@ -111,6 +117,7 @@ def list_city_places( stmt = stmt.where(PlaceContent.title.ilike(f"%{q}%")) rows = db.execute(stmt).all() + logger.debug("city_slug=%r listing -> %d place(s)", city_slug, len(rows)) return [ PlaceListItem(id=p.id, slug=p.slug, category=p.category, name=pc.title, location=LatLon(lat=lat, lon=lon)) for p, pc, lon, lat in rows diff --git a/backend/app/config.py b/backend/app/config.py index 09195f7..e073dca 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -6,6 +6,7 @@ class Settings(BaseSettings): database_url: str = "postgresql+psycopg://guidecity:guidecity@localhost:5432/guidecity" api_v1_prefix: str = "/api/v1" + log_level: str = "INFO" settings = Settings() diff --git a/backend/app/core/logging.py b/backend/app/core/logging.py index a9dd3e3..66190dc 100644 --- a/backend/app/core/logging.py +++ b/backend/app/core/logging.py @@ -1,4 +1,11 @@ import logging +import time +from collections.abc import Awaitable, Callable + +from starlette.requests import Request +from starlette.responses import Response + +request_logger = logging.getLogger("guidecity.http") def configure_logging(level: int = logging.INFO) -> None: @@ -6,3 +13,25 @@ def configure_logging(level: int = logging.INFO) -> None: level=level, format="%(asctime)s %(levelname)s %(name)s %(message)s", ) + + +async def log_requests( + request: Request, + call_next: Callable[[Request], Awaitable[Response]], +) -> Response: + """Logs method/path/status/duration for every request handled by the app.""" + start = time.perf_counter() + try: + response = await call_next(request) + except Exception: + duration_ms = (time.perf_counter() - start) * 1000 + request_logger.exception( + "%s %s -> unhandled exception (%.1fms)", request.method, request.url.path, duration_ms + ) + raise + + duration_ms = (time.perf_counter() - start) * 1000 + request_logger.info( + "%s %s -> %d (%.1fms)", request.method, request.url.path, response.status_code, duration_ms + ) + return response diff --git a/backend/app/main.py b/backend/app/main.py index 2a6460f..076ac94 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -1,9 +1,26 @@ +import logging +from collections.abc import AsyncIterator +from contextlib import asynccontextmanager + from fastapi import FastAPI from app.api.routes import cities, health, nearby, places from app.config import settings +from app.core.logging import configure_logging, log_requests -app = FastAPI(title="guideCity API", version="0.1.0") +configure_logging(level=getattr(logging, settings.log_level.upper(), logging.INFO)) +logger = logging.getLogger("guidecity") + + +@asynccontextmanager +async def lifespan(_app: FastAPI) -> AsyncIterator[None]: + logger.info("guideCity API startup complete (log_level=%s)", settings.log_level) + yield + logger.info("guideCity API shutting down") + + +app = FastAPI(title="guideCity API", version="0.1.0", lifespan=lifespan) +app.middleware("http")(log_requests) app.include_router(health.router, prefix=settings.api_v1_prefix) app.include_router(cities.router, prefix=settings.api_v1_prefix) diff --git a/backend/app/services/geocoding.py b/backend/app/services/geocoding.py index 0637f36..400b6c5 100644 --- a/backend/app/services/geocoding.py +++ b/backend/app/services/geocoding.py @@ -4,6 +4,8 @@ Used when the user denies location permission and types a place of interest, or when 2GIS's own geocoding API isn't wired into a given client flow yet. """ +import logging + from geoalchemy2 import Geometry from sqlalchemy import and_, cast, func, select from sqlalchemy.orm import Session @@ -13,6 +15,8 @@ from app.models.enums import ContentLanguage, ContentLength from app.models.place import Place from app.models.place_content import PlaceContent +logger = logging.getLogger("guidecity.geocoding") + def search_places( db: Session, @@ -44,4 +48,6 @@ def search_places( if city_slug is not None: stmt = stmt.join(City, City.id == Place.city_id).where(City.slug == city_slug) - return db.execute(stmt).all() + results = db.execute(stmt).all() + logger.info("name search q=%r city_slug=%s lang=%s -> %d result(s)", q, city_slug, language, len(results)) + return results diff --git a/backend/app/services/nearby_search.py b/backend/app/services/nearby_search.py index 94c763f..c4f40d7 100644 --- a/backend/app/services/nearby_search.py +++ b/backend/app/services/nearby_search.py @@ -10,6 +10,7 @@ results toward the user's direction of travel and to pick a shorter content Not implemented in this iteration — callers should not pass them yet. """ +import logging from dataclasses import dataclass from geoalchemy2 import Geometry @@ -21,6 +22,8 @@ from app.models.enums import ContentLanguage, ContentLength from app.models.place import Place from app.models.place_content import PlaceContent +logger = logging.getLogger("guidecity.nearby_search") + @dataclass class NearbyResult: @@ -44,6 +47,14 @@ def find_nearby( city_id: int | None = None if city_slug is not None: city_id = db.scalar(select(City.id).where(City.slug == city_slug)) + if city_id is None: + logger.warning("city_slug=%r not found; searching across all cities", city_slug) + + logger.debug( + "nearby search starting: lat=%.5f lon=%.5f city_slug=%s lang=%s length=%s " + "min_results=%d initial_radius_m=%d step_m=%d max_radius_m=%d", + lat, lon, city_slug, language, length, min_results, initial_radius_m, step_m, max_radius_m, + ) origin = func.ST_GeogFromText(f"SRID=4326;POINT({lon} {lat})") distance_expr = func.ST_Distance(Place.location, origin) @@ -75,8 +86,16 @@ def find_nearby( while True: stmt = base_stmt.where(func.ST_DWithin(Place.location, origin, radius)) rows = db.execute(stmt).all() + logger.debug("radius=%dm -> %d place(s) found", radius, len(rows)) if len(rows) >= min_results or radius >= max_radius_m: break radius += step_m + if len(rows) < min_results: + logger.warning( + "hit max_radius_m=%dm with only %d/%d place(s) found near lat=%.5f lon=%.5f", + max_radius_m, len(rows), min_results, lat, lon, + ) + logger.info("nearby search done: radius=%dm count=%d", radius, len(rows)) + return NearbyResult(search_radius_m=radius, rows=rows) diff --git a/backend/seed/seed_loader.py b/backend/seed/seed_loader.py index 99daeb5..b34a19b 100644 --- a/backend/seed/seed_loader.py +++ b/backend/seed/seed_loader.py @@ -6,26 +6,33 @@ Usage: """ import argparse +import logging from pathlib import Path import yaml +from app.core.logging import configure_logging from app.db.session import SessionLocal from app.models.city import City from app.models.place import Place from app.models.place_content import PlaceContent +logger = logging.getLogger("guidecity.seed_loader") + def load_cities(path: Path) -> None: + logger.info("loading cities from %s", path) data = yaml.safe_load(path.read_text(encoding="utf-8")) db = SessionLocal() try: for c in data["cities"]: city = db.query(City).filter(City.slug == c["slug"]).one_or_none() if city is None: + logger.debug("creating new city slug=%r", c["slug"]) city = City(slug=c["slug"], name_ru=c["name_ru"], name_en=c["name_en"]) db.add(city) else: + logger.debug("updating existing city slug=%r", c["slug"]) city.name_ru = c["name_ru"] city.name_en = c["name_en"] center = c.get("center") @@ -33,7 +40,10 @@ def load_cities(path: Path) -> None: city.center_point = f"SRID=4326;POINT({center['lon']} {center['lat']})" db.flush() db.commit() - print(f"Loaded {len(data['cities'])} cities from {path.name}") + logger.info("loaded %d cities from %s", len(data["cities"]), path.name) + except Exception: + logger.exception("failed loading cities from %s", path) + raise finally: db.close() @@ -79,6 +89,7 @@ def _upsert_content(db, place_id: int, language: str, length: str, title: str, b def load_places(path: Path) -> None: + logger.info("loading places from %s", path) data = yaml.safe_load(path.read_text(encoding="utf-8")) city_slug = data["city"] @@ -86,11 +97,13 @@ def load_places(path: Path) -> None: try: city = db.query(City).filter(City.slug == city_slug).one_or_none() if city is None: + logger.error("city %r not found; run --cities seed/cities.yaml first", city_slug) raise SystemExit( f"City '{city_slug}' not found. Run `--cities seed/cities.yaml` first." ) for place_data in data["places"]: + logger.debug("upserting place slug=%r", place_data["slug"]) place = _upsert_place(db, city.id, place_data) titles = place_data.get("title", {}) for language, lengths in place_data["content"].items(): @@ -99,12 +112,16 @@ def load_places(path: Path) -> None: _upsert_content(db, place.id, language, length, title, body.strip()) db.commit() - print(f"Loaded {len(data['places'])} places from {path.name}") + logger.info("loaded %d places from %s", len(data["places"]), path.name) + except Exception: + logger.exception("failed loading places from %s", path) + raise finally: db.close() def main() -> None: + configure_logging() parser = argparse.ArgumentParser(description=__doc__) group = parser.add_mutually_exclusive_group(required=True) group.add_argument("--cities", help="Path to a cities YAML file") diff --git a/docker-compose.yml b/docker-compose.yml index 697da63..542ea37 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -19,6 +19,7 @@ services: build: ./backend environment: DATABASE_URL: postgresql+psycopg://${POSTGRES_USER}:${POSTGRES_PASSWORD}@db:5432/${POSTGRES_DB} + LOG_LEVEL: ${LOG_LEVEL:-INFO} ports: - "8000:8000" depends_on: