laantungir/routstr-core
1
0
Fork 0
mirror of https://github.com/Routstr/routstr-core.git synced 2026-08-09 02:54:37 +00:00
Code Issues Packages Projects Releases Wiki Activity

Merge upstream main and resolve uv.lock conflict

Browse Source
This commit is contained in:
Kyle Santiago
2025-07-31 14:16:33 -04:00
parent a2cbc6060d ee38d0011c
commit 588ad0e7e9
15 changed files with 2900 additions and 597 deletions
Download Patch File Download Diff File Expand all files Collapse all files
.gitignore
+6 -1
View File
@@ -15,5 +15,10 @@ compose.override.yml
# Coverage
.coverage
# deployment
# Logging
logs/*
!logs/.gitkeep
*.log
# deployment
proof_backups
compose.yml
+1
View File
@@ -5,6 +5,7 @@ services:
build: .
volumes:
- .:/app
- ./logs:/app/logs
env_file:
- .env
environment:
logs/.gitkeep
View File
pyproject.toml
+1
View File
@@ -11,6 +11,7 @@ dependencies = [
"sqlmodel>=0.0.24",
"httpx[socks]>=0.25.2",
"greenlet>=3.2.1",
"python-json-logger>=2.0.0",
]
[dependency-groups]
router/auth.py
+343 -6
View File
@@ -6,6 +6,7 @@ from sqlmodel import col, update
from .cashu import credit_balance
from .db import ApiKey, AsyncSession
from .logging.logging_config import get_logger
from .payment.cost_caculation import (
CostData,
CostDataError,
@@ -14,6 +15,8 @@ from .payment.cost_caculation import (
)
from .payment.helpers import get_max_cost_for_model
logger = get_logger(__name__)
# TODO: implement prepaid api key (not like it was before)
# PREPAID_API_KEY = os.environ.get("PREPAID_API_KEY", None)
# PREPAID_BALANCE = int(os.environ.get("PREPAID_BALANCE", "0")) * 1000 # Convert to msats
@@ -30,7 +33,19 @@ async def validate_bearer_key(
If it's a cashu key, it redeems it and stores its hash and balance.
Otherwise checks if the hash of the key exists.
"""
logger.debug(
"Starting bearer key validation",
extra={
"key_preview": bearer_key[:20] + "..."
if len(bearer_key) > 20
else bearer_key,
"has_refund_address": bool(refund_address),
"has_expiry_time": bool(key_expiry_time),
},
)
if not bearer_key:
logger.error("Empty bearer key provided")
raise HTTPException(
status_code=401,
detail={
@@ -43,23 +58,108 @@ async def validate_bearer_key(
)
if bearer_key.startswith("sk-"):
logger.debug(
"Processing sk- prefixed API key",
extra={"key_preview": bearer_key[:10] + "..."},
)
if existing_key := await session.get(ApiKey, bearer_key[3:]):
logger.info(
"Existing sk- API key found",
extra={
"key_hash": existing_key.hashed_key[:8] + "...",
"balance": existing_key.balance,
"total_requests": existing_key.total_requests,
},
)
if key_expiry_time is not None:
existing_key.key_expiry_time = key_expiry_time
logger.debug(
"Updated key expiry time",
extra={
"key_hash": existing_key.hashed_key[:8] + "...",
"expiry_time": key_expiry_time,
},
)
if refund_address is not None:
existing_key.refund_address = refund_address
logger.debug(
"Updated refund address",
extra={
"key_hash": existing_key.hashed_key[:8] + "...",
"refund_address_preview": refund_address[:20] + "..."
if len(refund_address) > 20
else refund_address,
},
)
return existing_key
else:
logger.warning(
"sk- API key not found in database",
extra={"key_preview": bearer_key[:10] + "..."},
)
if bearer_key.startswith("cashu"):
logger.debug(
"Processing Cashu token",
extra={
"token_preview": bearer_key[:20] + "...",
"token_type": bearer_key[:6] if len(bearer_key) >= 6 else bearer_key,
},
)
try:
hashed_key = hashlib.sha256(bearer_key.encode()).hexdigest()
logger.debug(
"Generated token hash", extra={"hash_preview": hashed_key[:16] + "..."}
)
if existing_key := await session.get(ApiKey, hashed_key):
logger.info(
"Existing Cashu token found",
extra={
"key_hash": existing_key.hashed_key[:8] + "...",
"balance": existing_key.balance,
"total_requests": existing_key.total_requests,
},
)
if key_expiry_time is not None:
existing_key.key_expiry_time = key_expiry_time
logger.debug(
"Updated key expiry time for existing Cashu key",
extra={
"key_hash": existing_key.hashed_key[:8] + "...",
"expiry_time": key_expiry_time,
},
)
if refund_address is not None:
existing_key.refund_address = refund_address
logger.debug(
"Updated refund address for existing Cashu key",
extra={
"key_hash": existing_key.hashed_key[:8] + "...",
"refund_address_preview": refund_address[:20] + "..."
if len(refund_address) > 20
else refund_address,
},
)
return existing_key
logger.info(
"Creating new Cashu token entry",
extra={
"hash_preview": hashed_key[:16] + "...",
"has_refund_address": bool(refund_address),
"has_expiry_time": bool(key_expiry_time),
},
)
new_key = ApiKey(
hashed_key=hashed_key,
balance=0,
@@ -68,14 +168,44 @@ async def validate_bearer_key(
)
session.add(new_key)
await session.flush()
logger.debug(
"New key created, starting token redemption",
extra={"key_hash": hashed_key[:8] + "..."},
)
msats = await credit_balance(bearer_key, new_key, session)
if msats <= 0:
logger.error(
"Token redemption returned zero or negative amount",
extra={"msats": msats, "key_hash": hashed_key[:8] + "..."},
)
raise Exception("Token redemption failed")
await session.refresh(new_key)
await session.commit()
logger.info(
"New Cashu token successfully redeemed and stored",
extra={
"key_hash": hashed_key[:8] + "...",
"redeemed_msats": msats,
"final_balance": new_key.balance,
},
)
return new_key
except Exception as e:
print(f"Redemption failed: {e}")
logger.error(
"Cashu token redemption failed",
extra={
"error": str(e),
"error_type": type(e).__name__,
"token_preview": bearer_key[:20] + "..."
if len(bearer_key) > 20
else bearer_key,
},
)
raise HTTPException(
status_code=401,
detail={
@@ -86,6 +216,17 @@ async def validate_bearer_key(
}
},
)
logger.error(
"Invalid API key format",
extra={
"key_preview": bearer_key[:10] + "..."
if len(bearer_key) > 10
else bearer_key,
"key_length": len(bearer_key),
},
)
raise HTTPException(
status_code=401,
detail={
@@ -98,10 +239,34 @@ async def validate_bearer_key(
)
async def pay_for_request(key: ApiKey, session: AsyncSession, body: dict) -> None:
cost_per_request = get_max_cost_for_model(model=body["model"])
async def pay_for_request(key: ApiKey, session: AsyncSession, body: dict) -> int:
"""Process payment for a request."""
model = body["model"]
cost_per_request = get_max_cost_for_model(model=model)
logger.info(
"Processing payment for request",
extra={
"key_hash": key.hashed_key[:8] + "...",
"current_balance": key.balance,
"required_cost": cost_per_request,
"model": model,
"sufficient_balance": key.balance >= cost_per_request,
},
)
if key.balance < cost_per_request:
logger.warning(
"Insufficient balance for request",
extra={
"key_hash": key.hashed_key[:8] + "...",
"balance": key.balance,
"required": cost_per_request,
"shortfall": cost_per_request - key.balance,
"model": model,
},
)
raise HTTPException(
status_code=402,
detail={
@@ -113,6 +278,15 @@ async def pay_for_request(key: ApiKey, session: AsyncSession, body: dict) -> Non
},
)
logger.debug(
"Charging base cost for request",
extra={
"key_hash": key.hashed_key[:8] + "...",
"cost": cost_per_request,
"balance_before": key.balance,
},
)
# Charge the base cost for the request atomically to avoid race conditions
stmt = (
update(ApiKey)
@@ -126,7 +300,17 @@ async def pay_for_request(key: ApiKey, session: AsyncSession, body: dict) -> Non
)
result = await session.exec(stmt) # type: ignore[call-overload]
await session.commit()
if result.rowcount == 0:
logger.error(
"Concurrent request depleted balance",
extra={
"key_hash": key.hashed_key[:8] + "...",
"required_cost": cost_per_request,
"current_balance": key.balance,
},
)
# Another concurrent request spent the balance first
raise HTTPException(
status_code=402,
@@ -138,6 +322,50 @@ async def pay_for_request(key: ApiKey, session: AsyncSession, body: dict) -> Non
}
},
)
await session.refresh(key)
logger.info(
"Payment processed successfully",
extra={
"key_hash": key.hashed_key[:8] + "...",
"charged_amount": cost_per_request,
"new_balance": key.balance,
"total_spent": key.total_spent,
"total_requests": key.total_requests,
"model": model,
},
)
return cost_per_request
async def revert_pay_for_request(
key: ApiKey, session: AsyncSession, cost_per_request: int
) -> None:
stmt = (
update(ApiKey)
.where(col(ApiKey.hashed_key) == key.hashed_key)
.values(
balance=col(ApiKey.balance) + cost_per_request,
total_spent=col(ApiKey.total_spent) - cost_per_request,
total_requests=col(ApiKey.total_requests) - 1,
)
)
result = await session.exec(stmt) # type: ignore[call-overload]
await session.commit()
if result.rowcount == 0:
raise HTTPException(
status_code=402,
detail={
"error": {
"message": f"failed to revert request payment: {cost_per_request} mSats required. {key.balance} available.",
"type": "payment_error",
"code": "payment_error",
}
},
)
await session.refresh(key)
@@ -149,25 +377,81 @@ async def adjust_payment_for_tokens(
This is called after the initial payment and the upstream request is complete.
Returns cost data to be included in the response.
"""
max_cost = get_max_cost_for_model(model=response_data["model"])
model = response_data.get("model", "unknown")
max_cost = get_max_cost_for_model(model=model)
logger.debug(
"Starting payment adjustment for tokens",
extra={
"key_hash": key.hashed_key[:8] + "...",
"model": model,
"max_cost": max_cost,
"current_balance": key.balance,
"has_usage": "usage" in response_data,
},
)
match calculate_cost(response_data, max_cost):
case MaxCostData() as cost:
logger.debug(
"Using max cost data (no token adjustment)",
extra={
"key_hash": key.hashed_key[:8] + "...",
"model": model,
"max_cost": cost.total_msats,
},
)
return cost.dict()
case CostData() as cost:
# If token-based pricing is enabled and base cost is 0, use token-based cost
# Otherwise, token cost is additional to the base cost
cost_difference = cost.total_msats - max_cost
logger.info(
"Calculated token-based cost",
extra={
"key_hash": key.hashed_key[:8] + "...",
"model": model,
"token_cost": cost.total_msats,
"max_cost": max_cost,
"cost_difference": cost_difference,
"input_msats": cost.input_msats,
"output_msats": cost.output_msats,
},
)
if cost_difference == 0:
logger.debug(
"No cost adjustment needed",
extra={"key_hash": key.hashed_key[:8] + "...", "model": model},
)
await session.commit()
return cost.dict()
if cost_difference > 0:
# Need to charge more
logger.info(
"Additional charge required for token usage",
extra={
"key_hash": key.hashed_key[:8] + "...",
"additional_charge": cost_difference,
"current_balance": key.balance,
"sufficient_balance": key.balance >= cost_difference,
"model": model,
},
)
if key.balance < cost_difference:
print(
f"Warning: Insufficient balance for token-based pricing adjustment: {key.hashed_key[:10]}..."
logger.warning(
"Insufficient balance for token-based pricing adjustment",
extra={
"key_hash": key.hashed_key[:8] + "...",
"required": cost_difference,
"available": key.balance,
"shortfall": cost_difference - key.balance,
"model": model,
},
)
await session.commit()
else:
@@ -182,12 +466,43 @@ async def adjust_payment_for_tokens(
)
result = await session.exec(charge_stmt) # type: ignore[call-overload]
await session.commit()
if result.rowcount:
cost.total_msats = max_cost + cost_difference
await session.refresh(key)
logger.info(
"Additional charge applied successfully",
extra={
"key_hash": key.hashed_key[:8] + "...",
"charged_amount": cost_difference,
"new_balance": key.balance,
"total_cost": cost.total_msats,
"model": model,
},
)
else:
logger.warning(
"Failed to apply additional charge (concurrent operation)",
extra={
"key_hash": key.hashed_key[:8] + "...",
"attempted_charge": cost_difference,
"model": model,
},
)
else:
# Refund some of the base cost
refund = abs(cost_difference)
logger.info(
"Refunding excess payment",
extra={
"key_hash": key.hashed_key[:8] + "...",
"refund_amount": refund,
"current_balance": key.balance,
"model": model,
},
)
refund_stmt = (
update(ApiKey)
.where(col(ApiKey.hashed_key) == key.hashed_key)
@@ -201,8 +516,30 @@ async def adjust_payment_for_tokens(
cost.total_msats = max_cost - refund
await session.refresh(key)
logger.info(
"Refund processed successfully",
extra={
"key_hash": key.hashed_key[:8] + "...",
"refunded_amount": refund,
"new_balance": key.balance,
"final_cost": cost.total_msats,
"model": model,
},
)
return cost.dict()
case CostDataError() as error:
logger.error(
"Cost calculation error during payment adjustment",
extra={
"key_hash": key.hashed_key[:8] + "...",
"model": model,
"error_message": error.message,
"error_code": error.code,
},
)
raise HTTPException(
status_code=400,
detail={
router/cashu.py
+353 -26
View File
@@ -8,6 +8,9 @@ from sixty_nuts.types import CurrencyUnit
from sqlmodel import col, func, select, update
from .db import ApiKey, AsyncSession, get_session
from .logging.logging_config import get_logger
logger = get_logger(__name__)
RECEIVE_LN_ADDRESS = os.environ["RECEIVE_LN_ADDRESS"]
MINT = os.environ.get("MINT", "https://mint.minibits.cash/Bitcoin")
@@ -18,17 +21,40 @@ DEV_LN_ADDRESS = "routstr@minibits.cash"
DEVS_DONATION_RATE = float(os.environ.get("DEVS_DONATION_RATE", 0.021)) # 2.1%
NSEC = os.environ["NSEC"] # Nostr private key for the wallet
logger.info(
"Cashu module initialized",
extra={
"mint": MINT,
"minimum_payout": MINIMUM_PAYOUT,
"refund_processing_interval": REFUND_PROCESSING_INTERVAL,
"payout_interval": PAYOUT_INTERVAL,
"devs_donation_rate": DEVS_DONATION_RATE,
},
)
wallet_instance: Wallet | None = None
async def init_wallet() -> None:
"""Initialize the Cashu wallet."""
global wallet_instance
wallet_instance = await Wallet.create(nsec=NSEC)
try:
logger.info("Initializing Cashu wallet", extra={"mint": MINT})
wallet_instance = await Wallet.create(nsec=NSEC)
logger.info("Cashu wallet initialized successfully")
except Exception as e:
logger.error(
"Failed to initialize Cashu wallet",
extra={"error": str(e), "error_type": type(e).__name__, "mint": MINT},
)
raise
def wallet() -> Wallet:
"""Get the wallet instance."""
global wallet_instance
if wallet_instance is None:
logger.error("Wallet not initialized - call init_wallet() first")
raise ValueError("Wallet not initialized")
return wallet_instance
@@ -36,6 +62,10 @@ def wallet() -> Wallet:
async def delete_key_if_zero_balance(key: ApiKey, session: AsyncSession) -> None:
"""Delete the given API key if its balance is zero."""
if key.balance == 0:
logger.info(
"Deleting API key with zero balance",
extra={"key_hash": key.hashed_key[:8] + "...", "balance": key.balance},
)
await session.delete(key)
await session.commit()
@@ -45,6 +75,7 @@ async def pay_out() -> None:
Calculates the pay-out amount based on the spent balance, profit, and donation rate.
"""
try:
logger.debug("Starting payout process")
from .db import create_session
async with create_session() as session:
@@ -53,57 +84,151 @@ async def pay_out() -> None:
)
balance = result.one_or_none()
if not balance:
# No balance to pay out - this is OK, not an error
logger.debug("No balance to pay out")
return
user_balance_sats = balance // 1000
wallet_balance_sats = await wallet().get_balance()
logger.debug(
"Payout calculation",
extra={
"user_balance_sats": user_balance_sats,
"wallet_balance_sats": wallet_balance_sats,
},
)
# Handle edge cases more gracefully
if wallet_balance_sats < user_balance_sats:
print(
f"Warning: Wallet balance ({wallet_balance_sats} sats) is less than user balance ({user_balance_sats} sats). Skipping payout."
logger.warning(
"Insufficient wallet balance for payout",
extra={
"wallet_balance_sats": wallet_balance_sats,
"user_balance_sats": user_balance_sats,
"shortfall_sats": user_balance_sats - wallet_balance_sats,
},
)
return
if (revenue := wallet_balance_sats - user_balance_sats) <= MINIMUM_PAYOUT:
# Not enough revenue yet - this is OK
logger.debug(
"Revenue below minimum payout threshold",
extra={"revenue_sats": revenue, "minimum_payout": MINIMUM_PAYOUT},
)
return
devs_donation = int(revenue * DEVS_DONATION_RATE)
owners_draw = revenue - devs_donation
logger.info(
"Processing payout",
extra={
"revenue_sats": revenue,
"devs_donation_sats": devs_donation,
"owners_draw_sats": owners_draw,
"donation_rate": DEVS_DONATION_RATE,
},
)
# Send payouts
await wallet().send_to_lnurl(RECEIVE_LN_ADDRESS, owners_draw)
await wallet().send_to_lnurl(DEV_LN_ADDRESS, devs_donation)
try:
await wallet().send_to_lnurl(RECEIVE_LN_ADDRESS, owners_draw)
logger.info(
"Owner payout sent successfully",
extra={
"amount_sats": owners_draw,
"address": RECEIVE_LN_ADDRESS[:10] + "...",
},
)
await wallet().send_to_lnurl(DEV_LN_ADDRESS, devs_donation)
logger.info(
"Developer donation sent successfully",
extra={"amount_sats": devs_donation, "address": DEV_LN_ADDRESS},
)
except Exception as payout_error:
logger.error(
"Failed to send payouts",
extra={
"error": str(payout_error),
"error_type": type(payout_error).__name__,
"owners_draw_sats": owners_draw,
"devs_donation_sats": devs_donation,
},
)
raise
except Exception as e:
print(f"Error in pay_out: {e}")
logger.error(
"Error in payout process",
extra={"error": str(e), "error_type": type(e).__name__},
)
# Periodic payout task
async def periodic_payout() -> None:
"""Periodically process payouts."""
logger.info("Starting periodic payout task", extra={"interval_seconds": 300})
while True:
try:
await asyncio.sleep(300) # Run every 5 minutes
await pay_out()
except asyncio.CancelledError:
logger.info("Periodic payout task cancelled")
break
except Exception as e:
print(f"Error in periodic payout: {e}")
logger.error(
"Error in periodic payout",
extra={"error": str(e), "error_type": type(e).__name__},
)
# Continue running even if payout fails
async def credit_balance(cashu_token: str, key: ApiKey, session: AsyncSession) -> int:
"""Redeem a Cashu token and credit the amount to the API key balance."""
logger.debug(
"Starting token redemption",
extra={
"key_hash": key.hashed_key[:8] + "...",
"token_preview": cashu_token[:20] + "..."
if len(cashu_token) > 20
else cashu_token,
},
)
try:
amount, unit = await wallet().redeem(cashu_token)
logger.info(
"Token redeemed successfully",
extra={
"amount": amount,
"unit": unit,
"key_hash": key.hashed_key[:8] + "...",
},
)
except Exception as e:
print(f"Error in credit_balance: {e}")
# Ensure the balance cannot become negative if redeem fails
logger.error(
"Token redemption failed",
extra={
"error": str(e),
"error_type": type(e).__name__,
"key_hash": key.hashed_key[:8] + "...",
"token_preview": cashu_token[:20] + "..."
if len(cashu_token) > 20
else cashu_token,
},
)
return 0
if amount <= 0:
logger.warning(
"Zero or negative amount redeemed",
extra={
"amount": amount,
"unit": unit,
"key_hash": key.hashed_key[:8] + "...",
},
)
return 0
if unit == "msat":
@@ -111,6 +236,16 @@ async def credit_balance(cashu_token: str, key: ApiKey, session: AsyncSession) -
else:
amount_msats = amount * 1000
logger.debug(
"Crediting balance",
extra={
"amount_msats": amount_msats,
"original_amount": amount,
"unit": unit,
"key_hash": key.hashed_key[:8] + "...",
},
)
# Apply the balance change atomically to avoid race conditions when topping
# up the same key concurrently.
stmt = (
@@ -122,6 +257,15 @@ async def credit_balance(cashu_token: str, key: ApiKey, session: AsyncSession) -
await session.commit()
await session.refresh(key)
logger.info(
"Balance credited successfully",
extra={
"credited_msats": amount_msats,
"new_balance_msats": key.balance,
"key_hash": key.hashed_key[:8] + "...",
},
)
return amount_msats
@@ -134,15 +278,23 @@ async def check_for_refunds() -> None:
"""
# Setting REFUND_PROCESSING_INTERVAL to 0 disables it
if REFUND_PROCESSING_INTERVAL == 0:
print("Automatic refund processing is disabled.")
logger.info("Automatic refund processing is disabled")
return
logger.info(
"Starting refund monitoring task",
extra={"interval_seconds": REFUND_PROCESSING_INTERVAL},
)
while True:
try:
logger.debug("Checking for expired keys requiring refunds")
async for session in get_session():
result = await session.exec(select(ApiKey))
keys = result.all()
current_time = int(time.time())
expired_keys = []
for key in keys:
if (
key.balance > 0
@@ -150,28 +302,87 @@ async def check_for_refunds() -> None:
and key.key_expiry_time
and key.key_expiry_time < current_time
):
print(
f" DEBUG Refunding key {key.hashed_key[:3] + '[...]' + key.hashed_key[-3:]}, Current Time: {current_time}, Expirary Time: {key.key_expiry_time}",
flush=True,
)
expired_keys.append(key)
if expired_keys:
logger.info(
"Found expired keys for refund",
extra={
"expired_count": len(expired_keys),
"current_time": current_time,
},
)
for key in expired_keys:
logger.info(
"Processing refund for expired key",
extra={
"key_hash": key.hashed_key[:8] + "...",
"balance_msats": key.balance,
"expiry_time": key.key_expiry_time,
"current_time": current_time,
"expired_seconds": current_time
- (key.key_expiry_time or 0),
},
)
try:
await refund_balance(key.balance, key, session)
await delete_key_if_zero_balance(key, session)
logger.info(
"Refund processed successfully",
extra={"key_hash": key.hashed_key[:8] + "..."},
)
except Exception as refund_error:
logger.error(
"Failed to process refund",
extra={
"error": str(refund_error),
"error_type": type(refund_error).__name__,
"key_hash": key.hashed_key[:8] + "...",
"balance_msats": key.balance,
},
)
# Sleep for the specified interval before checking again
await asyncio.sleep(REFUND_PROCESSING_INTERVAL)
except asyncio.CancelledError:
logger.info("Refund monitoring task cancelled")
break
except Exception as e:
print(f"Error during refund check: {e}")
logger.error(
"Error during refund check",
extra={"error": str(e), "error_type": type(e).__name__},
)
async def refund_balance(amount_msats: int, key: ApiKey, session: AsyncSession) -> int:
"""Process a refund for an API key."""
if amount_msats <= 0:
amount_msats = key.balance
logger.info(
"Processing balance refund",
extra={
"amount_msats": amount_msats,
"key_hash": key.hashed_key[:8] + "...",
"refund_address": key.refund_address[:20] + "..."
if key.refund_address and len(key.refund_address) > 20
else key.refund_address,
},
)
# Convert msats to sats for cashu wallet
amount_sats = amount_msats // 1000
if amount_sats == 0:
logger.error(
"Amount too small to refund",
extra={
"amount_msats": amount_msats,
"amount_sats": amount_sats,
"key_hash": key.hashed_key[:8] + "...",
},
)
raise ValueError("Amount too small to refund (less than 1 sat)")
# Atomically deduct the balance to avoid race conditions when multiple
@@ -184,26 +395,142 @@ async def refund_balance(amount_msats: int, key: ApiKey, session: AsyncSession)
)
result = await session.exec(stmt) # type: ignore[call-overload]
await session.commit()
if result.rowcount == 0:
logger.error(
"Insufficient balance for refund",
extra={
"requested_msats": amount_msats,
"key_hash": key.hashed_key[:8] + "...",
"current_balance": key.balance,
},
)
raise ValueError("Insufficient balance.")
await session.refresh(key)
await delete_key_if_zero_balance(key, session)
if key.refund_address is None:
logger.error(
"Refund address not set", extra={"key_hash": key.hashed_key[:8] + "..."}
)
raise ValueError("Refund address not set.")
return await wallet().send_to_lnurl(key.refund_address, amount=amount_sats)
try:
result = await wallet().send_to_lnurl(key.refund_address, amount=amount_sats)
logger.info(
"Refund sent successfully",
extra={
"amount_sats": amount_sats,
"refund_address": key.refund_address[:20] + "..."
if len(key.refund_address) > 20
else key.refund_address,
"key_hash": key.hashed_key[:8] + "...",
"transaction_result": str(result),
},
)
return result
except Exception as e:
logger.error(
"Failed to send refund",
extra={
"error": str(e),
"error_type": type(e).__name__,
"amount_sats": amount_sats,
"refund_address": key.refund_address,
"key_hash": key.hashed_key[:8] + "...",
},
)
raise
async def x_cashu_refund(key: ApiKey, session: AsyncSession, unit: CurrencyUnit) -> str:
refund_token = await wallet().send(key.balance, unit=unit)
await session.delete(key)
await session.commit()
return refund_token
"""Process an X-Cashu refund token."""
logger.info(
"Processing X-Cashu refund",
extra={
"balance_msats": key.balance,
"unit": unit,
"key_hash": key.hashed_key[:8] + "...",
},
)
try:
refund_token = await wallet().send(key.balance, unit=unit)
logger.info(
"X-Cashu refund token created",
extra={
"amount": key.balance,
"unit": unit,
"key_hash": key.hashed_key[:8] + "...",
"token_preview": refund_token[:20] + "..."
if len(refund_token) > 20
else refund_token,
},
)
await session.delete(key)
await session.commit()
logger.info(
"X-Cashu refund completed", extra={"key_hash": key.hashed_key[:8] + "..."}
)
return refund_token
except Exception as e:
logger.error(
"Failed to create X-Cashu refund",
extra={
"error": str(e),
"error_type": type(e).__name__,
"balance": key.balance,
"unit": unit,
"key_hash": key.hashed_key[:8] + "...",
},
)
raise
async def redeem(cashu_token: str, lnurl: str) -> int:
amount, unit = await wallet().redeem(cashu_token)
unit = cast(CurrencyUnit, unit)
await wallet().send_to_lnurl(lnurl, amount=amount, unit=unit)
return amount
"""Redeem a Cashu token and send to LNURL."""
logger.info(
"Starting token redemption for LNURL",
extra={
"token_preview": cashu_token[:20] + "..."
if len(cashu_token) > 20
else cashu_token,
"lnurl_preview": lnurl[:20] + "..." if len(lnurl) > 20 else lnurl,
},
)
try:
amount, unit = await wallet().redeem(cashu_token)
logger.info("Token redeemed for LNURL", extra={"amount": amount, "unit": unit})
unit = cast(CurrencyUnit, unit)
result = await wallet().send_to_lnurl(lnurl, amount=amount, unit=unit)
logger.info(
"Successfully sent to LNURL",
extra={
"amount": amount,
"unit": unit,
"lnurl_preview": lnurl[:20] + "..." if len(lnurl) > 20 else lnurl,
"transaction_result": str(result),
},
)
return amount
except Exception as e:
logger.error(
"Failed to redeem and send to LNURL",
extra={
"error": str(e),
"error_type": type(e).__name__,
"token_preview": cashu_token[:20] + "..."
if len(cashu_token) > 20
else cashu_token,
"lnurl_preview": lnurl[:20] + "..." if len(lnurl) > 20 else lnurl,
},
)
raise
router/logging/__init__.py
View File
router/logging/logging_config.py
+253
View File
@@ -0,0 +1,253 @@
import logging.config
import logging.handlers
import os
import re
import tomllib
from datetime import datetime
from pathlib import Path
from typing import Any
from pythonjsonlogger import jsonlogger
class DailyRotatingFileHandler(logging.handlers.TimedRotatingFileHandler):
"""Custom TimedRotatingFileHandler that creates date-based filenames."""
def __init__(self, filename: str, **kwargs: Any) -> None:
"""Initialize with a base filename pattern."""
self.base_dir = os.path.dirname(filename)
self.base_name = os.path.basename(filename).replace(".log", "")
today = datetime.now().strftime("%Y-%m-%d")
self.current_date = today
dated_filename = os.path.join(self.base_dir, f"{self.base_name}_{today}.log")
super().__init__(dated_filename, **kwargs)
def doRollover(self) -> None:
"""Override rollover to create new date-based filename."""
if self.stream:
self.stream.close()
new_date = datetime.now().strftime("%Y-%m-%d")
new_filename = os.path.join(self.base_dir, f"{self.base_name}_{new_date}.log")
self.baseFilename = new_filename
self.current_date = new_date
# FIX ME: not sure if we need this
# self._cleanup_old_files()
if not self.delay:
self.stream = self._open()
def _cleanup_old_files(self) -> None:
"""Remove old log files beyond backupCount."""
if self.backupCount > 0:
log_files = []
if os.path.exists(self.base_dir):
for file in os.listdir(self.base_dir):
if file.startswith(f"{self.base_name}_") and file.endswith(".log"):
file_path = os.path.join(self.base_dir, file)
log_files.append((file_path, os.path.getmtime(file_path)))
log_files.sort(key=lambda x: x[1], reverse=True)
for file_path, _ in log_files[self.backupCount :]:
try:
os.remove(file_path)
except OSError:
pass
def get_package_version() -> str:
"""Read the package version from pyproject.toml."""
try:
# Find project root by looking for pyproject.toml
current_path = Path(__file__).parent
while current_path != current_path.parent:
pyproject_path = current_path / "pyproject.toml"
if pyproject_path.exists():
with open(pyproject_path, "rb") as f:
pyproject_data = tomllib.load(f)
version = pyproject_data.get("project", {}).get("version", "unknown")
return version
current_path = current_path.parent
# Fallback: try the simple path resolution (3 levels up for router/logging/logging_config.py)
pyproject_path = Path(__file__).parent.parent.parent / "pyproject.toml"
if pyproject_path.exists():
with open(pyproject_path, "rb") as f:
pyproject_data = tomllib.load(f)
version = pyproject_data.get("project", {}).get("version", "unknown")
return version
return "unknown"
except Exception:
return "unknown"
class VersionFilter(logging.Filter):
"""Filter to add package version to all log records."""
def __init__(self) -> None:
super().__init__()
self.version = get_package_version()
def filter(self, record: logging.LogRecord) -> bool:
"""Add version information to the log record."""
record.version = self.version
return True
class SecurityFilter(logging.Filter):
"""Filter to remove sensitive information from logs."""
SENSITIVE_KEYS = {
"authorization",
"x-cashu",
"bearer",
"token",
"key",
"secret",
"password",
"cashu_token",
"bearer_key",
"api_key",
"nsec",
"upstream_api_key",
"refund_address",
}
def filter(self, record: logging.LogRecord) -> bool:
"""Filter out sensitive information from log records."""
try:
message = record.getMessage()
for key in self.SENSITIVE_KEYS:
if key in message.lower():
patterns = [
rf"{key}[:\s=]+([a-zA-Z0-9_\-\.]+)", # key: value or key=value
rf'{key}[:\s=]+["\']([^"\']+)["\']', # key: "value" or key='value'
r"Bearer\s+([a-zA-Z0-9_\-\.]+)", # Bearer token
r"cashu[A-Z]+([a-zA-Z0-9_\-\.=/+]+)", # Cashu tokens
]
for pattern in patterns:
message = re.sub(
pattern, f"{key}: [REDACTED]", message, flags=re.IGNORECASE
)
record.msg = message
record.args = ()
except Exception:
pass
return True
def get_log_level() -> str:
"""Get log level from environment variable."""
return os.environ.get("LOG_LEVEL", "INFO").upper()
def setup_logging() -> None:
"""Configure centralized logging for the application."""
log_level = get_log_level()
LOGGING_CONFIG = {
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"json": {
"()": jsonlogger.JsonFormatter,
"format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s",
"datefmt": "%Y-%m-%d %H:%M:%S",
},
"standard": {
"format": "%(asctime)s [%(levelname)s] %(name)s v%(version)s: %(message)s",
"datefmt": "%Y-%m-%d %H:%M:%S",
},
},
"filters": {
"version_filter": {"()": VersionFilter},
"security_filter": {"()": SecurityFilter},
},
"handlers": {
"console": {
"class": "logging.StreamHandler",
"level": log_level,
"formatter": "json"
if os.environ.get("LOG_FORMAT", "json").lower() == "json"
else "standard",
"stream": "ext://sys.stdout",
"filters": ["version_filter", "security_filter"],
},
"file": {
"()": DailyRotatingFileHandler,
"level": log_level,
"formatter": "json",
"filename": "logs/app.log",
"when": "midnight", # Rotate at midnight each day
"interval": 1, # Every 1 day
"backupCount": 30, # Keep 30 days of logs
"atTime": None, # Rotate at midnight (00:00)
"filters": ["version_filter", "security_filter"],
},
},
"loggers": {
"router": {
"level": log_level,
"handlers": ["console", "file"],
"propagate": False,
},
"router.payment": {
"level": log_level,
"handlers": ["console", "file"],
"propagate": False,
},
"router.cashu": {
"level": log_level,
"handlers": ["console", "file"],
"propagate": False,
},
"router.proxy": {
"level": log_level,
"handlers": ["console", "file"],
"propagate": False,
},
"router.auth": {
"level": log_level,
"handlers": ["console", "file"],
"propagate": False,
},
# Suppress verbose third-party logging
"httpx": {
"level": "WARNING",
"handlers": ["console"],
"propagate": False,
},
"httpcore": {
"level": "WARNING",
"handlers": ["console"],
"propagate": False,
},
"uvicorn.access": {
"level": "WARNING",
"handlers": ["console"],
"propagate": False,
},
},
"root": {"level": log_level, "handlers": ["console"]},
}
os.makedirs("logs", exist_ok=True)
logging.config.dictConfig(LOGGING_CONFIG)
def get_logger(name: str) -> logging.Logger:
"""Get a logger instance for the given module name."""
return logging.getLogger(name)
router/main.py
+52 -9
View File
@@ -11,30 +11,62 @@ from .admin import admin_router
from .cashu import check_for_refunds, init_wallet, periodic_payout
from .db import init_db
from .discovery import providers_router
from .logging.logging_config import get_logger, setup_logging
from .models import MODELS, models_router, update_sats_pricing
from .proxy import proxy_router
# Initialize logging first
setup_logging()
logger = get_logger(__name__)
__version__ = "0.0.1"
@asynccontextmanager
async def lifespan(_: FastAPI) -> AsyncGenerator[None, None]:
await init_db()
await init_wallet()
pricing_task = asyncio.create_task(update_sats_pricing())
refund_task = asyncio.create_task(check_for_refunds())
payout_task = asyncio.create_task(periodic_payout())
logger.info("Application startup initiated", extra={"version": __version__})
try:
await init_db()
logger.info("Database initialized successfully")
await init_wallet()
logger.info("Wallet initialized successfully")
pricing_task = asyncio.create_task(update_sats_pricing())
refund_task = asyncio.create_task(check_for_refunds())
payout_task = asyncio.create_task(periodic_payout())
logger.info(
"Background tasks started successfully",
extra={"tasks": ["pricing", "refunds", "payouts"]},
)
yield
except Exception as e:
logger.error(
"Application startup failed",
extra={"error": str(e), "error_type": type(e).__name__},
)
raise
finally:
logger.info("Application shutdown initiated")
refund_task.cancel()
pricing_task.cancel()
payout_task.cancel()
await asyncio.gather(
pricing_task, refund_task, payout_task, return_exceptions=True
)
try:
await asyncio.gather(
pricing_task, refund_task, payout_task, return_exceptions=True
)
logger.info("Background tasks stopped successfully")
except Exception as e:
logger.error(
"Error stopping background tasks",
extra={"error": str(e), "error_type": type(e).__name__},
)
app = FastAPI(
@@ -54,9 +86,15 @@ app.add_middleware(
allow_headers=["*"],
)
logger.info(
"CORS middleware configured",
extra={"allowed_origins": os.environ.get("CORS_ORIGINS", "*").split(",")},
)
@app.get("/")
async def info() -> dict:
logger.info("Info endpoint accessed")
return {
"name": app.title,
"description": app.description,
@@ -74,3 +112,8 @@ app.include_router(admin_router)
app.include_router(wallet_router)
app.include_router(providers_router)
app.include_router(proxy_router)
logger.info(
"Application initialized successfully",
extra={"version": __version__, "routers_count": 5},
)
router/payment/cost_caculation.py
+86 -2
View File
@@ -2,8 +2,11 @@ import os
from pydantic import BaseModel
from router.logging.logging_config import get_logger
from router.models import MODELS
logger = get_logger(__name__)
COST_PER_REQUEST = (
int(os.environ.get("COST_PER_REQUEST", "1")) * 1000
) # Convert to msats
@@ -15,6 +18,16 @@ COST_PER_1K_OUTPUT_TOKENS = (
) # Convert to msats
MODEL_BASED_PRICING = os.environ.get("MODEL_BASED_PRICING", "false").lower() == "true"
logger.info(
"Cost calculation initialized",
extra={
"cost_per_request_msats": COST_PER_REQUEST,
"cost_per_1k_input_tokens_msats": COST_PER_1K_INPUT_TOKENS,
"cost_per_1k_output_tokens_msats": COST_PER_1K_OUTPUT_TOKENS,
"model_based_pricing": MODEL_BASED_PRICING,
},
)
class CostData(BaseModel):
base_msats: int
@@ -35,6 +48,25 @@ class CostDataError(BaseModel):
def calculate_cost(
response_data: dict, max_cost: int
) -> CostData | MaxCostData | CostDataError:
"""
Calculate the cost of an API request based on token usage.
Args:
response_data: Response data containing usage information
max_cost: Maximum cost in millisats
Returns:
Cost data or error information
"""
logger.debug(
"Starting cost calculation",
extra={
"max_cost_msats": max_cost,
"has_usage_data": "usage" in response_data,
"response_model": response_data.get("model", "unknown"),
},
)
cost_data = MaxCostData(
base_msats=max_cost,
input_msats=0,
@@ -43,7 +75,13 @@ def calculate_cost(
)
if "usage" not in response_data or response_data["usage"] is None:
print("No usage data in response, using base cost only")
logger.warning(
"No usage data in response, using base cost only",
extra={
"max_cost_msats": max_cost,
"model": response_data.get("model", "unknown"),
},
)
return cost_data
MSATS_PER_1K_INPUT_TOKENS = COST_PER_1K_INPUT_TOKENS
@@ -51,7 +89,22 @@ def calculate_cost(
if MODEL_BASED_PRICING and MODELS:
response_model = response_data.get("model", "")
logger.debug(
"Using model-based pricing",
extra={
"model": response_model,
"available_models": [model.id for model in MODELS],
},
)
if response_model not in [model.id for model in MODELS]:
logger.error(
"Invalid model in response",
extra={
"response_model": response_model,
"available_models": [model.id for model in MODELS],
},
)
return CostDataError(
message=f"Invalid model in response: {response_model}",
code="model_not_found",
@@ -59,6 +112,10 @@ def calculate_cost(
model = next(model for model in MODELS if model.id == response_model)
if model.sats_pricing is None:
logger.error(
"Model pricing not defined",
extra={"model": response_model, "model_id": model.id},
)
return CostDataError(
message="Model pricing not defined", code="pricing_not_found"
)
@@ -66,8 +123,23 @@ def calculate_cost(
MSATS_PER_1K_INPUT_TOKENS = model.sats_pricing.prompt * 1_000_000 # type: ignore
MSATS_PER_1K_OUTPUT_TOKENS = model.sats_pricing.completion * 1_000_000 # type: ignore
logger.info(
"Applied model-specific pricing",
extra={
"model": response_model,
"input_price_msats_per_1k": MSATS_PER_1K_INPUT_TOKENS,
"output_price_msats_per_1k": MSATS_PER_1K_OUTPUT_TOKENS,
},
)
if not (MSATS_PER_1K_OUTPUT_TOKENS and MSATS_PER_1K_INPUT_TOKENS):
# If no token pricing is configured, just return base cost
logger.warning(
"No token pricing configured, using base cost",
extra={
"base_cost_msats": max_cost,
"model": response_data.get("model", "unknown"),
},
)
return cost_data
input_tokens = response_data.get("usage", {}).get("prompt_tokens", 0)
@@ -77,6 +149,18 @@ def calculate_cost(
output_msats = int(round(output_tokens / 1000 * MSATS_PER_1K_OUTPUT_TOKENS, 0))
token_based_cost = int(round(input_msats + output_msats, 0))
logger.info(
"Calculated token-based cost",
extra={
"input_tokens": input_tokens,
"output_tokens": output_tokens,
"input_cost_msats": input_msats,
"output_cost_msats": output_msats,
"total_cost_msats": token_based_cost,
"model": response_data.get("model", "unknown"),
},
)
return CostData(
base_msats=0,
input_msats=input_msats,
router/payment/helpers.py
+286 -37
View File
@@ -6,29 +6,87 @@ import cbor2
from fastapi import HTTPException, Response
from sixty_nuts.types import CurrencyUnit
from router.logging.logging_config import get_logger
from router.models import MODELS
from router.payment.cost_caculation import COST_PER_REQUEST, MODEL_BASED_PRICING
logger = get_logger(__name__)
UPSTREAM_BASE_URL = os.environ["UPSTREAM_BASE_URL"]
UPSTREAM_API_KEY = os.environ.get("UPSTREAM_API_KEY", "")
logger.info(
"Payment helpers initialized",
extra={
"upstream_base_url": UPSTREAM_BASE_URL,
"has_upstream_api_key": bool(UPSTREAM_API_KEY),
"model_based_pricing": MODEL_BASED_PRICING,
},
)
def get_cost_per_request(model: str | None = None) -> int:
"""Get the cost per request for a given model."""
logger.debug(
"Calculating cost per request",
extra={
"model": model,
"model_based_pricing": MODEL_BASED_PRICING,
"has_models": bool(MODELS),
},
)
if MODEL_BASED_PRICING and MODELS and model:
return get_max_cost_for_model(model=model)
cost = get_max_cost_for_model(model=model)
logger.debug(
"Using model-based cost", extra={"model": model, "cost_msats": cost}
)
return cost
logger.debug(
"Using default cost per request", extra={"cost_msats": COST_PER_REQUEST}
)
return COST_PER_REQUEST
def check_token_balance(headers: dict, body: dict) -> CurrencyUnit:
"""Check if the provided token has sufficient balance."""
logger.debug(
"Checking token balance",
extra={
"has_x_cashu": "x-cashu" in headers,
"has_authorization": "authorization" in headers,
"model": body.get("model", "unknown"),
},
)
if x_cashu := headers.get("x-cashu", None):
cashu_token = x_cashu
logger.debug(
"Using X-Cashu token",
extra={
"token_preview": cashu_token[:20] + "..."
if len(cashu_token) > 20
else cashu_token
},
)
elif auth := headers.get("authorization", None):
cashu_token = auth.split(" ")[1] if len(auth.split(" ")) > 1 else ""
logger.debug(
"Using Authorization header token",
extra={
"token_preview": cashu_token[:20] + "..."
if len(cashu_token) > 20
else cashu_token
},
)
else:
logger.error("No authentication token provided")
raise HTTPException(status_code=401, detail="Unauthorized")
# Handle empty token
if not cashu_token:
logger.error("Empty token provided")
raise HTTPException(
status_code=401,
detail={
@@ -42,64 +100,230 @@ def check_token_balance(headers: dict, body: dict) -> CurrencyUnit:
# Handle regular API keys (sk-*)
if cashu_token.startswith("sk-"):
# For regular API keys, return default unit
logger.debug(
"Regular API key detected", extra={"key_preview": cashu_token[:10] + "..."}
)
return "sat"
cost = get_cost_per_request(model=body.get("model", None))
if cashu_token.startswith("cashuA"):
_token = base64_token_json(cashu_token)
amount = sum(p["amount"] for t in _token["token"] for p in t["proofs"])
unit: CurrencyUnit = _token["unit"]
if unit == "sat":
amount *= 1000
if amount < cost:
raise HTTPException(status_code=413, detail="Insufficient balance")
logger.debug("Processing CashuA token", extra={"required_cost_msats": cost})
try:
_token = base64_token_json(cashu_token)
amount = sum(p["amount"] for t in _token["token"] for p in t["proofs"])
unit: CurrencyUnit = _token["unit"]
if unit == "sat":
amount *= 1000
logger.info(
"CashuA token parsed successfully",
extra={
"amount": amount,
"unit": _token["unit"],
"amount_msats": amount,
"required_cost_msats": cost,
"sufficient_balance": amount >= cost,
},
)
if amount < cost:
logger.warning(
"Insufficient token balance",
extra={
"amount_msats": amount,
"required_msats": cost,
"shortfall_msats": cost - amount,
"unit": unit,
},
)
raise HTTPException(status_code=413, detail="Insufficient balance")
except Exception as e:
logger.error(
"Failed to parse CashuA token",
extra={
"error": str(e),
"error_type": type(e).__name__,
"token_preview": cashu_token[:20] + "...",
},
)
raise HTTPException(status_code=401, detail="Invalid token format")
elif cashu_token.startswith("cashuB"):
_token = base64_token_cbor(cashu_token)
amount = sum(p["a"] for t in _token["t"] for p in t["p"])
unit = _token["u"]
if unit == "sat":
amount *= 1000
if amount < cost:
raise HTTPException(status_code=413, detail="Insufficient balance")
logger.debug("Processing CashuB token", extra={"required_cost_msats": cost})
try:
_token = base64_token_cbor(cashu_token)
amount = sum(p["a"] for t in _token["t"] for p in t["p"])
unit = _token["u"]
if unit == "sat":
amount *= 1000
logger.info(
"CashuB token parsed successfully",
extra={
"amount": amount,
"unit": unit,
"amount_msats": amount,
"required_cost_msats": cost,
"sufficient_balance": amount >= cost,
},
)
if amount < cost:
logger.warning(
"Insufficient token balance",
extra={
"amount_msats": amount,
"required_msats": cost,
"shortfall_msats": cost - amount,
"unit": unit,
},
)
raise HTTPException(status_code=413, detail="Insufficient balance")
except Exception as e:
logger.error(
"Failed to parse CashuB token",
extra={
"error": str(e),
"error_type": type(e).__name__,
"token_preview": cashu_token[:20] + "...",
},
)
raise HTTPException(status_code=401, detail="Invalid token format")
else:
logger.error(
"Unknown token format",
extra={"token_prefix": cashu_token[:10] if cashu_token else "empty"},
)
raise HTTPException(status_code=401, detail="Unauthorized")
return unit
def base64_token_json(cashu_token: str) -> dict:
# Version 3 - JSON format
encoded = cashu_token[6:] # Remove "cashuA"
# Add correct padding – (-len) % 4 equals 0,1,2,3
encoded += "=" * ((-len(encoded)) % 4)
"""Decode a CashuA (JSON) token."""
logger.debug("Decoding CashuA token", extra={"token_length": len(cashu_token)})
decoded = base64.urlsafe_b64decode(encoded).decode()
token_data = json.loads(decoded)
try:
# Version 3 - JSON format
encoded = cashu_token[6:] # Remove "cashuA"
# Add correct padding – (-len) % 4 equals 0,1,2,3
encoded += "=" * ((-len(encoded)) % 4)
return token_data
decoded = base64.urlsafe_b64decode(encoded).decode()
token_data = json.loads(decoded)
logger.debug(
"CashuA token decoded successfully",
extra={
"token_proofs_count": sum(
len(t.get("proofs", [])) for t in token_data.get("token", [])
),
"unit": token_data.get("unit", "unknown"),
},
)
return token_data
except Exception as e:
logger.error(
"Failed to decode CashuA token",
extra={"error": str(e), "error_type": type(e).__name__},
)
raise
def base64_token_cbor(cashu_token: str) -> dict:
encoded = cashu_token[6:] # Remove "cashuB"
encoded += "=" * ((-len(encoded)) % 4)
decoded_bytes = base64.urlsafe_b64decode(encoded)
token_data = cbor2.loads(decoded_bytes)
return token_data
"""Decode a CashuB (CBOR) token."""
logger.debug("Decoding CashuB token", extra={"token_length": len(cashu_token)})
try:
encoded = cashu_token[6:] # Remove "cashuB"
encoded += "=" * ((-len(encoded)) % 4)
decoded_bytes = base64.urlsafe_b64decode(encoded)
token_data = cbor2.loads(decoded_bytes)
logger.debug(
"CashuB token decoded successfully",
extra={
"token_proofs_count": sum(
len(t.get("p", [])) for t in token_data.get("t", [])
),
"unit": token_data.get("u", "unknown"),
},
)
return token_data
except Exception as e:
logger.error(
"Failed to decode CashuB token",
extra={"error": str(e), "error_type": type(e).__name__},
)
raise
def get_max_cost_for_model(model: str) -> int:
"""Get the maximum cost for a specific model."""
logger.debug(
"Getting max cost for model",
extra={
"model": model,
"model_based_pricing": MODEL_BASED_PRICING,
"has_models": bool(MODELS),
},
)
if not MODEL_BASED_PRICING or not MODELS:
logger.debug(
"Using default cost (no model-based pricing)",
extra={"cost_msats": COST_PER_REQUEST, "model": model},
)
return COST_PER_REQUEST
if model not in [model.id for model in MODELS]:
logger.warning(
"Model not found in available models",
extra={
"requested_model": model,
"available_models": [m.id for m in MODELS],
"using_default_cost": COST_PER_REQUEST,
},
)
return COST_PER_REQUEST
for m in MODELS:
if m.id == model:
return m.sats_pricing.max_cost * 1000 # type: ignore
max_cost = m.sats_pricing.max_cost * 1000 # type: ignore
logger.debug(
"Found model-specific max cost",
extra={"model": model, "max_cost_msats": max_cost},
)
return int(max_cost)
logger.warning(
"Model pricing not found, using default",
extra={"model": model, "default_cost_msats": COST_PER_REQUEST},
)
return COST_PER_REQUEST
def create_error_response(error_type: str, message: str, status_code: int) -> Response:
"""Create a standardized error response."""
logger.info(
"Creating error response",
extra={
"error_type": error_type,
"error_message": message,
"status_code": status_code,
},
)
return Response(
content=json.dumps(
{
@@ -117,20 +341,45 @@ def create_error_response(error_type: str, message: str, status_code: int) -> Re
def prepare_upstream_headers(request_headers: dict) -> dict:
"""Prepare headers for upstream request, removing sensitive/problematic ones."""
logger.debug(
"Preparing upstream headers",
extra={
"original_headers_count": len(request_headers),
"has_upstream_api_key": bool(UPSTREAM_API_KEY),
},
)
headers = dict(request_headers)
# Remove headers that shouldn't be forwarded
headers.pop("host", None)
headers.pop("content-length", None)
headers.pop("refund-lnurl", None)
headers.pop("key-expiry-time", None)
headers.pop("x-cashu", None)
removed_headers = []
for header in [
"host",
"content-length",
"refund-lnurl",
"key-expiry-time",
"x-cashu",
]:
if headers.pop(header, None) is not None:
removed_headers.append(header)
# Handle authorization
if UPSTREAM_API_KEY:
headers["Authorization"] = f"Bearer {UPSTREAM_API_KEY}"
headers.pop("authorization", None)
if headers.pop("authorization", None) is not None:
removed_headers.append("authorization (replaced with upstream key)")
else:
headers.pop("Authorization", None)
headers.pop("authorization", None)
for auth_header in ["Authorization", "authorization"]:
if headers.pop(auth_header, None) is not None:
removed_headers.append(auth_header)
logger.debug(
"Headers prepared for upstream",
extra={
"final_headers_count": len(headers),
"removed_headers": removed_headers,
"added_upstream_auth": bool(UPSTREAM_API_KEY),
},
)
return headers
router/payment/x_cashu.py
+378 -36
View File
@@ -8,6 +8,7 @@ from fastapi.responses import Response, StreamingResponse
from sixty_nuts.types import CurrencyUnit
from router.cashu import wallet
from router.logging.logging_config import get_logger
from router.payment.cost_caculation import (
CostData,
CostDataError,
@@ -21,14 +22,46 @@ from router.payment.helpers import (
prepare_upstream_headers,
)
logger = get_logger(__name__)
async def x_cashu_handler(
request: Request, x_cashu_token: str, path: str
) -> Response | StreamingResponse:
headers = dict(request.headers)
amount, unit = await redeem_token(x_cashu_token)
headers = prepare_upstream_headers(dict(request.headers))
return await forward_to_upstream(request, path, headers, amount, unit)
"""Handle X-Cashu token payment requests."""
logger.info(
"Processing X-Cashu payment request",
extra={
"path": path,
"method": request.method,
"token_preview": x_cashu_token[:20] + "..."
if len(x_cashu_token) > 20
else x_cashu_token,
},
)
try:
headers = dict(request.headers)
amount, unit = await redeem_token(x_cashu_token)
headers = prepare_upstream_headers(dict(request.headers))
logger.info(
"X-Cashu token redeemed successfully",
extra={"amount": amount, "unit": unit, "path": path},
)
return await forward_to_upstream(request, path, headers, amount, unit)
except Exception as e:
logger.error(
"X-Cashu payment request failed",
extra={
"error": str(e),
"error_type": type(e).__name__,
"path": path,
"method": request.method,
},
)
raise
async def forward_to_upstream(
@@ -39,6 +72,18 @@ async def forward_to_upstream(
path = path.replace("v1/", "")
url = f"{UPSTREAM_BASE_URL}/{path}"
logger.debug(
"Forwarding request to upstream",
extra={
"url": url,
"method": request.method,
"path": path,
"amount": amount,
"unit": unit,
},
)
async with httpx.AsyncClient(
transport=httpx.AsyncHTTPTransport(retries=1),
timeout=None,
@@ -55,8 +100,40 @@ async def forward_to_upstream(
stream=True,
)
logger.debug(
"Received upstream response",
extra={
"status_code": response.status_code,
"path": path,
"response_headers": dict(response.headers),
},
)
if response.status_code != 200:
refund_token = await send_refund(amount, unit)
logger.warning(
"Upstream request failed, processing refund",
extra={
"status_code": response.status_code,
"path": path,
"amount": amount,
"unit": unit,
},
)
refund_token = await send_refund(amount - 60, unit)
logger.info(
"Refund processed for failed upstream request",
extra={
"status_code": response.status_code,
"refund_amount": amount,
"unit": unit,
"refund_token_preview": refund_token[:20] + "..."
if len(refund_token) > 20
else refund_token,
},
)
error_response = Response(
content=json.dumps(
{
@@ -75,6 +152,11 @@ async def forward_to_upstream(
return error_response
if path.endswith("chat/completions"):
logger.debug(
"Processing chat completion response",
extra={"path": path, "amount": amount, "unit": unit},
)
result = await handle_x_cashu_chat_completion(response, amount, unit)
background_tasks = BackgroundTasks()
background_tasks.add_task(response.aclose)
@@ -85,6 +167,11 @@ async def forward_to_upstream(
background_tasks.add_task(response.aclose)
background_tasks.add_task(client.aclose)
logger.debug(
"Streaming non-chat response",
extra={"path": path, "status_code": response.status_code},
)
return StreamingResponse(
response.aiter_bytes(),
status_code=response.status_code,
@@ -93,11 +180,17 @@ async def forward_to_upstream(
)
except Exception as exc:
tb = traceback.format_exc()
print(
f"Unexpected error: {exc}\n"
f"Request details: method={request.method}, url={url}, headers={headers}, "
f"path={path}, query_params={dict(request.query_params)}\n"
f"Traceback:\n{tb}"
logger.error(
"Unexpected error in upstream forwarding",
extra={
"error": str(exc),
"error_type": type(exc).__name__,
"method": request.method,
"url": url,
"path": path,
"query_params": dict(request.query_params),
"traceback": tb,
},
)
return create_error_response(
"internal_error", "An unexpected server error occurred", 500
@@ -108,11 +201,26 @@ async def handle_x_cashu_chat_completion(
response: httpx.Response, amount: int, unit: CurrencyUnit
) -> StreamingResponse | Response:
"""Handle both streaming and non-streaming chat completion responses with token-based pricing."""
logger.debug(
"Handling chat completion response",
extra={"amount": amount, "unit": unit, "status_code": response.status_code},
)
try:
content = await response.aread()
content_str = content.decode("utf-8") if isinstance(content, bytes) else content
is_streaming = content_str.startswith("data:") or "data:" in content_str
logger.debug(
"Chat completion response analysis",
extra={
"is_streaming": is_streaming,
"content_length": len(content_str),
"amount": amount,
"unit": unit,
},
)
if is_streaming:
return await handle_streaming_response(content_str, response, amount, unit)
else:
@@ -121,7 +229,15 @@ async def handle_x_cashu_chat_completion(
)
except Exception as e:
print(f"Error processing chat completion response: {e}")
logger.error(
"Error processing chat completion response",
extra={
"error": str(e),
"error_type": type(e).__name__,
"amount": amount,
"unit": unit,
},
)
# Return the original response if we can't process it
return StreamingResponse(
response.aiter_bytes(),
@@ -134,6 +250,22 @@ async def handle_streaming_response(
content_str: str, response: httpx.Response, amount: int, unit: CurrencyUnit
) -> StreamingResponse:
"""Handle Server-Sent Events (SSE) streaming response."""
logger.debug(
"Processing streaming response",
extra={
"amount": amount,
"unit": unit,
"content_lines": len(content_str.strip().split("\n")),
},
)
# Initialize response headers early so they can be modified during processing
response_headers = dict(response.headers)
if "transfer-encoding" in response_headers:
del response_headers["transfer-encoding"]
if "content-encoding" in response_headers:
del response_headers["content-encoding"]
# For streaming responses, we'll extract the final usage data
# and calculate cost based on that
usage_data = None
@@ -157,21 +289,66 @@ async def handle_streaming_response(
response_headers = dict(response.headers)
# If we found usage data, calculate cost and refund
if usage_data and model:
logger.debug(
"Found usage data in streaming response",
extra={
"model": model,
"usage_data": usage_data,
"amount": amount,
"unit": unit,
},
)
response_data = {"usage": usage_data, "model": model}
try:
cost_data = await get_cost(response_data)
if cost_data:
refund_amount = amount - cost_data.total_msats
if refund_amount > 0:
logger.info(
"Processing refund for streaming response",
extra={
"original_amount": amount,
"cost_msats": cost_data.total_msats,
"refund_amount": refund_amount,
"unit": unit,
"model": model,
},
)
refund_token = await send_refund(refund_amount, unit)
response_headers["X-Cashu"] = refund_token
except Exception as e:
print(f"Error calculating cost for streaming response: {e}")
if "transfer-encoding" in response_headers:
del response_headers["transfer-encoding"]
if "content-encoding" in response_headers:
del response_headers["content-encoding"]
logger.info(
"Refund processed for streaming response",
extra={
"refund_amount": refund_amount,
"unit": unit,
"refund_token_preview": refund_token[:20] + "..."
if len(refund_token) > 20
else refund_token,
},
)
else:
logger.debug(
"No refund needed for streaming response",
extra={
"amount": amount,
"cost_msats": cost_data.total_msats,
"model": model,
},
)
except Exception as e:
logger.error(
"Error calculating cost for streaming response",
extra={
"error": str(e),
"error_type": type(e).__name__,
"model": model,
"amount": amount,
"unit": unit,
},
)
async def generate() -> AsyncGenerator[bytes, None]:
for line in lines:
@@ -189,12 +366,25 @@ async def handle_non_streaming_response(
content_str: str, response: httpx.Response, amount: int, unit: CurrencyUnit
) -> Response:
"""Handle regular JSON response."""
logger.debug(
"Processing non-streaming response",
extra={"amount": amount, "unit": unit, "content_length": len(content_str)},
)
try:
response_json = json.loads(content_str)
cost_data = await get_cost(response_json)
if not cost_data:
logger.error(
"Failed to calculate cost for response",
extra={
"amount": amount,
"unit": unit,
"response_model": response_json.get("model", "unknown"),
},
)
return Response(
content=json.dumps(
{
@@ -216,11 +406,32 @@ async def handle_non_streaming_response(
del response_headers["content-encoding"]
refund_amount = amount - cost_data.total_msats
print("refund: ", refund_amount)
logger.info(
"Processing non-streaming response cost calculation",
extra={
"original_amount": amount,
"cost_msats": cost_data.total_msats,
"refund_amount": refund_amount,
"unit": unit,
"model": response_json.get("model", "unknown"),
},
)
if refund_amount > 0:
refund_token = await send_refund(refund_amount, unit)
response_headers["X-Cashu"] = refund_token
print(f"Refunded {refund_amount} msats")
logger.info(
"Refund processed for non-streaming response",
extra={
"refund_amount": refund_amount,
"unit": unit,
"refund_token_preview": refund_token[:20] + "..."
if len(refund_token) > 20
else refund_token,
},
)
return Response(
content=content_str,
@@ -229,8 +440,32 @@ async def handle_non_streaming_response(
media_type="application/json",
)
except json.JSONDecodeError as e:
response.headers["X-Cashu"] = await wallet().send(amount - 60)
print(f"Failed to parse JSON from upstream response: {e}")
logger.error(
"Failed to parse JSON from upstream response",
extra={
"error": str(e),
"content_preview": content_str[:200] + "..."
if len(content_str) > 200
else content_str,
"amount": amount,
"unit": unit,
},
)
# Emergency refund with small deduction for processing
emergency_refund = amount
refund_token = await wallet().send(emergency_refund)
response.headers["X-Cashu"] = refund_token
logger.warning(
"Emergency refund issued due to JSON parse error",
extra={
"original_amount": amount,
"refund_amount": emergency_refund,
"deduction": 60,
},
)
# Return original content if JSON parsing fails
return Response(
content=content_str,
@@ -246,14 +481,41 @@ async def get_cost(response_data: dict) -> MaxCostData | CostData | None:
This is called after the initial payment and the upstream request is complete.
Returns cost data to be included in the response.
"""
max_cost = get_max_cost_for_model(model=response_data["model"])
model = response_data.get("model", "unknown")
logger.debug(
"Calculating cost for response",
extra={"model": model, "has_usage": "usage" in response_data},
)
max_cost = get_max_cost_for_model(model=model)
match calculate_cost(response_data, max_cost):
case MaxCostData() as cost:
logger.debug(
"Using max cost pricing",
extra={"model": model, "max_cost_msats": cost.total_msats},
)
return cost
case CostData() as cost:
logger.debug(
"Using token-based pricing",
extra={
"model": model,
"total_cost_msats": cost.total_msats,
"input_msats": cost.input_msats,
"output_msats": cost.output_msats,
},
)
return cost
case CostDataError() as error:
logger.error(
"Cost calculation error",
extra={
"model": model,
"error_message": error.message,
"error_code": error.code,
},
)
raise HTTPException(
status_code=400,
detail={
@@ -267,10 +529,37 @@ async def get_cost(response_data: dict) -> MaxCostData | CostData | None:
async def redeem_token(x_cashu_token: str) -> tuple[int, Literal["sat", "msat"]]:
"""Redeem X-Cashu token and return amount and unit."""
logger.debug(
"Redeeming X-Cashu token",
extra={
"token_preview": x_cashu_token[:20] + "..."
if len(x_cashu_token) > 20
else x_cashu_token
},
)
try:
result = await wallet().redeem(x_cashu_token)
return cast(tuple[int, Literal["sat", "msat"]], result)
amount, unit = cast(tuple[int, Literal["sat", "msat"]], result)
logger.info(
"X-Cashu token redeemed successfully",
extra={"amount": amount, "unit": unit},
)
return amount, unit
except Exception as e:
logger.error(
"X-Cashu token redemption failed",
extra={
"error": str(e),
"error_type": type(e).__name__,
"token_preview": x_cashu_token[:20] + "..."
if len(x_cashu_token) > 20
else x_cashu_token,
},
)
raise HTTPException(
status_code=401,
detail={
@@ -284,16 +573,69 @@ async def redeem_token(x_cashu_token: str) -> tuple[int, Literal["sat", "msat"]]
async def send_refund(amount: int, unit: CurrencyUnit, mint: str | None = None) -> str:
try:
return await wallet().send(amount, unit=unit, mint_url=mint)
except Exception as e:
raise HTTPException(
status_code=401,
detail={
"error": {
"message": f"failed to create refund: {str(e)}",
"type": "invalid_request_error",
"code": "send_token_failed",
}
},
)
"""Send a refund using Cashu tokens."""
logger.debug(
"Creating refund token", extra={"amount": amount, "unit": unit, "mint": mint}
)
max_retries = 3
last_exception = None
for attempt in range(max_retries):
try:
refund_token = await wallet().send(amount, unit=unit, mint_url=mint)
logger.info(
"Refund token created successfully",
extra={
"amount": amount,
"unit": unit,
"mint": mint,
"attempt": attempt + 1,
"token_preview": refund_token[:20] + "..."
if len(refund_token) > 20
else refund_token,
},
)
return refund_token
except Exception as e:
last_exception = e
if attempt < max_retries - 1:
logger.warning(
"Refund token creation failed, retrying",
extra={
"error": str(e),
"error_type": type(e).__name__,
"attempt": attempt + 1,
"max_retries": max_retries,
"amount": amount,
"unit": unit,
"mint": mint,
},
)
else:
logger.error(
"Failed to create refund token after all retries",
extra={
"error": str(e),
"error_type": type(e).__name__,
"attempt": attempt + 1,
"max_retries": max_retries,
"amount": amount,
"unit": unit,
"mint": mint,
},
)
# If we get here, all retries failed
raise HTTPException(
status_code=401,
detail={
"error": {
"message": f"failed to create refund after {max_retries} attempts: {str(last_exception)}",
"type": "invalid_request_error",
"code": "send_token_failed",
}
},
)
router/price.py
+93 -22
View File
@@ -1,57 +1,128 @@
import asyncio
import logging
import os
import httpx
from .logging.logging_config import get_logger
logger = get_logger(__name__)
# artifical spread to cover conversion fees
EXCHANGE_FEE = float(os.environ.get("EXCHANGE_FEE", "1.005")) # 0.5% default
logger.info("Price module initialized", extra={"exchange_fee": EXCHANGE_FEE})
async def kraken_btc_usd(client: httpx.AsyncClient) -> float | None:
"""Fetch BTC/USD price from Kraken API."""
api = "https://api.kraken.com/0/public/Ticker?pair=XBTUSD"
try:
return float((await client.get(api)).json()["result"]["XXBTZUSD"]["c"][0])
logger.debug("Fetching BTC price from Kraken")
response = await client.get(api)
price_data = response.json()
price = float(price_data["result"]["XXBTZUSD"]["c"][0])
return price
except (httpx.RequestError, KeyError) as e:
logging.warning(f"Kraken API error: {e}")
logger.warning(
"Kraken API error",
extra={
"error": str(e),
"error_type": type(e).__name__,
"exchange": "kraken",
},
)
return None
async def coinbase_btc_usd(client: httpx.AsyncClient) -> float | None:
"""Fetch BTC/USD price from Coinbase API."""
api = "https://api.coinbase.com/v2/prices/BTC-USD/spot"
try:
return float((await client.get(api)).json()["data"]["amount"])
logger.debug("Fetching BTC price from Coinbase")
response = await client.get(api)
price_data = response.json()
price = float(price_data["data"]["amount"])
return price
except (httpx.RequestError, KeyError) as e:
logging.warning(f"Coinbase API error: {e}")
logger.warning(
"Coinbase API error",
extra={
"error": str(e),
"error_type": type(e).__name__,
"exchange": "coinbase",
},
)
return None
async def binance_btc_usdt(client: httpx.AsyncClient) -> float | None:
"""Fetch BTC/USDT price from Binance API."""
api = "https://api.binance.com/api/v3/ticker/price?symbol=BTCUSDT"
try:
return float((await client.get(api)).json()["price"])
logger.debug("Fetching BTC price from Binance")
response = await client.get(api)
price_data = response.json()
price = float(price_data["price"])
return price
except (httpx.RequestError, KeyError) as e:
logging.warning(f"Binance API error: {e}")
logger.warning(
"Binance API error",
extra={
"error": str(e),
"error_type": type(e).__name__,
"exchange": "binance",
},
)
return None
async def btc_usd_ask_price() -> float:
async with httpx.AsyncClient() as client:
return (
max(
[
price
for price in await asyncio.gather(
kraken_btc_usd(client),
coinbase_btc_usd(client),
binance_btc_usdt(client),
)
if price is not None
]
"""Get the highest BTC/USD price from multiple exchanges with fee adjustment."""
logger.debug("Starting BTC price aggregation from multiple exchanges")
async with httpx.AsyncClient(timeout=30.0) as client:
try:
prices = await asyncio.gather(
kraken_btc_usd(client),
coinbase_btc_usd(client),
binance_btc_usdt(client),
)
* EXCHANGE_FEE
)
valid_prices = [price for price in prices if price is not None]
if not valid_prices:
logger.error("No valid BTC prices obtained from any exchange")
raise ValueError("Unable to fetch BTC price from any exchange")
max_price = max(valid_prices)
final_price = max_price * EXCHANGE_FEE
return final_price
except Exception as e:
logger.error(
"Error in BTC price aggregation",
extra={"error": str(e), "error_type": type(e).__name__},
)
raise
async def sats_usd_ask_price() -> float:
return (await btc_usd_ask_price()) / 100_000_000
"""Get the USD price per satoshi."""
logger.debug("Calculating satoshi price from BTC price")
try:
btc_price = await btc_usd_ask_price()
sats_price = btc_price / 100_000_000
return sats_price
except Exception as e:
logger.error(
"Error calculating satoshi price",
extra={"error": str(e), "error_type": type(e).__name__},
)
raise
router/proxy.py
+368 -60
View File
@@ -7,6 +7,7 @@ import httpx
from fastapi import APIRouter, BackgroundTasks, Depends, HTTPException, Request
from fastapi.responses import Response, StreamingResponse
from router.logging.logging_config import get_logger
from router.payment.helpers import (
UPSTREAM_BASE_URL,
check_token_balance,
@@ -15,10 +16,15 @@ from router.payment.helpers import (
)
from router.payment.x_cashu import x_cashu_handler
from .auth import adjust_payment_for_tokens, pay_for_request, validate_bearer_key
from .cashu import x_cashu_refund
from .auth import (
adjust_payment_for_tokens,
pay_for_request,
revert_pay_for_request,
validate_bearer_key,
)
from .db import ApiKey, AsyncSession, create_session, get_session
logger = get_logger(__name__)
proxy_router = APIRouter()
@@ -26,6 +32,14 @@ async def handle_streaming_chat_completion(
response: httpx.Response, key: ApiKey, session: AsyncSession
) -> StreamingResponse:
"""Handle streaming chat completion responses with token-based pricing."""
logger.info(
"Processing streaming chat completion",
extra={
"key_hash": key.hashed_key[:8] + "...",
"key_balance": key.balance,
"response_status": response.status_code,
},
)
async def stream_with_cost() -> AsyncGenerator[bytes, None]:
# Store all chunks to analyze
@@ -38,6 +52,14 @@ async def handle_streaming_chat_completion(
# Pass through each chunk to client
yield chunk
logger.debug(
"Streaming completed, analyzing usage data",
extra={
"key_hash": key.hashed_key[:8] + "...",
"chunks_count": len(stored_chunks),
},
)
# Process stored chunks to find usage data
# Start from the end and work backwards
for i in range(len(stored_chunks) - 1, -1, -1):
@@ -63,6 +85,15 @@ async def handle_streaming_chat_completion(
and data["usage"] is not None
and isinstance(data["usage"], dict)
):
logger.info(
"Found usage data in streaming response",
extra={
"key_hash": key.hashed_key[:8] + "...",
"usage_data": data["usage"],
"model": data.get("model", "unknown"),
},
)
# Found usage data, calculate cost
# Create a new session for this operation
async with create_session() as new_session:
@@ -71,18 +102,43 @@ async def handle_streaming_chat_completion(
key.__class__, key.hashed_key
)
if fresh_key:
cost_data = await adjust_payment_for_tokens(
fresh_key, data, new_session
)
# Format as SSE and yield
cost_json = json.dumps({"cost": cost_data})
yield f"data: {cost_json}\n\n".encode()
try:
cost_data = await adjust_payment_for_tokens(
fresh_key, data, new_session
)
logger.info(
"Token adjustment completed for streaming",
extra={
"key_hash": key.hashed_key[:8] + "...",
"cost_data": cost_data,
"balance_after_adjustment": fresh_key.balance,
},
)
# Format as SSE and yield
cost_json = json.dumps({"cost": cost_data})
yield f"data: {cost_json}\n\n".encode()
except Exception as cost_error:
logger.error(
"Error adjusting payment for streaming tokens",
extra={
"error": str(cost_error),
"error_type": type(cost_error).__name__,
"key_hash": key.hashed_key[:8] + "...",
},
)
break
except json.JSONDecodeError:
continue
except Exception as e:
print(f"Error processing streaming response for cost: {e}")
logger.error(
"Error processing streaming response chunk",
extra={
"error": str(e),
"error_type": type(e).__name__,
"key_hash": key.hashed_key[:8] + "...",
},
)
return StreamingResponse(
stream_with_cost(),
@@ -95,12 +151,41 @@ async def handle_non_streaming_chat_completion(
response: httpx.Response, key: ApiKey, session: AsyncSession
) -> Response:
"""Handle non-streaming chat completion responses with token-based pricing."""
logger.info(
"Processing non-streaming chat completion",
extra={
"key_hash": key.hashed_key[:8] + "...",
"key_balance": key.balance,
"response_status": response.status_code,
},
)
try:
content = await response.aread()
response_json = json.loads(content)
logger.debug(
"Parsed response JSON",
extra={
"key_hash": key.hashed_key[:8] + "...",
"model": response_json.get("model", "unknown"),
"has_usage": "usage" in response_json,
},
)
cost_data = await adjust_payment_for_tokens(key, response_json, session)
response_json["cost"] = cost_data
logger.info(
"Token adjustment completed for non-streaming",
extra={
"key_hash": key.hashed_key[:8] + "...",
"cost_data": cost_data,
"model": response_json.get("model", "unknown"),
"balance_after_adjustment": key.balance,
},
)
# Keep only standard headers that are safe to pass through
allowed_headers = {
"content-type",
@@ -126,10 +211,26 @@ async def handle_non_streaming_chat_completion(
media_type="application/json",
)
except json.JSONDecodeError as e:
print(f"Failed to parse JSON from upstream response: {e}")
logger.error(
"Failed to parse JSON from upstream response",
extra={
"error": str(e),
"key_hash": key.hashed_key[:8] + "...",
"content_preview": content[:200].decode(errors="ignore")
if content
else "empty",
},
)
raise
except Exception as e:
print(f"Error adjusting payment for tokens: {e}")
logger.error(
"Error processing non-streaming chat completion",
extra={
"error": str(e),
"error_type": type(e).__name__,
"key_hash": key.hashed_key[:8] + "...",
},
)
raise
@@ -146,6 +247,19 @@ async def forward_to_upstream(
path = path.replace("v1/", "")
url = f"{UPSTREAM_BASE_URL}/{path}"
logger.info(
"Forwarding request to upstream",
extra={
"url": url,
"method": request.method,
"path": path,
"key_hash": key.hashed_key[:8] + "...",
"key_balance": key.balance,
"has_request_body": request_body is not None,
},
)
client = httpx.AsyncClient(
transport=httpx.AsyncHTTPTransport(retries=1),
timeout=None, # No timeout - requests can take as long as needed
@@ -176,6 +290,16 @@ async def forward_to_upstream(
stream=True,
)
logger.info(
"Received upstream response",
extra={
"status_code": response.status_code,
"path": path,
"key_hash": key.hashed_key[:8] + "...",
"content_type": response.headers.get("content-type", "unknown"),
},
)
# For chat completions, we need to handle token-based pricing
if path.endswith("chat/completions"):
# Check if client requested streaming
@@ -184,14 +308,35 @@ async def forward_to_upstream(
try:
request_data = json.loads(request_body)
client_wants_streaming = request_data.get("stream", False)
logger.debug(
"Chat completion request analysis",
extra={
"client_wants_streaming": client_wants_streaming,
"model": request_data.get("model", "unknown"),
"key_hash": key.hashed_key[:8] + "...",
},
)
except json.JSONDecodeError:
pass
logger.warning(
"Failed to parse request body JSON for streaming detection"
)
# Handle both streaming and non-streaming responses
content_type = response.headers.get("content-type", "")
upstream_is_streaming = "text/event-stream" in content_type
is_streaming = client_wants_streaming and upstream_is_streaming
logger.debug(
"Response type analysis",
extra={
"is_streaming": is_streaming,
"client_wants_streaming": client_wants_streaming,
"upstream_is_streaming": upstream_is_streaming,
"content_type": content_type,
"key_hash": key.hashed_key[:8] + "...",
},
)
if is_streaming and response.status_code == 200:
# Process streaming response and extract cost from the last chunk
result = await handle_streaming_chat_completion(response, key, session)
@@ -216,6 +361,15 @@ async def forward_to_upstream(
background_tasks.add_task(response.aclose)
background_tasks.add_task(client.aclose)
logger.debug(
"Streaming non-chat response",
extra={
"path": path,
"status_code": response.status_code,
"key_hash": key.hashed_key[:8] + "...",
},
)
return StreamingResponse(
response.aiter_bytes(),
status_code=response.status_code,
@@ -227,10 +381,18 @@ async def forward_to_upstream(
await client.aclose()
error_type = type(exc).__name__
error_details = str(exc)
print(
f"Error forwarding request to upstream: {error_type}: {error_details}\n"
f"Request details: method={request.method}, url={url}, headers={headers}, "
f"path={path}, query_params={dict(request.query_params)}"
logger.error(
"HTTP request error to upstream",
extra={
"error_type": error_type,
"error_details": error_details,
"method": request.method,
"url": url,
"path": path,
"query_params": dict(request.query_params),
"key_hash": key.hashed_key[:8] + "...",
},
)
# Provide more specific error messages based on the error type
@@ -247,15 +409,22 @@ async def forward_to_upstream(
except Exception as exc:
await client.aclose()
import traceback
tb = traceback.format_exc()
print(
f"Unexpected error: {exc}\n"
f"Request details: method={request.method}, url={url}, headers={headers}, "
f"path={path}, query_params={dict(request.query_params)}\n"
f"Traceback:\n{tb}"
logger.error(
"Unexpected error in upstream forwarding",
extra={
"error": str(exc),
"error_type": type(exc).__name__,
"method": request.method,
"url": url,
"path": path,
"query_params": dict(request.query_params),
"key_hash": key.hashed_key[:8] + "...",
"traceback": tb,
},
)
return create_error_response(
"internal_error", "An unexpected server error occurred", 500
)
@@ -265,6 +434,17 @@ async def forward_to_upstream(
async def proxy(
request: Request, path: str, session: AsyncSession = Depends(get_session)
) -> Response | StreamingResponse:
"""Main proxy endpoint handler."""
logger.info(
"Received proxy request",
extra={
"method": request.method,
"path": path,
"client_host": request.client.host if request.client else "unknown",
"user_agent": request.headers.get("user-agent", "unknown")[:100],
},
)
request_body = await request.body()
headers = dict(request.headers)
@@ -273,8 +453,25 @@ async def proxy(
if request_body:
try:
request_body_dict = json.loads(request_body)
logger.debug(
"Request body parsed",
extra={
"path": path,
"body_keys": list(request_body_dict.keys()),
"model": request_body_dict.get("model", "not_specified"),
},
)
except json.JSONDecodeError as e:
print(f"Error: failed to parse request body '{e}'")
logger.error(
"Invalid JSON in request body",
extra={
"error": str(e),
"path": path,
"body_preview": request_body[:200].decode(errors="ignore")
if request_body
else "empty",
},
)
return Response(
content=json.dumps(
{"error": {"type": "invalid_request_error", "code": "invalid_json"}}
@@ -284,30 +481,91 @@ async def proxy(
)
# Check token balance for all requests to get currency unit
unit = check_token_balance(headers, request_body_dict)
try:
unit = check_token_balance(headers, request_body_dict)
logger.debug(
"Token balance check completed", extra={"path": path, "unit": unit}
)
except HTTPException as e:
logger.warning(
"Token balance check failed",
extra={"path": path, "status_code": e.status_code, "detail": str(e.detail)},
)
raise
# Handle authentication
if x_cashu := headers.get("x-cashu", None):
logger.info(
"Processing X-Cashu payment",
extra={
"path": path,
"token_preview": x_cashu[:20] + "..." if len(x_cashu) > 20 else x_cashu,
},
)
return await x_cashu_handler(request, x_cashu, path)
elif auth := headers.get("authorization", None):
logger.debug(
"Processing bearer token authentication",
extra={
"path": path,
"token_preview": auth[:20] + "..." if len(auth) > 20 else auth,
},
)
key = await get_bearer_token_key(headers, path, session, auth)
else:
if request.method not in ["GET"]:
logger.warning(
"Unauthorized request - no authentication provided",
extra={"method": request.method, "path": path},
)
return Response(
content=json.dumps({"detail": "Unauthorized"}),
status_code=401,
media_type="application/json",
)
logger.debug("Processing unauthenticated GET request", extra={"path": path})
# Prepare headers for upstream
headers = prepare_upstream_headers(dict(request.headers))
return await forward_get_to_upstream(request, path, headers)
cost_per_request = 0
# Only pay for request if we have request body data (for completions endpoints)
if request_body_dict:
await pay_for_request(key, session, request_body_dict)
logger.info(
"Processing payment for request",
extra={
"path": path,
"key_hash": key.hashed_key[:8] + "...",
"key_balance_before": key.balance,
"model": request_body_dict.get("model", "unknown"),
},
)
try:
await pay_for_request(key, session, request_body_dict)
logger.info(
"Payment processed successfully",
extra={
"path": path,
"key_hash": key.hashed_key[:8] + "...",
"key_balance_after": key.balance,
"model": request_body_dict.get("model", "unknown"),
},
)
except Exception as e:
logger.error(
"Payment processing failed",
extra={
"error": str(e),
"error_type": type(e).__name__,
"path": path,
"key_hash": key.hashed_key[:8] + "...",
},
)
raise
# Prepare headers for upstream
headers = prepare_upstream_headers(dict(request.headers))
@@ -317,28 +575,17 @@ async def proxy(
request, path, headers, request_body, key, session
)
if response.status_code != 200 and key.refund_address == "X-CASHU":
refund_token = await x_cashu_refund(key, session, unit)
response = Response(
content=json.dumps(
{
"error": {
"message": "Error forwarding request to upstream",
"type": "upstream_error",
"code": response.status_code,
"refund_token": refund_token,
}
}
),
status_code=response.status_code,
media_type="application/json",
if response.status_code != 200:
await revert_pay_for_request(key, session, cost_per_request)
logger.warning(
"Upstream request failed, revert payment",
extra={
"status_code": response.status_code,
"path": path,
"key_hash": key.hashed_key[:8] + "...",
"key_balance": key.balance,
},
)
response.headers["X-Cashu"] = refund_token
return response
if key.refund_address == "X-CASHU":
refund_token = await x_cashu_refund(key, session, unit)
response.headers["X-Cashu"] = refund_token
return response
@@ -351,18 +598,40 @@ async def get_bearer_token_key(
refund_address = headers.get("Refund-LNURL", None)
key_expiry_time = headers.get("Key-Expiry-Time", None)
logger.debug(
"Processing bearer token",
extra={
"path": path,
"has_refund_address": bool(refund_address),
"has_expiry_time": bool(key_expiry_time),
"bearer_key_preview": bearer_key[:20] + "..."
if len(bearer_key) > 20
else bearer_key,
},
)
# Validate key_expiry_time header
if key_expiry_time:
try:
key_expiry_time = int(key_expiry_time) # type: ignore
logger.debug(
"Key expiry time validated",
extra={"expiry_time": key_expiry_time, "path": path},
)
except ValueError:
print("Invalid Key-Expiry-Time: must be a valid Unix timestamp")
logger.error(
"Invalid Key-Expiry-Time header",
extra={"key_expiry_time": key_expiry_time, "path": path},
)
raise HTTPException(
status_code=400,
detail="Invalid Key-Expiry-Time: must be a valid Unix timestamp",
)
if not refund_address:
print("Error: Refund-LNURL header required when using Key-Expiry-Time")
logger.error(
"Missing Refund-LNURL header with Key-Expiry-Time",
extra={"path": path, "expiry_time": key_expiry_time},
)
raise HTTPException(
status_code=400,
detail="Error: Refund-LNURL header required when using Key-Expiry-Time",
@@ -370,12 +639,35 @@ async def get_bearer_token_key(
else:
key_expiry_time = None
return await validate_bearer_key(
bearer_key,
session,
refund_address,
key_expiry_time, # type: ignore
)
try:
key = await validate_bearer_key(
bearer_key,
session,
refund_address,
key_expiry_time, # type: ignore
)
logger.info(
"Bearer token validated successfully",
extra={
"path": path,
"key_hash": key.hashed_key[:8] + "...",
"key_balance": key.balance,
},
)
return key
except Exception as e:
logger.error(
"Bearer token validation failed",
extra={
"error": str(e),
"error_type": type(e).__name__,
"path": path,
"bearer_key_preview": bearer_key[:20] + "..."
if len(bearer_key) > 20
else bearer_key,
},
)
raise
async def forward_get_to_upstream(
@@ -389,6 +681,11 @@ async def forward_get_to_upstream(
url = f"{UPSTREAM_BASE_URL}/{path}"
logger.info(
"Forwarding GET request to upstream",
extra={"url": url, "method": request.method, "path": path},
)
async with httpx.AsyncClient(
transport=httpx.AsyncHTTPTransport(retries=1),
timeout=None,
@@ -404,6 +701,11 @@ async def forward_get_to_upstream(
),
)
logger.info(
"GET request forwarded successfully",
extra={"path": path, "status_code": response.status_code},
)
return StreamingResponse(
response.aiter_bytes(),
status_code=response.status_code,
@@ -411,11 +713,17 @@ async def forward_get_to_upstream(
)
except Exception as exc:
tb = traceback.format_exc()
print(
f"Unexpected error: {exc}\n"
f"Request details: method={request.method}, url={url}, headers={headers}, "
f"path={path}, query_params={dict(request.query_params)}\n"
f"Traceback:\n{tb}"
logger.error(
"Error forwarding GET request",
extra={
"error": str(exc),
"error_type": type(exc).__name__,
"method": request.method,
"url": url,
"path": path,
"query_params": dict(request.query_params),
"traceback": tb,
},
)
return create_error_response(
"internal_error", "An unexpected server error occurred", 500
uv.lock
Generated
+680 -398
View File
File diff suppressed because it is too large Load Diff