Merge pull request #483 from Routstr/more-logging-cleanup

remove and clean up redundant logs

routstr/auth.py

@@ -317,13 +317,13 @@ async def validate_bearer_key(
                 extra={"key_hash": hashed_key[:8] + "..."},
             )
 
-            logger.info(
+            logger.debug(
                 "AUTH: About to call credit_balance",
                 extra={"token_preview": bearer_key[:50]},
             )
             try:
                 msats = await credit_balance(bearer_key, new_key, session)
-                logger.info(
+                logger.debug(
                     "AUTH: credit_balance returned successfully", extra={"msats": msats}
                 )
             except Exception as credit_error:

routstr/core/db.py

@@ -79,11 +79,10 @@ class ApiKey(SQLModel, table=True):  # type: ignore
 
 
 async def reset_all_reserved_balances(session: AsyncSession) -> None:
-    logger.info("Resetting all reserved balances to 0")
     stmt = update(ApiKey).values(reserved_balance=0)
     await session.exec(stmt)  # type: ignore[call-overload]
     await session.commit()
-    logger.info("Reserved balances reset successfully")
+    logger.info("Reset reserved balances on startup")
 
 
 class ModelRow(SQLModel, table=True):  # type: ignore

routstr/core/exceptions.py

@@ -22,16 +22,20 @@ async def http_exception_handler(request: Request, exc: Exception) -> JSONRespon
     # Get status code and detail - works for both FastAPI and Starlette HTTPException
     status_code = getattr(exc, "status_code", 500)
     detail = getattr(exc, "detail", str(exc))
+    path = request.url.path
 
-    logger.warning(
-        "HTTP exception",
-        extra={
-            "request_id": request_id,
-            "status_code": status_code,
-            "detail": detail,
-            "path": request.url.path,
-        },
-    )
+    # 4xx is client behaviour; the uvicorn access log already records it.
+    # Only 5xx warrants a server-side warning/error log here.
+    if status_code >= 500:
+        logger.error(
+            f"HTTP {status_code} on {path}: {detail}",
+            extra={
+                "request_id": request_id,
+                "status_code": status_code,
+                "detail": detail,
+                "path": path,
+            },
+        )
 
     return JSONResponse(
         status_code=status_code,

routstr/core/logging.py

@@ -41,14 +41,23 @@ import logging.config
 import logging.handlers
 import os
 import re
+import sys
 import tomllib
 from datetime import datetime
 from pathlib import Path
 from typing import Any
 
 from pythonjsonlogger import jsonlogger
+from rich.console import Console
 from rich.logging import RichHandler
 
+# Only use RichHandler when stdout is a real TTY. In non-TTY contexts
+# (docker logs, pipes, CI) Rich pads every line to width and wraps long
+# records, producing visually-empty trailing whitespace and split records.
+# A plain StreamHandler avoids both problems.
+_stdout_is_tty = sys.stdout.isatty()
+_console = Console(soft_wrap=True) if _stdout_is_tty else None
+
 # Define custom TRACE level
 TRACE_LEVEL = 5
 logging.addLevelName(TRACE_LEVEL, "TRACE")
@@ -261,6 +270,26 @@ def setup_logging() -> None:
     if console_enabled:
         handlers.append("console")
 
+    if _stdout_is_tty:
+        console_handler: dict[str, Any] = {
+            "()": RichHandler,
+            "level": log_level,
+            "show_time": False,
+            "show_path": False,
+            "rich_tracebacks": True,
+            "markup": True,
+            "console": _console,
+            "filters": ["request_id_filter", "security_filter"],
+        }
+    else:
+        console_handler = {
+            "class": "logging.StreamHandler",
+            "level": log_level,
+            "formatter": "plain",
+            "stream": "ext://sys.stdout",
+            "filters": ["request_id_filter", "security_filter"],
+        }
+
     LOGGING_CONFIG = {
         "version": 1,
         "disable_existing_loggers": False,
@@ -270,6 +299,10 @@ def setup_logging() -> None:
                 "format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s %(request_id)s",
                 "datefmt": "%Y-%m-%d %H:%M:%S",
             },
+            "plain": {
+                "format": "%(asctime)s %(levelname)-7s %(name)s %(message)s",
+                "datefmt": "%Y-%m-%d %H:%M:%S",
+            },
         },
         "filters": {
             "version_filter": {"()": VersionFilter},
@@ -277,15 +310,7 @@ def setup_logging() -> None:
             "security_filter": {"()": SecurityFilter},
         },
         "handlers": {
-            "console": {
-                "()": RichHandler,
-                "level": log_level,
-                "show_time": False,
-                "show_path": False,
-                "rich_tracebacks": True,
-                "markup": True,
-                "filters": ["request_id_filter", "security_filter"],
-            },
+            "console": console_handler,
             "file": {
                 "()": DailyRotatingFileHandler,
                 "level": log_level,

routstr/payment/models.py

@@ -350,6 +350,9 @@ async def _update_sats_pricing_once() -> None:
     from ..proxy import get_upstreams, refresh_model_maps
 
     upstreams = get_upstreams()
+    if not upstreams:
+        return
+
     sats_to_usd = sats_usd_price()
 
     updated_count = 0
@@ -363,7 +366,10 @@ async def _update_sats_pricing_once() -> None:
         updated_count += len(updated_models)
 
     if updated_count > 0:
-        logger.info("Updated sats pricing", extra={"models_updated": updated_count})
+        logger.info(
+            f"Updated sats pricing for {updated_count} models",
+            extra={"models_updated": updated_count},
+        )
         await refresh_model_maps()
 
 

routstr/upstream/helpers.py

@@ -197,13 +197,14 @@ async def init_upstreams() -> list[BaseUpstreamProvider]:
         existing_providers = result.all()
 
         if not existing_providers:
-            logger.info(
-                "No upstream providers found in database, seeding from settings"
-            )
             await _seed_providers_from_settings(session, settings)
             await session.commit()
             result = await session.exec(select(UpstreamProviderRow))
             existing_providers = result.all()
+            if existing_providers:
+                logger.info(
+                    f"Seeded {len(existing_providers)} upstream providers from settings"
+                )
 
         async def _init_single_provider(
             provider_row: UpstreamProviderRow,

routstr/wallet.py

@@ -326,7 +326,7 @@ async def credit_balance(
         except Exception:
             pass
 
-        logger.info(
+        logger.debug(
             "Cashu token successfully redeemed and stored",
             extra={"amount": amount, "unit": unit, "mint_url": mint_url},
         )
@@ -488,7 +488,7 @@ async def fetch_all_balances(
 
 async def periodic_payout() -> None:
     if not settings.receive_ln_address:
-        logger.error("RECEIVE_LN_ADDRESS is not set, skipping payout")
+        logger.warning("RECEIVE_LN_ADDRESS is not set, periodic payout disabled")
         return
     while True:
         await asyncio.sleep(60 * 15)