""" ============================================================================= execution_logger.py — Module de logging d'exécution détaillé ============================================================================= POURQUOI CE MODULE ------------------ Le bot actuel ne sait PAS combien il paie réellement en spread/slippage. Il calcule ses PnL avec les prix "théoriques" (mid market au moment du signal), alors que les ordres MARKET sur Binance s'exécutent au ASK (achat) ou au BID (vente). La différence ASK-BID, c'est le spread — invisible dans les logs actuels, mais bien réel sur le compte. CE QUE FAIT CE MODULE --------------------- À chaque ordre passé, il loggue dans un fichier dédié : - Prix théorique au moment du signal (ce que le bot voyait) - Type d'ordre (MARKET / LIMIT) - Prix d'exécution réel (depuis la réponse Binance) - Slippage en absolu et en pourcentage - Spread bid/ask au moment du fill - Volume 24h de la paire (pour corréler liquidité ↔ slippage) - Tous les fills individuels (un ordre peut être splitté en plusieurs) UTILISATION DANS market_spy.py ------------------------------ 1. Copier ce fichier dans le dossier du bot 2. En haut de market_spy.py, ajouter : from execution_logger import ExecutionLogger exec_logger = ExecutionLogger(log_dir="/var/log/market_spy") 3. À chaque ordre BUY, juste après la réponse Binance : order = client.create_order(symbol=..., side="BUY", type="MARKET", ...) exec_logger.log_buy( symbol=symbol, order_response=order, theoretical_price=price_at_signal, signal_pattern=pattern_name, ) 4. À chaque ordre SELL, juste après la réponse Binance : order = client.create_order(symbol=..., side="SELL", type="MARKET", ...) exec_logger.log_sell( symbol=symbol, order_response=order, theoretical_price=price_at_exit_signal, exit_reason=reason, buy_log_id=buy_log_id, ) Le module crée un fichier JSONL (une ligne JSON par ordre) facile à analyser ensuite avec le script `analyze_execution.py`. ============================================================================= """ import json import logging import time import uuid from datetime import datetime, timezone from pathlib import Path from typing import Optional log = logging.getLogger("execution_logger") class ExecutionLogger: """Logger structuré pour chaque exécution d'ordre.""" def __init__(self, log_dir: str = "./exec_logs", binance_client=None): """ Args: log_dir : dossier où écrire les logs JSONL binance_client : client Binance pour récupérer le bid/ask (optionnel mais recommandé) """ self.log_dir = Path(log_dir) self.log_dir.mkdir(parents=True, exist_ok=True) self.log_path = self.log_dir / f"executions_{datetime.now().strftime('%Y%m')}.jsonl" self.client = binance_client log.info(f"ExecutionLogger initialisé → {self.log_path}") # ----------------------------------------------------------------------- # API publique # ----------------------------------------------------------------------- def log_buy(self, symbol: str, order_response: dict, theoretical_price: float, signal_pattern: str, **extra) -> str: """Loggue un ordre BUY. Retourne un buy_log_id à passer à log_sell.""" log_id = str(uuid.uuid4())[:8] record = self._build_record( log_id=log_id, side="BUY", symbol=symbol, order_response=order_response, theoretical_price=theoretical_price, extra={"signal_pattern": signal_pattern, **extra}, ) self._write(record) return log_id def log_sell(self, symbol: str, order_response: dict, theoretical_price: float, exit_reason: str, buy_log_id: Optional[str] = None, **extra) -> str: """Loggue un ordre SELL et lie au BUY correspondant.""" log_id = str(uuid.uuid4())[:8] record = self._build_record( log_id=log_id, side="SELL", symbol=symbol, order_response=order_response, theoretical_price=theoretical_price, extra={"exit_reason": exit_reason, "buy_log_id": buy_log_id, **extra}, ) self._write(record) return log_id # ----------------------------------------------------------------------- # Construction du record # ----------------------------------------------------------------------- def _build_record(self, log_id: str, side: str, symbol: str, order_response: dict, theoretical_price: float, extra: dict) -> dict: """ Extrait toutes les infos utiles de la réponse Binance et calcule les métriques de qualité d'exécution. """ # Données de base de la réponse Binance order_id = order_response.get("orderId") order_type = order_response.get("type", "UNKNOWN") status = order_response.get("status", "UNKNOWN") executed_qty = float(order_response.get("executedQty", 0)) cumm_quote_qty = float(order_response.get("cummulativeQuoteQty", 0)) # Prix d'exécution moyen pondéré (le vrai prix payé/reçu) if executed_qty > 0: avg_fill_price = cumm_quote_qty / executed_qty else: avg_fill_price = 0.0 log.warning(f"Ordre {order_id} sans qty exécutée — voir status={status}") # Slippage : différence entre prix théorique et prix réel if theoretical_price > 0 and avg_fill_price > 0: slippage_abs = avg_fill_price - theoretical_price slippage_pct = (slippage_abs / theoretical_price) * 100 # Slippage défavorable : positif pour BUY (payé plus cher), # négatif pour SELL (vendu moins cher) if side == "SELL": slippage_abs = -slippage_abs slippage_pct = -slippage_pct else: slippage_abs = 0.0 slippage_pct = 0.0 # Détail des fills individuels (peut révéler du splitting d'ordre) fills_detail = [] for fill in order_response.get("fills", []): fills_detail.append({ "price": float(fill.get("price", 0)), "qty": float(fill.get("qty", 0)), "commission": float(fill.get("commission", 0)), "commission_asset": fill.get("commissionAsset", ""), }) # Frais totaux (en asset de commission, à convertir en USDT côté analyse) total_commission = sum(f["commission"] for f in fills_detail) # Bid/Ask au moment du fill (best effort — peut échouer si client absent) bid, ask, spread_pct = self._fetch_bid_ask(symbol) # Volume 24h de la paire (proxy de liquidité) vol_24h = self._fetch_volume_24h(symbol) # Latence d'exécution (temps de transaction Binance — pas la latence réseau client) transact_time = order_response.get("transactTime", int(time.time() * 1000)) return { "log_id": log_id, "timestamp_utc": datetime.now(timezone.utc).isoformat(), "transact_time_ms": transact_time, "side": side, "symbol": symbol, "order_id": order_id, "order_type": order_type, "status": status, "executed_qty": executed_qty, "cumm_quote_qty": cumm_quote_qty, "avg_fill_price": avg_fill_price, "theoretical_price": theoretical_price, "slippage_abs": slippage_abs, "slippage_pct": slippage_pct, "n_fills": len(fills_detail), "fills": fills_detail, "total_commission": total_commission, "bid": bid, "ask": ask, "spread_pct": spread_pct, "volume_24h_usdt": vol_24h, **extra, } # ----------------------------------------------------------------------- # Fetch bid/ask et volume (best effort, ne bloque pas le bot si KO) # ----------------------------------------------------------------------- def _fetch_bid_ask(self, symbol: str) -> tuple: if self.client is None: return (None, None, None) try: ticker = self.client.get_orderbook_ticker(symbol=symbol) bid = float(ticker["bidPrice"]) ask = float(ticker["askPrice"]) spread_pct = ((ask - bid) / bid * 100) if bid > 0 else None return (bid, ask, spread_pct) except Exception as e: log.debug(f"Bid/ask KO pour {symbol}: {e}") return (None, None, None) def _fetch_volume_24h(self, symbol: str) -> Optional[float]: if self.client is None: return None try: ticker = self.client.get_ticker(symbol=symbol) return float(ticker.get("quoteVolume", 0)) except Exception as e: log.debug(f"Volume 24h KO pour {symbol}: {e}") return None # ----------------------------------------------------------------------- # Écriture # ----------------------------------------------------------------------- def _write(self, record: dict) -> None: """Écriture en append, une ligne JSON par record.""" try: with open(self.log_path, "a") as f: f.write(json.dumps(record) + "\n") except Exception as e: log.error(f"Échec écriture log d'exécution : {e}")