From 38f9923469bf18dbb76af2a2881a85dadad9aedc Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Fri, 1 May 2026 22:51:29 +0200 Subject: [PATCH] remove and clean up redundant logs --- routstr/auth.py | 4 ++-- routstr/core/db.py | 3 +-- routstr/core/exceptions.py | 22 +++++++++++-------- routstr/core/logging.py | 43 +++++++++++++++++++++++++++++-------- routstr/payment/models.py | 8 ++++++- routstr/upstream/helpers.py | 7 +++--- routstr/wallet.py | 4 ++-- 7 files changed, 63 insertions(+), 28 deletions(-) diff --git a/routstr/auth.py b/routstr/auth.py index df761938..c08ed555 100644 --- a/routstr/auth.py +++ b/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: diff --git a/routstr/core/db.py b/routstr/core/db.py index a0992a62..1a253479 100644 --- a/routstr/core/db.py +++ b/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 diff --git a/routstr/core/exceptions.py b/routstr/core/exceptions.py index 64111047..4262f91c 100644 --- a/routstr/core/exceptions.py +++ b/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, diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 14b1b1ff..fac0100f 100644 --- a/routstr/core/logging.py +++ b/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, diff --git a/routstr/payment/models.py b/routstr/payment/models.py index afed3238..17910749 100644 --- a/routstr/payment/models.py +++ b/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() diff --git a/routstr/upstream/helpers.py b/routstr/upstream/helpers.py index 535b6fef..9ad4d73f 100644 --- a/routstr/upstream/helpers.py +++ b/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, diff --git a/routstr/wallet.py b/routstr/wallet.py index dee6625b..360447d6 100644 --- a/routstr/wallet.py +++ b/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)