logging improved

src/exec_mcp/bitstamp_private_ws.py

@@ -2,6 +2,8 @@ from __future__ import annotations
 
 import asyncio
 import json
+import logging
+import time
 
 import websockets
 
@@ -11,35 +13,48 @@ from .services_orders import _record_order_status_update
 WS_URL = "wss://ws.bitstamp.net"
 WS_RECONNECT_SECONDS = 5
 WS_HEARTBEAT_SECONDS = 15
+logger = logging.getLogger("exec_mcp")
 
 
 async def private_ws_main(stop_event: asyncio.Event) -> None:
+    logger.info("private websocket supervisor started")
     while not stop_event.is_set():
+        started = time.monotonic()
         try:
             await _run_once(stop_event)
         except asyncio.CancelledError:
+            logger.info("private websocket supervisor cancelled")
             raise
         except Exception:
+            logger.exception("private websocket supervisor failed after %.3fs", time.monotonic() - started)
             await asyncio.sleep(WS_RECONNECT_SECONDS)
 
 
 async def _run_once(stop_event: asyncio.Event) -> None:
     accounts = [a for a in __import__("exec_mcp.repo", fromlist=["list_accounts"]).list_accounts(enabled_only=True) if a["venue"] == "bitstamp"]
     if not accounts:
+        logger.info("private websocket: no enabled Bitstamp accounts configured; sleeping")
         await asyncio.sleep(WS_RECONNECT_SECONDS)
         return
 
+    logger.info("private websocket: connecting for %d enabled Bitstamp account(s)", len(accounts))
     async with websockets.connect(WS_URL, ping_interval=None) as ws:
         for account in accounts:
             token_info = _get_token(account["id"])
+            logger.info("private websocket: subscribed account=%s venue_account_ref=%s", account["id"], account["venue_account_ref"])
             await ws.send(json.dumps({"event": "bts:subscribe", "data": {"channel": f"private-my_orders_{account['venue_account_ref']}-{token_info['user_id']}", "auth": token_info["token"]}}))
 
+        message_count = 0
         while not stop_event.is_set():
             try:
                 message = await asyncio.wait_for(ws.recv(), timeout=WS_HEARTBEAT_SECONDS)
             except asyncio.TimeoutError:
                 await ws.send(json.dumps({"event": "bts:heartbeat"}))
+                logger.debug("private websocket: heartbeat sent after %.1fs without a message", WS_HEARTBEAT_SECONDS)
                 continue
+            message_count += 1
+            if message_count % 100 == 0:
+                logger.info("private websocket: processed %d messages on current connection", message_count)
             _handle_message(json.loads(message))
 
 
@@ -62,4 +77,5 @@ def _handle_message(payload: dict) -> None:
     try:
         _record_order_status_update(bitstamp_order_id=str(order_id), status=str(status), raw_json=payload)
     except Exception:
+        logger.exception("private websocket: failed to persist order update for order_id=%s", order_id)
         return

src/exec_mcp/server.py

@@ -2,6 +2,8 @@ from __future__ import annotations
 
 from contextlib import asynccontextmanager
 import asyncio
+import logging
+import time
 
 from fastapi import FastAPI, Form, HTTPException
 from fastapi.responses import HTMLResponse, RedirectResponse
@@ -17,40 +19,51 @@ from .services_orders import place_order as service_place_order, query_order as
 from .storage import init_db
 
 mcp = FastMCP("exec-mcp")
+logger = logging.getLogger("exec_mcp")
 
 
 async def _metadata_refresh_loop() -> None:
+    logger.info("metadata refresh loop started")
     while True:
+        started = time.monotonic()
         try:
             refresh_metadata()
+            logger.info("metadata refresh loop completed in %.3fs", time.monotonic() - started)
         except Exception:
-            pass
+            logger.exception("metadata refresh loop failed after %.3fs", time.monotonic() - started)
         await asyncio.sleep(METADATA_REFRESH_SECONDS)
 
 
 async def _fx_refresh_loop() -> None:
+    logger.info("fx refresh loop started")
     while True:
+        started = time.monotonic()
         try:
             refresh_eur_usd()
+            logger.info("fx refresh loop completed in %.3fs", time.monotonic() - started)
         except Exception:
-            pass
+            logger.exception("fx refresh loop failed after %.3fs", time.monotonic() - started)
         await asyncio.sleep(FX_REFRESH_SECONDS)
 
 
 @asynccontextmanager
 async def lifespan(_: FastAPI):
     init_db()
+    logger.info("application startup: database initialized")
     try:
         refresh_metadata()
+        logger.info("application startup: Bitstamp metadata refreshed")
     except Exception:
-        pass
+        logger.exception("application startup: Bitstamp metadata refresh failed")
     stop_event = asyncio.Event()
     metadata_task = asyncio.create_task(_metadata_refresh_loop())
     fx_task = asyncio.create_task(_fx_refresh_loop())
     private_ws_task = asyncio.create_task(private_ws_main(stop_event))
+    logger.info("background tasks started: metadata, fx, private websocket")
     try:
         yield
     finally:
+        logger.info("application shutdown: stopping background tasks")
         stop_event.set()
         metadata_task.cancel()
         fx_task.cancel()
@@ -105,6 +118,7 @@ def http_root() -> str:
 
 @app.get("/health")
 def http_health() -> dict:
+    logger.debug("health check requested")
     return {"ok": True, "server": "exec-mcp"}
 
 

