Tiingo bid/ask spread monitor + logging hardening

- tiingo_provider.py: /tiingo/fx/top quotes (10s TTL cache, graceful None on any failure); spread log writer. Signals never consume bid/ask; warn-only by design (no historical bid/ask to validate a gate against — live == backtest rule). - app_config: repo-root .env loader (setdefault; shell env still wins), tiingo_api_key resolver (TIINGO_API_KEY/TIINGO → config.json), telegram.channel_spread_detail flag (default false). - telegram_bot: 5-min spread sampler → logs/spread_log.csv (weekend- aware), alert-time quote refresh, bid/ask + wide-spread warning in signal messages, /status spread line. Raw numbers to owner DM always; channel only while channel_spread_detail=true (Tiingo free tier is internal-use-only; flip before public launch). Free-tier limit math: worst case ~41 req/h vs 50/h cap, one pair. - Logging: 3h rotation x 240 backups (30-day retention), full-date stamps, force=True root handlers; candle loops + sampler survive failed cycles; breach-task exceptions logged via done-callback; PTB error handler; sys/threading excepthooks in main(). - test_all.py: Module 14 (tiingo, dotenv, spread routing, loop resilience, rotation) — 215 tests green. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01HVRmy6KspMs96o5PTPYFAB
2026-07-22 17:18:14 -04:00
parent 0823c05868
commit 91b4a6bb5e
6 changed files with 733 additions and 27 deletions
@@ -43,6 +43,7 @@ import logging
 import logging.handlers
 import os
 import sys
+import threading
 import time
 from concurrent.futures import ThreadPoolExecutor
 from datetime import datetime, timezone
@@ -66,9 +67,12 @@ from config import (
 )
 from app_config import (
    get_app_config, provider_api_key, telegram_token, telegram_chat_id,
-    telegram_channel_id,
+    telegram_channel_id, tiingo_api_key,
 )
 from data_provider import ForexDataProvider, make_data_provider
+from tiingo_provider import (
+    Quote, TiingoQuoteProvider, WIDE_SPREAD_MULTIPLE, log_quote,
+)
 from pair_signals import PAIR_PRODUCERS
 from signal_aggregator import SignalAggregator, SignalReport

@@ -81,17 +85,24 @@ if hasattr(sys.stdout, "reconfigure"):
 _LOG_DIR = os.path.join(os.path.dirname(os.path.abspath(__file__)), "logs")
 os.makedirs(_LOG_DIR, exist_ok=True)
 _log_formatter = logging.Formatter(
-    "%(asctime)s [%(levelname)s] %(name)s: %(message)s", datefmt="%H:%M:%S"
+    "%(asctime)s [%(levelname)s] %(name)s: %(message)s",
+    datefmt="%Y-%m-%d %H:%M:%S",
 )
 _console_handler = logging.StreamHandler()
 _console_handler.setFormatter(_log_formatter)
+# 3-hour rotation × 240 backups = 30 days retention. Handlers sit on the
+# ROOT logger (force=True guarantees ownership even if something logged
+# first), so every module logger — data_provider, tiingo_provider,
+# news_engine, signal_aggregator, websockets, telegram.ext — lands in
+# the same file.
 _file_handler = logging.handlers.TimedRotatingFileHandler(
    os.path.join(_LOG_DIR, "telegram.log"),
-    when="midnight", backupCount=30, encoding="utf-8",
+    when="h", interval=3, backupCount=240, encoding="utf-8",
 )
 _file_handler.setFormatter(_log_formatter)
 logging.basicConfig(level=getattr(logging, _APP.log_level, logging.INFO),
-                    handlers=[_console_handler, _file_handler])
+                    handlers=[_console_handler, _file_handler],
+                    force=True)
 logging.getLogger("httpx").setLevel(logging.WARNING)
 logging.getLogger("httpcore").setLevel(logging.WARNING)
 logger = logging.getLogger("telegram_bot")
@@ -202,6 +213,32 @@ def _get_shared_dp() -> ForexDataProvider:
    return _shared_dp


