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 <noreply@anthropic.com>

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

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,

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

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()

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

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)

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

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)

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")