src/exec_mcp/services_bitstamp.py

@@ -1,7 +1,9 @@
 from __future__ import annotations
 
+import logging
 import os
 import threading
+import time
 
 try:
     import bitstamp.client
@@ -18,6 +20,7 @@ BALANCE_CACHE_TTL_MS = 1200
 ACCOUNT_INFO_CACHE_TTL_MS = 1200
 FEES_CACHE_TTL_SECONDS = 10 * 60
 STALE_CACHE_TTL_SECONDS = 2
+logger = logging.getLogger("exec_mcp")
 _CACHE_LOCKS: dict[str, threading.Lock] = {}
 _CACHE_LOCKS_GUARD = threading.Lock()
 _BITSTAMP_CLIENTS: dict[str, BitstampClient] = {}
@@ -255,6 +258,7 @@ def fetch_account_balance(account_id: str) -> dict:
                 _raise_cached_error(cached)
             return cached
 
+        started = time.monotonic()
         try:
             client = get_bitstamp_client(account_id)
             payload = client.trading._post("account_balances/", return_json=True, version=2)
@@ -271,6 +275,9 @@ def fetch_account_balance(account_id: str) -> dict:
             _ttl_from_env_ms("BITSTAMP_BALANCE_CACHE_TTL_MS", BALANCE_CACHE_TTL_MS),
         )
         repo.cache_put(_stale_key(cache_key), result, STALE_CACHE_TTL_SECONDS)
+        elapsed = time.monotonic() - started
+        if elapsed >= 2:
+            logger.info("fetch_account_balance completed in %.3fs for account_id=%s", elapsed, account_id)
         return result
 
 
@@ -328,6 +335,7 @@ def fetch_account_info(account_id: str) -> dict:
                 _raise_cached_error(cached)
             return cached
 
+        started = time.monotonic()
         try:
             account = repo.get_account(account_id)
             balance = fetch_account_balance(account_id)
@@ -364,6 +372,9 @@ def fetch_account_info(account_id: str) -> dict:
             _ttl_from_env_ms("BITSTAMP_ACCOUNT_INFO_CACHE_TTL_MS", ACCOUNT_INFO_CACHE_TTL_MS),
         )
         repo.cache_put(_stale_key(cache_key), result, STALE_CACHE_TTL_SECONDS)
+        elapsed = time.monotonic() - started
+        if elapsed >= 2:
+            logger.info("fetch_account_info completed in %.3fs for account_id=%s", elapsed, account_id)
         return result
 
 

src/exec_mcp/services_orders.py

@@ -1,6 +1,7 @@
 from __future__ import annotations
 
 import json
+import logging
 import os
 import time
 import threading
@@ -21,6 +22,7 @@ FINISHED_ORDER_STATUS = "finished"
 _CANCEL_BREAKER_LOCK = threading.Lock()
 _CANCEL_BREAKER_NEXT_ALLOWED: dict[str, float] = {}
 _CANCEL_BREAKER_SECONDS = 3.0
+logger = logging.getLogger("exec_mcp")
 
 
 def _cancel_breaker_is_open(account_id: str) -> bool:
@@ -238,6 +240,7 @@ def place_order(*, account_id: str, market: str, side: str, order_type: str, amo
 def get_open_orders(*, account_id: str, client_id: str | None = None) -> dict:
     client_id = _normalize_client_id(client_id)
     client = _get_client(account_id)
+    started = time.monotonic()
     with get_connection() as conn:
         if client_id is None:
             rows = conn.execute(
@@ -266,6 +269,8 @@ def get_open_orders(*, account_id: str, client_id: str | None = None) -> dict:
 
     orders = []
     delay = _bitstamp_call_delay_seconds()
+    if rows:
+        logger.info("get_open_orders scanning %d open row(s) for account_id=%s client_id=%s", len(rows), account_id, client_id)
     for row in rows:
         order = dict(row)
         bitstamp_order_id = order.get("bitstamp_order_id")
@@ -296,11 +301,22 @@ def get_open_orders(*, account_id: str, client_id: str | None = None) -> dict:
         if delay > 0:
             time.sleep(delay)
 
+    elapsed = time.monotonic() - started
+    if elapsed >= 5:
+        logger.info(
+            "get_open_orders finished in %.3fs for account_id=%s client_id=%s rows=%d returned=%d",
+            elapsed,
+            account_id,
+            client_id,
+            len(rows),
+            len(orders),
+        )
     return {"ok": True, "client_id": client_id, "orders": orders}
 
 
 def cancel_all_orders(*, account_id: str, client_id: str | None = None) -> dict:
     client_id = _normalize_client_id(client_id)
+    started = time.monotonic()
     orders = get_open_orders(account_id=account_id, client_id=client_id)["orders"]
     results = []
     delay = _bitstamp_call_delay_seconds()
@@ -329,6 +345,15 @@ def cancel_all_orders(*, account_id: str, client_id: str | None = None) -> dict:
         if delay > 0:
             time.sleep(delay)
     invalidate_account_cache(account_id)
+    elapsed = time.monotonic() - started
+    if elapsed >= 5:
+        logger.info(
+            "cancel_all_orders finished in %.3fs for account_id=%s client_id=%s cancelled=%d",
+            elapsed,
+            account_id,
+            client_id,
+            len(results),
+        )
     return {"ok": True, "client_id": client_id, "cancelled": results, "count": len(results)}