improve logging

Rm shaky test

routstr/algorithm.py

@@ -150,18 +150,6 @@ def should_prefer_model(
     # Prefer lower adjusted cost
     should_replace = candidate_adjusted < current_adjusted
 
-    # Log provider changes when candidate wins
-    if should_replace:
-        candidate_provider_name = getattr(
-            candidate_provider, "provider_type", "unknown"
-        )
-        current_provider_name = getattr(current_provider, "provider_type", "unknown")
-        logger.debug(
-            f"Model selection for alias '{alias}': choosing {candidate_provider_name} "
-            f"(cost: ${candidate_adjusted:.6f}) over {current_provider_name} "
-            f"(cost: ${current_adjusted:.6f})"
-        )
-
     return should_replace
 
 

routstr/core/db.py

@@ -126,8 +126,6 @@ def run_migrations() -> None:
     import pathlib
 
     try:
-        logger.info("Starting database migrations")
-
         # Get the path to the alembic.ini file
         project_root = pathlib.Path(__file__).resolve().parents[2]
         alembic_ini_path = project_root / "alembic.ini"
@@ -144,7 +142,6 @@ def run_migrations() -> None:
         alembic_cfg.set_main_option("sqlalchemy.url", DATABASE_URL)
 
         # Run migrations to the latest revision
-        logger.info("Running migrations to latest revision")
         command.upgrade(alembic_cfg, "head")
 
         logger.info("Database migrations completed successfully")

routstr/core/logging.py

@@ -338,6 +338,11 @@ def setup_logging() -> None:
                 "handlers": ["console"] if console_enabled else [],
                 "propagate": False,
             },
+            "openai": {
+                "level": "WARNING",
+                "handlers": ["console"] if console_enabled else [],
+                "propagate": False,
+            },
             "httpcore": {
                 "level": "WARNING",
                 "handlers": ["console"] if console_enabled else [],
@@ -360,6 +365,11 @@ def setup_logging() -> None:
             },
             "watchfiles.main": {"level": "WARNING", "handlers": [], "propagate": False},
             "aiosqlite": {"level": "ERROR", "handlers": [], "propagate": False},
+            "alembic": {
+                "level": "WARNING",
+                "handlers": ["console"] if console_enabled else [],
+                "propagate": False,
+            },
         },
         "root": {
             "level": log_level,

routstr/core/main.py

@@ -54,9 +54,6 @@ async def lifespan(_: FastAPI) -> AsyncGenerator[None, None]:
 
     try:
         # Run database migrations on startup
-        # This ensures the database schema is always up-to-date in production
-        # Migrations are idempotent - running them multiple times is safe
-        logger.info("Running database migrations")
         run_migrations()
 
         # Initialize database connection pools
@@ -104,6 +101,9 @@ async def lifespan(_: FastAPI) -> AsyncGenerator[None, None]:
 
         yield
 
+    except asyncio.CancelledError:
+        # Expected during shutdown
+        pass
     except Exception as e:
         logger.error(
             "Application startup failed",

routstr/payment/price.py

@@ -110,10 +110,6 @@ async def _update_prices() -> None:
         return
     BTC_USD_PRICE = btc_price
     SATS_USD_PRICE = btc_price / 100_000_000
-    logger.info(
-        "Updated BTC/USD price",
-        extra={"btc_usd": btc_price, "sats_usd": SATS_USD_PRICE},
-    )
 
 
 def btc_usd_price() -> float:

routstr/upstream/base.py

@@ -1726,7 +1726,6 @@ class BaseUpstreamProvider:
         Returns:
             List of Model objects with pricing
         """
-        logger.debug(f"Fetching models for {self.provider_type or self.base_url}")
 
         try:
             or_models, provider_models_response = await asyncio.gather(
@@ -1753,18 +1752,9 @@ class BaseUpstreamProvider:
                 else:
                     not_found_models.append(model_id)
 
-            logger.info(
-                "Fetched models for provider",
-                extra={
-                    "provider": self.provider_type or self.base_url,
-                    "found_count": len(found_models),
-                    "not_found_count": len(not_found_models),
-                },
-            )
-
             if not_found_models:
                 logger.debug(
-                    "Models not found in OpenRouter",
+                    f"({len(not_found_models)}/{len(provider_model_ids)}) unmatched models for {self.provider_type or self.base_url}",
                     extra={"not_found_models": not_found_models},
                 )
 
@@ -1832,10 +1822,7 @@ class BaseUpstreamProvider:
                 self._models_cache = models_with_fees
 
             self._models_by_id = {m.id: m for m in self._models_cache}
-            logger.info(
-                f"Refreshed models cache for {self.provider_type or self.base_url}",
-                extra={"model_count": len(models)},
-            )
+
         except Exception as e:
             logger.error(
                 f"Failed to refresh models cache for {self.provider_type or self.base_url}",

routstr/upstream/helpers.py

@@ -193,7 +193,7 @@ async def init_upstreams() -> list[BaseUpstreamProvider]:
             if provider:
                 await provider.refresh_models_cache()
                 upstreams.append(provider)
-                logger.info(
+                logger.debug(
                     f"Initialized {provider_row.provider_type} provider",
                     extra={
                         "base_url": provider_row.base_url,

routstr/upstream/ppqai.py

@@ -102,11 +102,6 @@ class PPQAIUpstreamProvider(BaseUpstreamProvider):
         url = f"{self.base_url}/models"
         headers = {"Authorization": f"Bearer {self.api_key}"}
 
-        logger.debug(
-            "Fetching models from PPQ.AI",
-            extra={"url": url, "has_api_key": bool(self.api_key)},
-        )
-
         try:
             async with httpx.AsyncClient(timeout=30.0) as client:
                 response = await client.get(url, headers=headers)
@@ -114,10 +109,6 @@ class PPQAIUpstreamProvider(BaseUpstreamProvider):
                 data = response.json()
 
                 models_data = data.get("data", [])
-                logger.info(
-                    "Fetched models from PPQ.AI",
-                    extra={"model_count": len(models_data)},
-                )
 
                 or_models = [
                     Model(**model)  # type: ignore
@@ -198,15 +189,6 @@ class PPQAIUpstreamProvider(BaseUpstreamProvider):
 
                 return models
 
-        except httpx.HTTPStatusError as e:
-            logger.error(
-                "HTTP error fetching models from PPQ.AI",
-                extra={
-                    "status_code": e.response.status_code,
-                    "error": str(e),
-                },
-            )
-            return []
         except Exception as e:
             logger.error(
                 "Error fetching models from PPQ.AI",