+# ── Tiingo bid/ask spread monitor (optional; no key → feature off) ───
+# Warn-only BY DESIGN: there is no historical bid/ask to replay, so a
+# suppressing gate could never be validated (live == backtest rule).
+# Signals never consume bid/ask — this is execution-cost visibility.
+
+_TIINGO_KEY = tiingo_api_key()
+_tiingo: Optional[TiingoQuoteProvider] = (
+    TiingoQuoteProvider(_TIINGO_KEY) if _TIINGO_KEY else None
+)
+_last_quotes: Dict[str, Quote] = {}
+_QUOTE_MAX_AGE = 600          # cached quote stays displayable this long
+_SPREAD_SAMPLE_SECONDS = 300  # sampler cadence (→ logs/spread_log.csv)
+
+# config.json telegram.channel_spread_detail: True while the channel is
+# internal/testing → it gets raw bid/ask like the owner DM. MUST be
+# flipped back to false before the channel goes public (Tiingo free
+# tier is internal-use-only).
+_CHANNEL_SPREAD_DETAIL = _APP.channel_spread_detail
+
+
+def _spread_detail_for(chat_id: int) -> bool:
+    """Owner DMs always get raw quote numbers; the channel only while
+    config.json marks it internal."""
+    return chat_id != CHANNEL_ID or _CHANNEL_SPREAD_DETAIL
+
+
 # ── Signal formatting ─────────────────────────────────────────────────

 _SIGNAL_EMOJI = {
@@ -257,6 +294,37 @@ def _live_price_line(symbol: str) -> Optional[str]:
    return f"📡 Live: *{_fmt_price(price)}*  ({age:.0f}s tick)"


+def _spread_lines(symbol: str, include_quote: bool = True) -> List[str]:
+    """Live bid/ask + wide-spread warning for signal messages.
+    Empty when Tiingo is off or the cached quote is stale.
+
+    include_quote=False is the subscriber-channel variant: Tiingo's
+    free tier is licensed internal-use-only (no redistributing the
+    data), so raw bid/ask/spread numbers stay in the owner DM — the
+    channel gets only a number-free wide-spread caution."""
+    q = _last_quotes.get(symbol)
+    if q is None or q.age_seconds() > _QUOTE_MAX_AGE:
+        return []
+    assumed = PAIR_INFO.get(symbol, {}).get("default_spread", 0.0)
+    wide = assumed > 0 and q.spread >= WIDE_SPREAD_MULTIPLE * assumed
+    if not include_quote:
+        return [
+            "⚠️ Spread unusually wide right now — execution cost is "
+            "elevated, consider waiting for it to normalize"
+        ] if wide else []
+    lines = [
+        f"💱 Bid/Ask: {_fmt_price(q.bid)} / {_fmt_price(q.ask)}"
+        f"  (spread ${q.spread:.2f})"
+    ]
+    if wide:
+        lines.append(
+            f"⚠️ Wide spread: ${q.spread:.2f} ≈ {q.spread / assumed:.1f}× the "
+            f"${assumed:.2f} cost the strategy was validated at — "
+            f"execution is expensive right now"
+        )
+    return lines
+
+
 _DISCLAIMER = (
    "⚠️ _Not financial advice. For educational and research purposes only. "
    "Trading forex/CFDs carries a high risk of loss — do your own analysis "
@@ -264,7 +332,7 @@ _DISCLAIMER = (
 )


-def format_signal_message(report: SignalReport) -> str:
+def format_signal_message(report: SignalReport, spread_detail: bool = True) -> str:
    sig = report.final_signal
    emoji = _SIGNAL_EMOJI.get(sig, "⬜")
    qe = _QUALITY_EMOJI.get(report.signal_quality, "")
@@ -285,6 +353,7 @@ def format_signal_message(report: SignalReport) -> str:
    live = _live_price_line(report.symbol)
    if live:
        lines.append(live)
+    lines += _spread_lines(report.symbol, include_quote=spread_detail)
    lines += [
        f"📊 Regime: {regime_str} | Vol: {vol_str}",
        "",
@@ -477,6 +546,24 @@ async def run_signal(
    )


+async def _refresh_quotes(symbols: List[str]) -> None:
+    """Fetch fresh Tiingo quotes (blocking HTTP) off the event loop —
+    called just before alerts go out so the spread block reflects the
+    moment of entry, and by the 5-min sampler."""
+    if _tiingo is None:
+        return
+    loop = asyncio.get_running_loop()
+    for symbol in set(symbols):
+        try:
+            quote = await loop.run_in_executor(
+                _executor, _tiingo.get_quote, symbol)
+        except Exception as exc:
+            logger.warning(f"Tiingo quote refresh failed for {symbol}: {exc}")
+            continue
+        if quote is not None:
+            _last_quotes[symbol] = quote
+
+
 # ── Alert gating (quality threshold + dedup) ─────────────────────────

 _QUALITY_RANK = {"A+": 4, "A": 3, "B": 2, "C": 1}
@@ -589,10 +676,13 @@ async def _scan_timeframe(
        if _passes_quality(r.signal_quality)
        and _should_alert(f"{r.symbol}_{tf.value}", r)
    ]
+    if actionable:
+        await _refresh_quotes([r.symbol for r in actionable])
    sent_ok: Set[int] = set()
    for chat_id in _signal_targets():
        for i, report in enumerate(actionable):
-            detail = format_signal_message(report)
+            detail = format_signal_message(
+                report, spread_detail=_spread_detail_for(chat_id))
            try:
                await bot.send_message(chat_id, detail, parse_mode=ParseMode.MARKDOWN)
                sent_ok.add(i)
@@ -690,9 +780,11 @@ async def _handle_breach(bot, ws_symbol: str, pair_symbol: str, price: float, le
        f"⚡ *LEVEL BREAK* — {_escape_md(display)} crossed "
        f"*{_escape_md(label)}* @ `{_fmt_price(price)}`\n\n"
    )
-    detail = header + format_signal_message(report)
+    await _refresh_quotes([pair_symbol])
    sent = False
    for chat_id in _signal_targets():
+        detail = header + format_signal_message(
+            report, spread_detail=_spread_detail_for(chat_id))
        try:
            await bot.send_message(chat_id, detail, parse_mode=ParseMode.MARKDOWN)
            sent = True
@@ -702,6 +794,15 @@ async def _handle_breach(bot, ws_symbol: str, pair_symbol: str, price: float, le
        _commit_alert(f"{pair_symbol}_{Timeframe.M15.value}", report)


+def _breach_task_done(task: asyncio.Task) -> None:
+    """Fire-and-forget breach tasks must still surface their failures —
+    without this, an exception sits unretrieved until GC and never
+    reaches the log file."""
+    _breach_tasks.discard(task)
+    if not task.cancelled() and task.exception() is not None:
+        logger.error("Breach alert task failed", exc_info=task.exception())
+
+
 async def _ws_heartbeat(ws) -> None:
    """Twelve Data drops idle WS connections; heartbeat every 10s keeps it
    alive through quiet periods (weekends, low-liquidity hours)."""
@@ -764,7 +865,7 @@ async def _ws_monitor(bot) -> None:
                            _handle_breach(bot, ws_symbol, pair_symbol, price, breached)
                        )
                        _breach_tasks.add(task)
-                        task.add_done_callback(_breach_tasks.discard)
+                        task.add_done_callback(_breach_task_done)

                    _cleanup_cooldowns()

@@ -791,15 +892,51 @@ async def _candle_loop(bot, tf: Timeframe, interval_minutes: int) -> None:
            if not _feed_active():
                break
            logger.info(f"{label} auto-scan: firing")
-            await _scan_timeframe(
-                bot, tf, AUTOSCAN_CONFIRMATIONS[tf]
-            )
+            try:
+                await _scan_timeframe(
+                    bot, tf, AUTOSCAN_CONFIRMATIONS[tf]
+                )
+            except Exception:
+                # One failed cycle must not kill the loop for good —
+                # log it and wait for the next candle boundary.
+                logger.exception(f"{label} auto-scan: cycle failed")
    except asyncio.CancelledError:
        pass
    finally:
        logger.info(f"{label} auto-scan loop stopped")


+def _weekend_closed(now: datetime) -> bool:
+    """Fri 22:00 → Sun 22:00 UTC — the window the platform treats as
+    market-closed (same as the weekend filter)."""
+    wd, hr = now.weekday(), now.hour
+    return (wd == 4 and hr >= 22) or wd == 5 or (wd == 6 and hr < 22)
+
+
+async def _spread_sampler_loop() -> None:
+    """Every 5 min: fetch bid/ask for each scanned pair, cache it for
+    the alert formatter, and append to logs/spread_log.csv — the
+    dataset that validates (or refutes) the assumed $0.30 round-trip
+    cost every backtest charges."""
+    try:
+        while True:
+            try:
+                if not _weekend_closed(datetime.now(timezone.utc)):
+                    await _refresh_quotes(SCAN_PAIRS)
+                    for symbol in SCAN_PAIRS:
+                        q = _last_quotes.get(symbol)
+                        # Age guard: never log a stale row after a failed fetch.
+                        if q is not None and q.age_seconds() < _SPREAD_SAMPLE_SECONDS:
+                            log_quote(q)
+            except Exception:
+                logger.exception("Spread sampler: cycle failed")
+            await asyncio.sleep(_SPREAD_SAMPLE_SECONDS)
+    except asyncio.CancelledError:
+        pass
+    finally:
+        logger.info("Spread sampler stopped")
+
+
 _TF_INTERVAL_MINUTES = {
    Timeframe.M5: 5, Timeframe.M15: 15, Timeframe.M30: 30,
    Timeframe.H1: 60, Timeframe.H4: 240, Timeframe.D1: 1440,
@@ -810,10 +947,11 @@ _AUTOSCAN_LOOPS = [


 _ws_task: Optional[asyncio.Task] = None
+_spread_task: Optional[asyncio.Task] = None


 def _start_scheduler(bot) -> None:
-    global _ws_task
+    global _ws_task, _spread_task
    alive = [t for t in _autoscan_tasks if not t.done()]
    if not alive:
        _autoscan_tasks.clear()
@@ -828,15 +966,23 @@ def _start_scheduler(bot) -> None:
        _ws_task = asyncio.create_task(_ws_monitor(bot))
        logger.info("WebSocket level-breach monitor started")

+    if _tiingo is not None and (_spread_task is None or _spread_task.done()):
+        _spread_task = asyncio.create_task(_spread_sampler_loop())
+        logger.info("Tiingo spread sampler started (every %ss)",
+                    _SPREAD_SAMPLE_SECONDS)
+

 def _stop_scheduler() -> None:
-    global _ws_task
+    global _ws_task, _spread_task
    for t in _autoscan_tasks:
        t.cancel()
    _autoscan_tasks.clear()
    if _ws_task and not _ws_task.done():
        _ws_task.cancel()
    _ws_task = None
+    if _spread_task and not _spread_task.done():
+        _spread_task.cancel()
+    _spread_task = None
    for t in list(_breach_tasks):
        t.cancel()
    _breach_tasks.clear()
@@ -934,6 +1080,17 @@ def _status_text() -> str:
    else:
        lines.append("❌ WebSocket: *disconnected*")

+    if _tiingo is not None:
+        for pair in SCAN_PAIRS:
+            q = _last_quotes.get(pair)
+            display = PAIR_INFO.get(pair, {}).get("display", pair)
+            if q is None:
+                lines.append(f"💱 Spread ({display}): waiting for first quote")
+            else:
+                lines.append(
+                    f"💱 Spread ({display}): `${q.spread:.2f}` "
+                    f"({q.age_seconds():.0f}s ago)")
+
    if _last_prices:
        lines.append("\n*Live Prices (WebSocket):*")
        for ws_sym, pair in _WS_TO_PAIR.items():
@@ -1266,6 +1423,38 @@ async def _post_shutdown(app: Application) -> None:

 # ── Entry point ───────────────────────────────────────────────────────

+async def _on_error(update: object, context: ContextTypes.DEFAULT_TYPE) -> None:
+    """python-telegram-bot routes every unhandled handler exception here;
+    without a registered error handler PTB only half-logs them."""
+    logger.error(
+        "Unhandled error in Telegram handler (update=%s)",
+        getattr(update, "update_id", update),
+        exc_info=context.error,
+    )
+
+
+def _install_excepthooks() -> None:
+    """Route uncaught exceptions from the main thread and worker threads
+    into the rotating log file instead of bare stderr, so a crash right
+    before exit is still recorded."""
+    def hook(exc_type, exc, tb):
+        if issubclass(exc_type, KeyboardInterrupt):
+            sys.__excepthook__(exc_type, exc, tb)
+            return
+        logger.critical("Uncaught exception", exc_info=(exc_type, exc, tb))
+
+    def thread_hook(args):
+        if issubclass(args.exc_type, SystemExit):
+            return
+        name = args.thread.name if args.thread else "?"
+        logger.critical(
+            f"Uncaught exception in thread {name}",
+            exc_info=(args.exc_type, args.exc_value, args.exc_traceback))
+
+    sys.excepthook = hook
+    threading.excepthook = thread_hook
+
+
 def main() -> None:
    if not TOKEN or not CHAT_ID:
        raise SystemExit(
@@ -1273,6 +1462,7 @@ def main() -> None:
            "and telegram.chat_id in config.json, or the TELEGRAM_TOKEN and "
            "TELEGRAM_CHAT_ID environment variables.")

+    _install_excepthooks()
    logger.info("Starting ForexBot2 Telegram bot…")

    app = (
@@ -1292,6 +1482,7 @@ def main() -> None:
    app.add_handler(CommandHandler("clearcache", cmd_clearcache))
    app.add_handler(CallbackQueryHandler(cb_scan, pattern="^scan_"))
    app.add_handler(CallbackQueryHandler(cb_menu, pattern="^menu_"))
+    app.add_error_handler(_on_error)

    logger.info("Bot running — press Ctrl+C to stop")
    app.run_polling(allowed_updates=Update.ALL_TYPES)