From a1fd290d5f821a78f98794084cab4f6fe942d007 Mon Sep 17 00:00:00 2001 From: KoalaTrapLord Date: Fri, 13 Mar 2026 18:09:52 +0000 Subject: [PATCH] refactor: adopt Python logging module with named loggers Replace all print() calls with structured logging using the Python logging module. This provides: - Named loggers per subsystem: commander_ai_lab.api, .batch, .sim, .coach, .deckgen, .collection, .scanner, .ml, .cache, .pplx - Dual output: console (StreamHandler) + rotating file (RotatingFileHandler) at logs/commander-ai-lab.log (25 MB x 5 backups = 125 MB max) - Configurable via env vars: CAL_LOG_DIR, CAL_LOG_MAX_MB, CAL_LOG_BACKUP_COUNT - --verbose / -v flag for DEBUG-level output - overnight-run.py: separate rotating log at logs/overnight-run.log (10 MB x 5) - Sub-module loggers in ml/, scanner/, deck_sources/, src/ all propagate to the root commander_ai_lab logger - Stripped redundant [TAG] prefixes from messages (logger name carries context) - Format: '2026-03-13 14:00:00 INFO [commander_ai_lab.batch] message' Files changed: lab_api.py, overnight-run.py, and 11 sub-module .py files 176 total print() calls converted (101 in lab_api.py, 76 in sub-modules) --- deck_sources/archidekt_adapter.py | 6 +- deck_sources/edhrec_adapter.py | 6 +- deck_sources/moxfield_adapter.py | 6 +- deck_sources/mtggoldfish_adapter.py | 6 +- lab_api.py | 260 +++++++++++++++--------- ml/actions/labeler.py | 10 +- ml/data/dataset_builder.py | 16 +- ml/training/policy_network.py | 8 +- ml/training/trainer.py | 53 +++-- overnight-run.py | 200 +++++++++++------- scanner/pipeline.py | 8 +- scanner/ximilar_client.py | 12 +- src/commander_ai_lab/lab/experiments.py | 56 ++--- 13 files changed, 390 insertions(+), 257 deletions(-) diff --git a/deck_sources/archidekt_adapter.py b/deck_sources/archidekt_adapter.py index 8ad81eb..2bc13dd 100644 --- a/deck_sources/archidekt_adapter.py +++ b/deck_sources/archidekt_adapter.py @@ -7,6 +7,10 @@ Currently returns a hardcoded sample for end-to-end wiring. Real implementation will call the Archidekt API. """ from .models import TemplateDeck, TemplateDeckCard +import logging + +log = logging.getLogger("commander_ai_lab.deckgen.archidekt") + def fetch_template_decks(commander_name: str, color_identity: list, config: dict = None) -> list: @@ -26,5 +30,5 @@ def fetch_template_decks(commander_name: str, color_identity: list, config: dict # 1. Search Archidekt for popular decks with this commander # 2. Fetch the top 3-5 decklists # 3. Normalize card names and return as TemplateDeck - print(f" [ARCHIDEKT] Stub: No template decks for '{commander_name}' (not yet implemented)") + log.info(f" Stub: No template decks for '{commander_name}' (not yet implemented)") return [] diff --git a/deck_sources/edhrec_adapter.py b/deck_sources/edhrec_adapter.py index d419797..14ef47c 100644 --- a/deck_sources/edhrec_adapter.py +++ b/deck_sources/edhrec_adapter.py @@ -7,6 +7,10 @@ Currently returns a hardcoded sample for end-to-end wiring. Real implementation will parse EDHREC commander pages. """ from .models import TemplateDeck, TemplateDeckCard +import logging + +log = logging.getLogger("commander_ai_lab.deckgen.edhrec") + def fetch_template_decks(commander_name: str, color_identity: list, config: dict = None) -> list: @@ -27,5 +31,5 @@ def fetch_template_decks(commander_name: str, color_identity: list, config: dict # 2. Fetch the "Average Deck" or "Top Cards" list # 3. Parse card names and inclusion percentages # 4. Return as a single TemplateDeck with weighted cards - print(f" [EDHREC] Stub: No recommendations for '{commander_name}' (not yet implemented)") + log.info(f" Stub: No recommendations for '{commander_name}' (not yet implemented)") return [] diff --git a/deck_sources/moxfield_adapter.py b/deck_sources/moxfield_adapter.py index ec95582..b9fba11 100644 --- a/deck_sources/moxfield_adapter.py +++ b/deck_sources/moxfield_adapter.py @@ -6,6 +6,10 @@ Fetches template decklists from Moxfield for a given commander. Currently returns empty (experimental — not yet implemented). """ from .models import TemplateDeck, TemplateDeckCard +import logging + +log = logging.getLogger("commander_ai_lab.deckgen.moxfield") + def fetch_template_decks(commander_name: str, color_identity: list, config: dict = None) -> list: @@ -13,5 +17,5 @@ def fetch_template_decks(commander_name: str, color_identity: list, config: dict Fetch template decks from Moxfield for the given commander. Experimental — not yet implemented. """ - print(f" [MOXFIELD] Stub: Not yet implemented for '{commander_name}'") + log.info(f" Stub: Not yet implemented for '{commander_name}'") return [] diff --git a/deck_sources/mtggoldfish_adapter.py b/deck_sources/mtggoldfish_adapter.py index df8dceb..34c2e2b 100644 --- a/deck_sources/mtggoldfish_adapter.py +++ b/deck_sources/mtggoldfish_adapter.py @@ -6,6 +6,10 @@ Fetches template decklists from MTGGoldfish for a given commander. Currently returns empty (experimental — not yet implemented). """ from .models import TemplateDeck, TemplateDeckCard +import logging + +log = logging.getLogger("commander_ai_lab.deckgen.mtggoldfish") + def fetch_template_decks(commander_name: str, color_identity: list, config: dict = None) -> list: @@ -13,5 +17,5 @@ def fetch_template_decks(commander_name: str, color_identity: list, config: dict Fetch template decks from MTGGoldfish for the given commander. Experimental — not yet implemented. """ - print(f" [MTGGOLDFISH] Stub: Not yet implemented for '{commander_name}'") + log.info(f" Stub: Not yet implemented for '{commander_name}'") return [] diff --git a/lab_api.py b/lab_api.py index 6a3fb61..6400db7 100644 --- a/lab_api.py +++ b/lab_api.py @@ -19,6 +19,8 @@ import asyncio import csv import io import json +import logging +import logging.handlers import os import re import sqlite3 @@ -62,6 +64,61 @@ class Config: CFG = Config() +# ══════════════════════════════════════════════════════════════ +# Logging Setup +# ══════════════════════════════════════════════════════════════ + +_LOG_FORMAT = "%(asctime)s %(levelname)-5s [%(name)s] %(message)s" +_LOG_DATE_FMT = "%Y-%m-%d %H:%M:%S" +_LOG_DIR = Path(os.environ.get("CAL_LOG_DIR", "logs")) +_LOG_MAX_BYTES = int(os.environ.get("CAL_LOG_MAX_MB", "25")) * 1024 * 1024 +_LOG_BACKUP_COUNT = int(os.environ.get("CAL_LOG_BACKUP_COUNT", "5")) + + +def setup_logging(level: int = logging.INFO) -> None: + """Configure the root 'commander_ai_lab' logger with console + rotating file.""" + _LOG_DIR.mkdir(parents=True, exist_ok=True) + + root_logger = logging.getLogger("commander_ai_lab") + root_logger.setLevel(level) + + # Avoid duplicate handlers if called again + if root_logger.handlers: + return + + formatter = logging.Formatter(_LOG_FORMAT, datefmt=_LOG_DATE_FMT) + + # Console handler — matches previous print() behaviour + console = logging.StreamHandler(sys.stdout) + console.setLevel(level) + console.setFormatter(formatter) + root_logger.addHandler(console) + + # Rotating file handler — 25 MB × 5 backups = 125 MB max + file_handler = logging.handlers.RotatingFileHandler( + _LOG_DIR / "commander-ai-lab.log", + maxBytes=_LOG_MAX_BYTES, + backupCount=_LOG_BACKUP_COUNT, + encoding="utf-8", + ) + file_handler.setLevel(level) + file_handler.setFormatter(formatter) + root_logger.addHandler(file_handler) + + +# Named loggers — import these where needed +log = logging.getLogger("commander_ai_lab.api") # API endpoints, server lifecycle +log_batch = logging.getLogger("commander_ai_lab.batch") # Batch sim (Java + DeepSeek) +log_sim = logging.getLogger("commander_ai_lab.sim") # DeepSeek game simulation +log_coach = logging.getLogger("commander_ai_lab.coach") # Coach + report generation +log_deckgen = logging.getLogger("commander_ai_lab.deckgen") # Deck generation (all versions) +log_collect = logging.getLogger("commander_ai_lab.collection") # Collection management +log_scan = logging.getLogger("commander_ai_lab.scanner") # Card scanner +log_ml = logging.getLogger("commander_ai_lab.ml") # ML training + inference +log_cache = logging.getLogger("commander_ai_lab.cache") # Scryfall cache +log_pplx = logging.getLogger("commander_ai_lab.pplx") # Perplexity API + + # ══════════════════════════════════════════════════════════════ # App Setup # ══════════════════════════════════════════════════════════════ @@ -512,7 +569,7 @@ async def list_decks(): }) seen_names.add(db_name.lower()) except Exception as e: - print(f" WARNING: Failed to load DB decks for /api/lab/decks: {e}") + log.warning(f" WARNING: Failed to load DB decks for /api/lab/decks: {e}") return {"decks": decks} @@ -719,10 +776,10 @@ def load_precon_index(): if idx_path.exists(): with open(idx_path, "r", encoding="utf-8") as f: PRECON_INDEX = json.load(f) - print(f" Precons: {len(PRECON_INDEX)} precon decks loaded") + log.info(f" Precons: {len(PRECON_INDEX)} precon decks loaded") else: PRECON_INDEX = [] - print(f" Precons: index not found at {idx_path}") + log.info(f" Precons: index not found at {idx_path}") @app.get("/api/lab/precons") @@ -866,7 +923,7 @@ def download_precon_database(force: bool = False) -> dict: if len(existing) > 50: age_hours = (time.time() - idx_path.stat().st_mtime) / 3600 if age_hours < PRECON_CACHE_HOURS: - print(f" Precons: {len(existing)} decks cached " + log.info(f" Precons: {len(existing)} decks cached " f"({age_hours:.0f}h old, refresh after {PRECON_CACHE_HOURS}h)") PRECON_INDEX = existing return {"downloaded": 0, "skipped": True, "total": len(existing), @@ -875,7 +932,7 @@ def download_precon_database(force: bool = False) -> dict: pass # Fall through to download # ── Download ───────────────────────────────────────────── - print(" Precons: Downloading full precon database from GitHub...") + log.info(" Precons: Downloading full precon database from GitHub...") try: req = Request(GITHUB_PRECON_URL, headers={"User-Agent": "CommanderAILab/3.0"}) with urlopen(req, timeout=120) as resp: @@ -883,7 +940,7 @@ def download_precon_database(force: bool = False) -> dict: all_decks = json.loads(raw) except Exception as e: msg = f"Failed to download precon database: {e}" - print(f" Precons: ERROR — {msg}") + log.error(f" Precons: ERROR — {msg}") # Fall back to whatever we have locally if idx_path.exists(): load_precon_index() @@ -895,7 +952,7 @@ def download_precon_database(force: bool = False) -> dict: if d.get('type') == 'Commander Deck' and (d.get('format') or '').lower() == 'commander' ] - print(f" Precons: Found {len(commander_decks)} Commander precon decks") + log.info(f" Precons: Found {len(commander_decks)} Commander precon decks") # ── Ensure precon-decks dir exists ─────────────────────── PRECON_DIR.mkdir(parents=True, exist_ok=True) @@ -953,7 +1010,7 @@ def download_precon_database(force: bool = False) -> dict: json.dump(index, f, indent=2, ensure_ascii=False) PRECON_INDEX = index - print(f" Precons: {written} .dck files written, index saved") + log.info(f" Precons: {written} .dck files written, index saved") return {"downloaded": written, "skipped": False, "total": written, "error": None} @@ -1195,7 +1252,7 @@ def _save_profile_to_dck(profile: dict) -> Path: out_path = Path(save_dir) / f"{safe_name}.dck" out_path.write_text(content, encoding="utf-8") - print(f" [Import] Saved .dck: {out_path}") + log_collect.info(f" Saved .dck: {out_path}") return out_path @@ -1239,7 +1296,7 @@ async def run_batch_subprocess( ai_think_time_ms=ai_think_time_ms, max_queue_depth=max_queue_depth, ) - print(f"[Lab API] Starting batch {state.batch_id}: {' '.join(cmd[:6])}...") + log_batch.info(f"Starting batch {state.batch_id}: {' '.join(cmd[:6])}...") loop = asyncio.get_event_loop() await loop.run_in_executor( None, @@ -1248,7 +1305,7 @@ async def run_batch_subprocess( except Exception as e: state.error = str(e) state.running = False - print(f"[Lab API] Batch {state.batch_id} ERROR: {e}") + log_batch.error(f"Batch {state.batch_id} ERROR: {e}") def _run_process_blocking(state: BatchState, cmd: list[str]): @@ -1266,9 +1323,9 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): dbg.write(f"Forge JAR exists: {os.path.exists(CFG.forge_jar)}\n") dbg.write(f"Forge Dir exists: {os.path.isdir(CFG.forge_dir)}\n") dbg.write(f"{'-'*60}\n") - print(f"[Lab API] Debug log: {debug_log_path}") + log_batch.warning(f"Debug log: {debug_log_path}") except Exception as e: - print(f"[Lab API] Could not write debug log header: {e}") + log_batch.warning(f"Could not write debug log header: {e}") # Ensure Forge subprocesses use Java 17 (Forge crashes on Java 25+) env = os.environ.copy() @@ -1278,7 +1335,7 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): java17_home = os.path.dirname(java17_bin) env['JAVA_HOME'] = java17_home env['PATH'] = java17_bin + os.pathsep + env.get('PATH', '') - print(f'[Lab API] Using Java 17: {java17}') + log_batch.info(f'Using Java 17: {java17}') # NOTE: Do NOT set _JAVA_OPTIONS=-Djava.awt.headless=true here. # Forge sim mode needs AWT classes for card data initialization; @@ -1309,7 +1366,7 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): time.sleep(30) elapsed_since_activity = time.time() - last_activity[0] if elapsed_since_activity > stall_limit: - print(f'[Lab API] WATCHDOG: No output for {int(elapsed_since_activity)}s. Killing process.') + log_batch.warning(f'WATCHDOG: No output for {int(elapsed_since_activity)}s. Killing process.') state.log_lines.append(f'[WATCHDOG] Process stalled ({int(elapsed_since_activity)}s with no output). Killed.') proc.kill() return @@ -1345,7 +1402,7 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): except ValueError: pass - print(f" [{state.batch_id}] {line}") + log_batch.info(f" [{state.batch_id}] {line}") proc.wait() @@ -1367,7 +1424,7 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): dbg.write("<< NO OUTPUT >>\n") dbg.write(f"-- END OUTPUT --\n\n") except Exception as e: - print(f"[Lab API] Could not write debug log output: {e}") + log_batch.warning(f"Could not write debug log output: {e}") if proc.returncode != 0: if proc.returncode == -9 or proc.returncode == 137: @@ -1376,7 +1433,7 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): state.error = f'Java process exited with code {proc.returncode}. Check forge-sim-debug.log for details.' else: state.completed_games = state.total_games - print(f"[Lab API] Batch {state.batch_id} completed in {elapsed}ms") + log_batch.info(f"Batch {state.batch_id} completed in {elapsed}ms") # Auto-generate deck reports for the coach if state.result_path and os.path.exists(state.result_path): @@ -1386,9 +1443,9 @@ def _run_process_blocking(state: BatchState, cmd: list[str]): reports_dir = str(lab_root / "deck-reports") updated = generate_single_deck_report(state.result_path, reports_dir) if updated: - print(f"[Lab API] Deck reports updated: {', '.join(updated)}") + log_batch.info(f"Deck reports updated: {', '.join(updated)}") except Exception as rpt_err: - print(f"[Lab API] Deck report generation failed (non-fatal): {rpt_err}") + log_batch.info(f"Deck report generation failed (non-fatal): {rpt_err}") except Exception as e: state.error = str(e) @@ -1451,7 +1508,7 @@ def _load_deck_cards_by_name(deck_name: str) -> list[dict]: if result: return result except Exception as e: - print(f"[DeepSeek Batch] DB lookup failed for '{deck_name}': {e}") + log_sim.error(f"DB lookup failed for '{deck_name}': {e}") # 2. Try .dck file if CFG.forge_decks_dir and os.path.isdir(CFG.forge_decks_dir): @@ -1752,7 +1809,7 @@ def _run_deepseek_batch_thread( for ds in all_deck_results: state.log_lines.append(f' {ds["deckName"]}: {ds["wins"]}W-{ds["losses"]}L ({ds["winRate"]}% WR)') - print(f'[DeepSeek Batch] Batch {state.batch_id} complete: {completed} games in {elapsed:.1f}s') + log_sim.info(f'Batch {state.batch_id} complete: {completed} games in {elapsed:.1f}s') except Exception as e: import traceback @@ -2015,10 +2072,10 @@ def init_collection_db(): for col_name, col_def in _migrate_columns: if col_name not in existing_cols: conn.execute(f"ALTER TABLE collection_entries ADD COLUMN {col_name} {col_def}") - print(f" Migration: added column '{col_name}' to collection_entries") + log_collect.info(f" Migration: added column '{col_name}' to collection_entries") conn.commit() conn.close() - print(f" Collection DB: {COLLECTION_DB_PATH}") + log_collect.info(f" Collection DB: {COLLECTION_DB_PATH}") # Fields stored as JSON strings in SQLite that should be returned as parsed arrays @@ -4181,7 +4238,7 @@ async def export_deck_to_sim(deck_id: int): out_path = Path(save_dir) / f"{safe_name}.dck" out_path.write_text(content, encoding="utf-8") - print(f" [DeckBuilder] Exported deck {deck_id} to {out_path}") + log_deckgen.info(f" Exported deck {deck_id} to {out_path}") return { "success": True, @@ -4507,7 +4564,7 @@ async def scan_card_image(request: FastAPIRequest): if len(image_bytes) > 20 * 1024 * 1024: raise HTTPException(400, "Image file too large (max 20 MB)") - print(f" [SCAN] Processing {len(image_bytes)} bytes, mode={mode} (Ximilar AI)") + log_scan.info(f" Processing {len(image_bytes)} bytes, mode={mode} (Ximilar AI)") if mode == "multi": results = scan_multi(image_bytes, _scryfall_fuzzy_lookup, ximilar_api_key=api_key) @@ -4918,7 +4975,7 @@ async def get_card_edhrec(cardId: int): }) except Exception as e: - print(f" [EDHREC] Error fetching data for '{name}': {e}") + log_deckgen.error(f" Error fetching data for '{name}': {e}") # Graceful degradation — return empty results result = { @@ -5345,7 +5402,7 @@ def _get_deepseek_brain(): cfg.log_dir = _os2.path.join(_os2.path.dirname(_os2.path.abspath(__file__)), 'logs', 'decisions') _deepseek_brain = DeepSeekBrain(cfg) except Exception as e: - print(f'[DeepSeek] Failed to initialize brain: {e}') + log_sim.error(f'Failed to initialize brain: {e}') return None return _deepseek_brain @@ -5844,11 +5901,11 @@ def _generate_deck(req: DeckGenerationRequest) -> dict: return {"error": "Commander not found. Please check the name or Scryfall ID."} color_identity = req.color_identity or commander.get("color_identity", []) - print(f" [DECKGEN] Commander: {commander['name']}, CI: {color_identity}") + log_deckgen.info(f" Commander: {commander['name']}, CI: {color_identity}") # 2. Load collection collection = _get_collection_for_colors(color_identity) - print(f" [DECKGEN] {len(collection)} cards in collection match color identity") + log_deckgen.info(f" {len(collection)} cards in collection match color identity") # 3. Call source adapters (currently stubbed) template_cards = [] # list of (name, weight, source_name) @@ -5861,7 +5918,7 @@ def _generate_deck(req: DeckGenerationRequest) -> dict: for tc in td.cards: template_cards.append((tc.name, tc.quantity, "archidekt")) except Exception as e: - print(f" [DECKGEN] Archidekt adapter error: {e}") + log_deckgen.error(f" Archidekt adapter error: {e}") try: if sources.use_edhrec: @@ -5870,7 +5927,7 @@ def _generate_deck(req: DeckGenerationRequest) -> dict: for tc in td.cards: template_cards.append((tc.name, tc.quantity, "edhrec")) except Exception as e: - print(f" [DECKGEN] EDHREC adapter error: {e}") + log_deckgen.error(f" EDHREC adapter error: {e}") try: if sources.use_moxfield: @@ -5879,7 +5936,7 @@ def _generate_deck(req: DeckGenerationRequest) -> dict: for tc in td.cards: template_cards.append((tc.name, tc.quantity, "moxfield")) except Exception as e: - print(f" [DECKGEN] Moxfield adapter error: {e}") + log_deckgen.error(f" Moxfield adapter error: {e}") try: if sources.use_mtggoldfish: @@ -5888,7 +5945,7 @@ def _generate_deck(req: DeckGenerationRequest) -> dict: for tc in td.cards: template_cards.append((tc.name, tc.quantity, "mtggoldfish")) except Exception as e: - print(f" [DECKGEN] MTGGoldfish adapter error: {e}") + log_deckgen.error(f" MTGGoldfish adapter error: {e}") # 4. Build candidate pool from collection, scored by type need # Build a map: name_lower -> card dict (deduped) @@ -6076,8 +6133,8 @@ def _generate_deck(req: DeckGenerationRequest) -> dict: "is_proxy": card.get("is_proxy", False), }) - print(f" [DECKGEN] Generated deck: {len(clean_cards)} cards + commander") - print(f" [DECKGEN] Stats: {stats}") + log_deckgen.info(f" Generated deck: {len(clean_cards)} cards + commander") + log_deckgen.info(f" Stats: {stats}") return { "commander": commander, @@ -6208,11 +6265,11 @@ async def deck_generator_commit(req: DeckGenerationRequest): dck_lines.append(f"{card.get('quantity', 1)} {card_name}") with open(dck_path, "w", encoding="utf-8") as f: f.write("\n".join(dck_lines)) - print(f" [DECKGEN] Exported .dck file: {dck_path}") + log_deckgen.info(f" Exported .dck file: {dck_path}") except Exception as e: - print(f" [DECKGEN] Warning: Failed to export .dck file: {e}") + log_deckgen.warning(f" Warning: Failed to export .dck file: {e}") - print(f" [DECKGEN] Saved deck '{deck_name}' (ID: {deck_id}) with {len(cards)} cards + commander") + log_deckgen.info(f" Saved deck '{deck_name}' (ID: {deck_id}) with {len(cards)} cards + commander") result["deck_id"] = deck_id result["deck_name"] = deck_name @@ -6291,7 +6348,7 @@ async def deck_generator_commander_search(q: str = ""): "image_url": image_uris.get("normal", image_uris.get("small", "")), }) except Exception as e: - print(f" [DECKGEN] Scryfall search error: {e}") + log_deckgen.error(f" Scryfall search error: {e}") return {"results": results[:20]} @@ -6461,7 +6518,7 @@ def _call_pplx_api(messages: list[dict], max_tokens: int = 4096, temperature: fl raise ValueError('Empty response from Perplexity API') content = choices[0].get('message', {}).get('content', '') usage = data.get('usage', {}) - print(f'[pplx-api] tokens: prompt={usage.get("prompt_tokens","?")}, ' + log_pplx.debug(f'tokens: prompt={usage.get("prompt_tokens","?")}, ' f'completion={usage.get("completion_tokens","?")}, ' f'model={data.get("model","?")}') return content @@ -6776,7 +6833,7 @@ async def deck_generate_ai(req: DeckGenerateAIRequest): commander = scry_data.get('name', commander) # Use canonical name commander_type = scry_data.get('type_line', '') except Exception as e: - print(f'[pplx-gen] Scryfall lookup failed for "{commander}": {e}') + log_pplx.error(f'Scryfall lookup failed for "{commander}": {e}') # Build collection summary collection_block = '' @@ -6951,7 +7008,7 @@ async def deck_gen_v3_generate(req: DeckGenV3Request): except ValueError as e: return JSONResponse({'error': str(e)}, status_code=422) except Exception as e: - print(f'[deck-gen-v3] Error: {e}') + log_deckgen.error(f'Error: {e}') import traceback traceback.print_exc() raise HTTPException(500, f'Deck generation failed: {str(e)}') @@ -7058,19 +7115,19 @@ async def deck_gen_v3_commit(req: DeckGenV3Request): dck_lines.append(f"{card.get('count', 1)} {cname}") with open(dck_path, 'w', encoding='utf-8') as f: f.write('\n'.join(dck_lines)) - print(f" [DeckGenV3] Exported .dck: {dck_path}") + log_deckgen.info(f" Exported .dck: {dck_path}") except Exception as e: - print(f" [DeckGenV3] .dck export failed: {e}") + log_deckgen.error(f" .dck export failed: {e}") result['deck_id'] = deck_id result['deck_name'] = deck_name - print(f" [DeckGenV3] Committed deck '{deck_name}' (ID: {deck_id})") + log_deckgen.info(f" Committed deck '{deck_name}' (ID: {deck_id})") return result except ValueError as e: return JSONResponse({'error': str(e)}, status_code=422) except Exception as e: - print(f'[deck-gen-v3] Commit error: {e}') + log_deckgen.error(f'Commit error: {e}') import traceback traceback.print_exc() raise HTTPException(500, f'Deck generation/commit failed: {str(e)}') @@ -7276,22 +7333,22 @@ def init_coach_service(): from coach.config import EMBEDDINGS_NPZ if EMBEDDINGS_NPZ.exists(): _coach_embeddings.load() - print(f" Coach: Embeddings loaded ({_coach_embeddings.card_count} cards)") + log_coach.info(f" Coach: Embeddings loaded ({_coach_embeddings.card_count} cards)") else: - print(" Coach: Embeddings not yet downloaded (will download on first use)") + log_coach.warning(" Coach: Embeddings not yet downloaded (will download on first use)") except Exception as e: - print(f" Coach: Embeddings load failed: {e}") + log_coach.error(f" Coach: Embeddings load failed: {e}") _coach_service = CoachService(_coach_llm, _coach_embeddings) # Check LLM connection llm_status = _coach_llm.check_connection() if llm_status.get("connected"): - print(f" Coach LLM: Connected ({llm_status.get('active_model', 'unknown')})") + log_coach.info(f" Coach LLM: Connected ({llm_status.get('active_model', 'unknown')})") else: - print(f" Coach LLM: Not connected (start LM Studio on 192.168.0.122:1234)") + log_coach.warning(f" Coach LLM: Not connected (start LM Studio on 192.168.0.122:1234)") - print(" Coach: Service initialized") + log_coach.info(" Coach: Service initialized") # Initialize V3 Deck Generator (Perplexity) _deck_gen_v3_error = None @@ -7310,21 +7367,21 @@ def init_coach_service(): db_conn_factory=_get_db_conn, embedding_index=_coach_embeddings, ) - print(f" Deck Gen V3: Initialized (model: {DECK_GEN_MODEL})") + log_deckgen.info(f" Deck Gen V3: Initialized (model: {DECK_GEN_MODEL})") except ImportError as e: _deck_gen_v3_error = f"Missing dependency: {e}. Run: pip install openai" - print(f" Deck Gen V3: {_deck_gen_v3_error}") + log_deckgen.error(f" Deck Gen V3: {_deck_gen_v3_error}") _deck_gen_v3 = None except Exception as e: _deck_gen_v3_error = str(e) - print(f" Deck Gen V3: Failed to initialize: {e}") + log_deckgen.error(f" Deck Gen V3: Failed to initialize: {e}") _deck_gen_v3 = None else: _deck_gen_v3_error = "PPLX_API_KEY not set" - print(" Deck Gen V3: Skipped (no PPLX_API_KEY)") + log_deckgen.info(" Deck Gen V3: Skipped (no PPLX_API_KEY)") except Exception as e: - print(f" Coach: Failed to initialize: {e}") + log_coach.error(f" Coach: Failed to initialize: {e}") _coach_service = None @@ -7427,7 +7484,7 @@ async def coach_run_session(deck_id: str, body: CoachRequestBody = None): try: _coach_embeddings.load(force_download=True) except Exception as e: - print(f" Coach: Embeddings download failed: {e}") + log_coach.error(f" Coach: Embeddings download failed: {e}") goals = None if body and body.goals: @@ -7442,7 +7499,7 @@ async def coach_run_session(deck_id: str, body: CoachRequestBody = None): try: fallback_report = _build_deck_report_from_db(deck_id) except Exception as e: - print(f" Coach: Fallback report build failed for '{deck_id}': {e}") + log_coach.error(f" Coach: Fallback report build failed for '{deck_id}': {e}") try: session = await _coach_service.run_coaching_session(deck_id, goals, fallback_report=fallback_report) @@ -7998,11 +8055,11 @@ def _get_policy_service(): from ml.serving.policy_server import PolicyInferenceService _policy_service = PolicyInferenceService() if _policy_service.load(): - print(f"[ML] Policy model loaded on {_policy_service.device}") + log_ml.info(f"Policy model loaded on {_policy_service.device}") else: - print(f"[ML] Policy model not available: {_policy_service._load_error}") + log_ml.error(f"Policy model not available: {_policy_service._load_error}") except Exception as e: - print(f"[ML] Policy service init failed: {e}") + log_ml.error(f"Policy service init failed: {e}") return _policy_service @@ -8162,7 +8219,7 @@ def _run_training_pipeline( if rebuild_dataset or not os.path.exists(train_path): _training_state["phase"] = "building" _training_state["message"] = "Loading card embeddings & building dataset..." - print("[ML Train] Building dataset (loading embeddings, may auto-download)...") + log_ml.info("Building dataset (loading embeddings, may auto-download)...") from ml.data.dataset_builder import build_dataset, split_dataset, save_dataset dataset = build_dataset(results_dir=results_dir) @@ -8174,14 +8231,14 @@ def _run_training_pipeline( save_dataset(test_ds, os.path.join(data_dir, "test.npz")) total_samples = len(dataset["states"]) _training_state["message"] = f"Dataset built: {total_samples} samples" - print(f"[ML Train] Dataset built: {total_samples} samples") + log_ml.info(f"Dataset built: {total_samples} samples") # --- Phase 2: Train --- _training_state["phase"] = "training" _training_state["total_epochs"] = epochs _training_state["current_epoch"] = 0 _training_state["message"] = f"Training policy network ({epochs} epochs)..." - print(f"[ML Train] Starting training: {epochs} epochs, lr={lr}, bs={batch_size}") + log_ml.info(f"Starting training: {epochs} epochs, lr={lr}, bs={batch_size}") import numpy as np import torch @@ -8253,13 +8310,13 @@ def _run_training_pipeline( "device": device, } _training_state["message"] = f"Training complete! Best val acc: {summary.get('best_val_accuracy', 0):.1%}" - print(f"[ML Train] Complete: {summary.get('best_val_accuracy', 0):.1%} val accuracy") + log_ml.info(f"Complete: {summary.get('best_val_accuracy', 0):.1%} val accuracy") # Auto-reload policy server with new checkpoint global _policy_service, _policy_service_init_attempted if _policy_service and _policy_service._loaded: _policy_service.reload(summary.get("checkpoint_path")) - print("[ML Train] Policy server reloaded with new checkpoint") + log_ml.info("Policy server reloaded with new checkpoint") elif not _policy_service_init_attempted: _policy_service_init_attempted = False # Allow re-init with new model @@ -8269,7 +8326,7 @@ def _run_training_pipeline( _training_state["running"] = False _training_state["error"] = str(e) _training_state["message"] = f"Training failed: {e}" - print(f"[ML Train] ERROR: {e}") + log_ml.error(f"ERROR: {e}") traceback.print_exc() @@ -8678,6 +8735,8 @@ def parse_args(): help="Ximilar API key for card scanner (visual AI recognition)") parser.add_argument("--pplx-key", default=os.environ.get("PPLX_API_KEY", "REDACTED_PPLX_KEY"), help="Perplexity API key for AI deck research/generation (env: PPLX_API_KEY)") + parser.add_argument("--verbose", "-v", action="store_true", + help="Enable DEBUG-level logging (default: INFO)") return parser.parse_args() @@ -8721,17 +8780,18 @@ def load_commander_meta(): try: with open(meta_path, "r", encoding="utf-8") as f: COMMANDER_META = json.load(f) - print(f" Meta: Loaded {len(COMMANDER_META)} commanders from {meta_path}") + log.info(f" Meta: Loaded {len(COMMANDER_META)} commanders from {meta_path}") return except Exception as e: - print(f" WARNING: Failed to load commander-meta.json: {e}") + log.warning(f" WARNING: Failed to load commander-meta.json: {e}") COMMANDER_META = BUILTIN_COMMANDERS - print(f" Meta: {len(COMMANDER_META)} built-in commanders") + log.info(f" Meta: {len(COMMANDER_META)} built-in commanders") def main(): args = parse_args() + setup_logging(logging.DEBUG if getattr(args, 'verbose', False) else logging.INFO) CFG.forge_jar = args.forge_jar CFG.forge_dir = args.forge_dir @@ -8741,21 +8801,21 @@ def main(): CFG.ximilar_api_key = args.ximilar_key CFG.pplx_api_key = args.pplx_key - print("╔══════════════════════════════════════════════════╗") - print("║ Commander AI Lab — API Server v3.0.0 ║") - print("╚══════════════════════════════════════════════════╝") - print() - print(f" Forge JAR: {CFG.forge_jar}") - print(f" Forge Dir: {CFG.forge_dir}") - print(f" Decks Dir: {CFG.forge_decks_dir}") - print(f" Lab JAR: {CFG.lab_jar}") - print(f" Results Dir: {CFG.results_dir}") - print(f" Port: {CFG.port}") - print(f" Ximilar: {'configured' if CFG.ximilar_api_key else 'NOT SET (scanner will fail)'}") - print(f" Perplexity: {'configured' if CFG.pplx_api_key else 'NOT SET (AI research/gen disabled)'}") + log.info("╔══════════════════════════════════════════════════╗") + log.info("║ Commander AI Lab — API Server v3.0.0 ║") + log.info("╚══════════════════════════════════════════════════╝") + log.info("") + log.info(f" Forge JAR: {CFG.forge_jar}") + log.info(f" Forge Dir: {CFG.forge_dir}") + log.info(f" Decks Dir: {CFG.forge_decks_dir}") + log.info(f" Lab JAR: {CFG.lab_jar}") + log.info(f" Results Dir: {CFG.results_dir}") + log.info(f" Port: {CFG.port}") + log.info(f" Ximilar: {'configured' if CFG.ximilar_api_key else 'NOT SET (scanner will fail)'}") + log.info(f" Perplexity: {'configured' if CFG.pplx_api_key else 'NOT SET (AI research/gen disabled)'}") j17 = get_java17() - print(f" Java 17: {j17 if j17 != 'java' else 'NOT FOUND (batch sim may fail on Java 25+)'}") - print(f" LM Studio: http://192.168.0.122:1234") + log.info(f" Java 17: {j17 if j17 != 'java' else 'NOT FOUND (batch sim may fail on Java 25+)'}") + log.info(f" LM Studio: http://192.168.0.122:1234") load_commander_meta() download_precon_database() # Auto-downloads all 163+ Commander precons on first run @@ -8764,27 +8824,27 @@ def main(): # Ximilar API key check if not CFG.ximilar_api_key: - print(" WARNING: --ximilar-key not set. Card scanner will not work.") - print(" Set via CLI: --ximilar-key YOUR_KEY") - print(" Or env var: XIMILAR_API_KEY=YOUR_KEY") + log_scan.warning(" WARNING: --ximilar-key not set. Card scanner will not work.") + log.info(" Set via CLI: --ximilar-key YOUR_KEY") + log.info(" Or env var: XIMILAR_API_KEY=YOUR_KEY") if not CFG.forge_jar: - print("WARNING: --forge-jar not set. /api/lab/start will fail.") + log.warning("WARNING: --forge-jar not set. /api/lab/start will fail.") if not CFG.lab_jar: - print("WARNING: Lab JAR not found. Build with: mvn package -DskipTests") + log.warning("WARNING: Lab JAR not found. Build with: mvn package -DskipTests") if not CFG.forge_decks_dir: - print("WARNING: Commander decks dir not found. /api/lab/decks will return empty.") + log.warning("WARNING: Commander decks dir not found. /api/lab/decks will return empty.") - print() - print(f" Starting server on http://localhost:{CFG.port}") + log.info("") + log.info(f" Starting server on http://localhost:{CFG.port}") if _spa_dir.exists(): - print(f" Web UI: http://localhost:{CFG.port}/ (React SPA)") - print(f" Routes: / (Batch Sim), /collection, /decks, /autogen, /simulator, /coach, /training") + log.info(f" Web UI: http://localhost:{CFG.port}/ (React SPA)") + log.info(f" Routes: / (Batch Sim), /collection, /decks, /autogen, /simulator, /coach, /training") else: - print(f" Web UI: http://localhost:{CFG.port}/index.html (legacy HTML)") - print(f" NOTE: React SPA not built. Run: cd frontend/commander-ai-lab-ui && npm install && npm run build") - print(f" API docs: http://localhost:{CFG.port}/docs") - print() + log.info(f" Web UI: http://localhost:{CFG.port}/index.html (legacy HTML)") + log.info(f" NOTE: React SPA not built. Run: cd frontend/commander-ai-lab-ui && npm install && npm run build") + log.info(f" API docs: http://localhost:{CFG.port}/docs") + log.info("") import uvicorn uvicorn.run(app, host="0.0.0.0", port=CFG.port, log_level="info") diff --git a/ml/actions/labeler.py b/ml/actions/labeler.py index 4bbe078..10278ae 100644 --- a/ml/actions/labeler.py +++ b/ml/actions/labeler.py @@ -240,12 +240,12 @@ def print_label_distribution(labels: np.ndarray) -> Dict[str, int]: dist[action.value] = count total = len(labels) - print(f"\n{'Action':<25} {'Count':>8} {'Pct':>8}") - print("─" * 43) + log.info(f"\n{'Action':<25} {'Count':>8} {'Pct':>8}") + log.info("─" * 43) for action_name, count in sorted(dist.items(), key=lambda x: -x[1]): pct = (count / total * 100) if total > 0 else 0 - print(f" {action_name:<23} {count:>8} {pct:>7.1f}%") - print(f"{'─' * 43}") - print(f" {'TOTAL':<23} {total:>8}") + log.info(f" {action_name:<23} {count:>8} {pct:>7.1f}%") + log.info(f"{'─' * 43}") + log.info(f" {'TOTAL':<23} {total:>8}") return dist diff --git a/ml/data/dataset_builder.py b/ml/data/dataset_builder.py index 2060d4a..cb43908 100644 --- a/ml/data/dataset_builder.py +++ b/ml/data/dataset_builder.py @@ -154,17 +154,17 @@ def build_dataset( # Print game outcome distribution unique_outcomes, outcome_counts = np.unique(outcomes, return_counts=True) - print(f"\n{'Outcome':<25} {'Count':>8}") - print("─" * 35) + log.info(f"\n{'Outcome':<25} {'Count':>8}") + log.info("─" * 35) for o, c in sorted(zip(unique_outcomes, outcome_counts), key=lambda x: -x[1]): - print(f" {str(o):<23} {c:>8}") + log.info(f" {str(o):<23} {c:>8}") # Print playstyle distribution unique_styles, style_counts = np.unique(playstyles, return_counts=True) - print(f"\n{'Playstyle':<25} {'Count':>8}") - print("─" * 35) + log.info(f"\n{'Playstyle':<25} {'Count':>8}") + log.info("─" * 35) for s, c in sorted(zip(unique_styles, style_counts), key=lambda x: -x[1]): - print(f" {str(s):<23} {c:>8}") + log.info(f" {str(s):<23} {c:>8}") return { "states": states, @@ -288,7 +288,7 @@ def main(): max_samples=args.max_samples, ) if not dataset: - print("\nNo data to save. Run simulations with --ml-log first.") + log.info("\nNo data to save. Run simulations with --ml-log first.") sys.exit(1) if args.no_split: @@ -300,7 +300,7 @@ def main(): save_dataset(val, f"{base}-val.npz") save_dataset(test, f"{base}-test.npz") - print("\nDataset build complete.") + log.info("\nDataset build complete.") if __name__ == "__main__": diff --git a/ml/training/policy_network.py b/ml/training/policy_network.py index d337e1d..b84a7dd 100644 --- a/ml/training/policy_network.py +++ b/ml/training/policy_network.py @@ -16,6 +16,10 @@ The network is designed for: import os import sys from pathlib import Path +import logging + +log = logging.getLogger("commander_ai_lab.ml.training") + # Conditional torch import — graceful failure if not installed try: @@ -25,7 +29,7 @@ try: TORCH_AVAILABLE = True except ImportError: TORCH_AVAILABLE = False - print("[ML] PyTorch not installed. Install with: pip install torch") + log.warning("PyTorch not installed. Install with: pip install torch") import numpy as np @@ -204,7 +208,7 @@ def save_checkpoint( "dropout": TRAINING_CONFIG.dropout, }, }, path) - print(f"[ML] Checkpoint saved: {path}") + log.info(f"Checkpoint saved: {path}") def load_checkpoint(path: str, device: str = "cpu"): diff --git a/ml/training/trainer.py b/ml/training/trainer.py index c9e0bf0..9de19c4 100644 --- a/ml/training/trainer.py +++ b/ml/training/trainer.py @@ -49,8 +49,7 @@ from ml.training.policy_network import ( PolicyNetwork, save_checkpoint, load_checkpoint, ) -logging.basicConfig(level=logging.INFO, format="[%(name)s] %(message)s") -logger = logging.getLogger("ml.trainer") +logger = logging.getLogger("commander_ai_lab.ml.training") # ══════════════════════════════════════════════════════════ @@ -502,40 +501,40 @@ def evaluate_model( def print_evaluation(results: Dict): """Pretty-print evaluation results.""" - print() - print("=" * 65) - print(" Test Set Evaluation") - print("=" * 65) - print(f" Overall Accuracy: {results['overall_accuracy']:.1%}") - print(f" Total Samples: {results['total_samples']:,}") - print() - print(f" {'Action':<20} {'Support':>8} {'Prec':>7} {'Recall':>7} {'F1':>7}") - print(" " + "-" * 55) + logger.info("") + logger.info("=" * 65) + logger.info(" Test Set Evaluation") + logger.info("=" * 65) + logger.info(f" Overall Accuracy: {results['overall_accuracy']:.1%}") + logger.info(f" Total Samples: {results['total_samples']:,}") + logger.info("") + logger.info(f" {'Action':<20} {'Support':>8} {'Prec':>7} {'Recall':>7} {'F1':>7}") + logger.info(" " + "-" * 55) for action_name, m in results["per_class"].items(): - print( + logger.info( f" {action_name:<20} {m['support']:>8} " f"{m['precision']:>7.3f} {m['recall']:>7.3f} {m['f1']:>7.3f}" ) - print(" " + "-" * 55) + logger.info(" " + "-" * 55) # Confusion matrix - print() - print(" Confusion Matrix (rows=true, cols=predicted):") + logger.info("") + logger.info(" Confusion Matrix (rows=true, cols=predicted):") header = " " + " " * 18 for c in range(NUM_ACTIONS): short_name = IDX_TO_ACTION[c].value[:6] header += f" {short_name:>6}" - print(header) + logger.info(header) for r in range(NUM_ACTIONS): row_name = IDX_TO_ACTION[r].value[:16] row_str = f" {row_name:<18}" for c in range(NUM_ACTIONS): row_str += f" {results['confusion_matrix'][r][c]:>6}" - print(row_str) - print() + logger.info(row_str) + logger.info("") # ══════════════════════════════════════════════════════════ @@ -605,8 +604,8 @@ def main(): args = parser.parse_args() if not TORCH_AVAILABLE: - print("PyTorch not installed. Install with:") - print(" pip install torch torchvision --index-url https://download.pytorch.org/whl/cu121") + logger.info("PyTorch not installed. Install with:") + logger.info(" pip install torch torchvision --index-url https://download.pytorch.org/whl/cu121") sys.exit(1) device = args.device or get_best_device() @@ -621,13 +620,13 @@ def main(): if args.eval_only: # Evaluation only if not os.path.exists(test_path): - print(f"Test data not found: {test_path}") - print("Run: python -m ml.scripts.ml_cli build") + logger.info(f"Test data not found: {test_path}") + logger.info("Run: python -m ml.scripts.ml_cli build") sys.exit(1) ckpt_path = args.checkpoint or os.path.join(ckpt_dir, "best_policy.pt") if not os.path.exists(ckpt_path): - print(f"Checkpoint not found: {ckpt_path}") + logger.info(f"Checkpoint not found: {ckpt_path}") sys.exit(1) test_states, test_labels = load_npz_split(test_path) @@ -641,15 +640,15 @@ def main(): eval_path = os.path.join(ckpt_dir, "eval_results.json") with open(eval_path, "w") as f: json.dump(results, f, indent=2) - print(f" Results saved: {eval_path}") + logger.info(f" Results saved: {eval_path}") return # Training mode for path, label in [(train_path, "train"), (val_path, "val")]: if not os.path.exists(path): - print(f"{label} data not found: {path}") - print("Build the dataset first:") - print(" python -m ml.scripts.ml_cli build --results-dir results/") + logger.info(f"{label} data not found: {path}") + logger.info("Build the dataset first:") + logger.info(" python -m ml.scripts.ml_cli build --results-dir results/") sys.exit(1) train_states, train_labels = load_npz_split(train_path) diff --git a/overnight-run.py b/overnight-run.py index d6dc7d4..8117d5d 100644 --- a/overnight-run.py +++ b/overnight-run.py @@ -22,11 +22,15 @@ Configuration: import argparse import json +import logging +import logging.handlers +import os import sys import time import urllib.request import urllib.error from datetime import datetime, timedelta +from pathlib import Path # ── Default Config ────────────────────────────────────────────── @@ -51,10 +55,48 @@ DEFAULT_CONFIG = { } -def log(msg): - ts = datetime.now().strftime("%H:%M:%S") - print(f"[{ts}] {msg}") - sys.stdout.flush() +# ── Logging ────────────────────────────────────────────────── +_LOG_DIR = Path(os.environ.get("CAL_LOG_DIR", "logs")) + + +def setup_overnight_logging() -> logging.Logger: + """Configure logging for the overnight runner. + + Outputs to both console and a rotating log file so that + unattended runs always have a persistent record. + """ + _LOG_DIR.mkdir(parents=True, exist_ok=True) + + logger = logging.getLogger("commander_ai_lab.overnight") + logger.setLevel(logging.INFO) + + if logger.handlers: + return logger + + fmt = logging.Formatter( + "%(asctime)s %(levelname)-5s [%(name)s] %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + + console = logging.StreamHandler(sys.stdout) + console.setLevel(logging.INFO) + console.setFormatter(fmt) + logger.addHandler(console) + + file_handler = logging.handlers.RotatingFileHandler( + _LOG_DIR / "overnight-run.log", + maxBytes=10 * 1024 * 1024, # 10 MB + backupCount=5, + encoding="utf-8", + ) + file_handler.setLevel(logging.INFO) + file_handler.setFormatter(fmt) + logger.addHandler(file_handler) + + return logger + + +log = setup_overnight_logging() def api_get(base_url, path): @@ -129,8 +171,8 @@ def wait_for_batch(base_url, batch_id, engine="deepseek", deadline=None): while True: # Hard deadline check — stop waiting if we've run out of time if deadline and time.time() >= deadline: - log(f" Time limit reached while batch {batch_id} was running.") - log(f" The batch will continue on the server but we're moving on.") + log.info(f" Time limit reached while batch {batch_id} was running.") + log.info(f" The batch will continue on the server but we're moving on.") return {"completed": 0, "timed_out": True} try: @@ -144,12 +186,12 @@ def wait_for_batch(base_url, batch_id, engine="deepseek", deadline=None): elapsed = status.get("elapsedMs", 0) if error: - log(f" Batch {batch_id} ERROR: {error}") + log.error(f" Batch {batch_id} ERROR: {error}") return None if not running and completed > 0: elapsed_s = elapsed / 1000 if elapsed else 0 - log(f" Batch {batch_id} complete: {completed} games in {elapsed_s:.0f}s") + log.info(f" Batch {batch_id} complete: {completed} games in {elapsed_s:.0f}s") try: result = api_get(base_url, f"/api/lab/result?batchId={batch_id}") return result @@ -160,15 +202,15 @@ def wait_for_batch(base_url, batch_id, engine="deepseek", deadline=None): if not running and completed == 0: stall_checks += 1 if stall_checks > 20: # 5 min with no progress - log(f" Batch {batch_id} never started. Aborting.") + log.info(f" Batch {batch_id} never started. Aborting.") return None # Progress log with ETA if deadline: mins_left = (deadline - time.time()) / 60 - log(f" Progress: {completed}/{total} games ({elapsed / 1000:.0f}s) — {mins_left:.0f}min left in run") + log.info(f" Progress: {completed}/{total} games ({elapsed / 1000:.0f}s) — {mins_left:.0f}min left in run") else: - log(f" Progress: {completed}/{total} games ({elapsed / 1000:.0f}s)") + log.info(f" Progress: {completed}/{total} games ({elapsed / 1000:.0f}s)") # Track stall if completed == last_completed: @@ -180,9 +222,9 @@ def wait_for_batch(base_url, batch_id, engine="deepseek", deadline=None): except Exception as e: consecutive_errors += 1 if consecutive_errors > 10: - log(f" Lost connection to server after 10 retries. Aborting batch.") + log.info(f" Lost connection to server after 10 retries. Aborting batch.") return None - log(f" Connection error (retry {consecutive_errors}/10): {e}") + log.info(f" Connection error (retry {consecutive_errors}/10): {e}") time.sleep(poll_interval) @@ -214,26 +256,26 @@ def wait_for_training(base_url): error = status.get("error") if error: - log(f" Training ERROR: {error}") + log.error(f" Training ERROR: {error}") return False if not running and phase in ("done", "idle") and epoch > 0: result = status.get("result", {}) - log(f" Training complete!") + log.info(f" Training complete!") if result: - log(f" Final accuracy: {result.get('best_val_accuracy', '?')}") - log(f" Model saved: {result.get('model_path', '?')}") + log.info(f" Final accuracy: {result.get('best_val_accuracy', '?')}") + log.info(f" Model saved: {result.get('model_path', '?')}") return True if phase == "training" and total > 0: metrics = status.get("metrics", {}) val_acc = metrics.get("val_accuracy", "?") if metrics else "?" - log(f" Training: epoch {epoch}/{total} — {message} (val_acc: {val_acc})") + log.info(f" Training: epoch {epoch}/{total} — {message} (val_acc: {val_acc})") else: - log(f" [{phase}] {message}") + log.info(f" [{phase}] {message}") except Exception as e: - log(f" Connection error: {e}") + log.info(f" Connection error: {e}") time.sleep(poll_interval) @@ -253,46 +295,46 @@ def run_overnight(cfg): """Main overnight pipeline.""" base_url = cfg["lab_url"] - log("=" * 60) - log(" Commander AI Lab — Overnight AFK Runner") - log("=" * 60) + log.info("=" * 60) + log.info(" Commander AI Lab — Overnight AFK Runner") + log.info("=" * 60) # ── Verify server ──────────────────────────────────────── - log("Checking lab server...") + log.info("Checking lab server...") if not check_server(base_url): - log(f"ERROR: Cannot reach lab server at {base_url}") - log("Start the lab first: start-lab.bat") + log.error(f"ERROR: Cannot reach lab server at {base_url}") + log.info("Start the lab first: start-lab.bat") return False - log(f"Server OK at {base_url}") + log.info(f"Server OK at {base_url}") # ── Get decks ───────────────────────────────────────────── available_decks = get_available_decks(base_url) - log(f"Found {len(available_decks)} decks: {', '.join(available_decks[:5])}{'...' if len(available_decks) > 5 else ''}") + log.info(f"Found {len(available_decks)} decks: {', '.join(available_decks[:5])}{'...' if len(available_decks) > 5 else ''}") engine = cfg["engine"] if engine == "deepseek": decks = cfg["ds_decks"] if cfg["ds_decks"] else available_decks if not decks: - log("ERROR: No decks available. Create decks in the Deck Builder first.") + log.error("ERROR: No decks available. Create decks in the Deck Builder first.") return False - log(f"Using DeepSeek engine with {len(decks)} deck(s)") + log.info(f"Using DeepSeek engine with {len(decks)} deck(s)") else: decks = cfg["java_decks"] if len(decks) != 3: - log("ERROR: Java engine requires exactly 3 deck names.") - log("Set java_decks in the config or use --decks deck1 deck2 deck3") + log.error("ERROR: Java engine requires exactly 3 deck names.") + log.info("Set java_decks in the config or use --decks deck1 deck2 deck3") return False - log(f"Using Java/Forge engine with decks: {decks}") + log.info(f"Using Java/Forge engine with decks: {decks}") # ── ML logging ──────────────────────────────────────────── - log("Enabling ML logging...") + log.info("Enabling ML logging...") try: api_post(base_url, "/api/ml/toggle?enable=true", {}) - log("ML logging enabled") + log.info("ML logging enabled") except Exception as e: - log(f"WARNING: Could not enable ML logging: {e}") - log("(DeepSeek batches always log ML data regardless)") + log.warning(f"WARNING: Could not enable ML logging: {e}") + log.info("(DeepSeek batches always log ML data regardless)") # Try alternate form try: api_get(base_url, "/api/ml/toggle?enable=true") @@ -301,7 +343,7 @@ def run_overnight(cfg): # ── Initial data stats ──────────────────────────────────── decisions_before, files_before = get_ml_data_summary(base_url) - log(f"Current ML data: {decisions_before} decisions in {files_before} files") + log.info(f"Current ML data: {decisions_before} decisions in {files_before} files") # ── Run batches ─────────────────────────────────────────── games_per_batch = cfg["games_per_batch"] @@ -315,32 +357,32 @@ def run_overnight(cfg): total_games = 0 total_decisions = 0 - log("") - log(f"Starting batch loop:") + log.info("") + log.info(f"Starting batch loop:") if num_batches > 0: - log(f" Mode: {num_batches} batches × {games_per_batch} games") + log.info(f" Mode: {num_batches} batches × {games_per_batch} games") else: - log(f" Mode: Run for {cfg['time_limit_hours']}h, {games_per_batch} games/batch") - log(f" Engine: {engine}") - log(f" Auto-train after: {'Yes' if cfg['auto_train'] else 'No'}") - log("") + log.info(f" Mode: Run for {cfg['time_limit_hours']}h, {games_per_batch} games/batch") + log.info(f" Engine: {engine}") + log.info(f" Auto-train after: {'Yes' if cfg['auto_train'] else 'No'}") + log.info("") while True: # Check stopping conditions if num_batches > 0 and batch_num >= num_batches: - log(f"Reached target of {num_batches} batches. Stopping.") + log.info(f"Reached target of {num_batches} batches. Stopping.") break elapsed = time.time() - start_time remaining = deadline - time.time() if remaining < 120: # need at least 2 min for a batch - log(f"Time limit approaching ({remaining:.0f}s left). Stopping sim loop.") + log.info(f"Time limit approaching ({remaining:.0f}s left). Stopping sim loop.") break batch_num += 1 elapsed_str = str(timedelta(seconds=int(elapsed))) remaining_str = str(timedelta(seconds=int(remaining))) - log(f"── Batch {batch_num} ── (elapsed: {elapsed_str}, remaining: {remaining_str})") + log.info(f"── Batch {batch_num} ── (elapsed: {elapsed_str}, remaining: {remaining_str})") try: if engine == "deepseek": @@ -352,12 +394,12 @@ def run_overnight(cfg): ) if not batch_id: - log(" ERROR: Failed to start batch (no batchId returned)") - log(" Waiting 60s before retry...") + log.error(" ERROR: Failed to start batch (no batchId returned)") + log.info(" Waiting 60s before retry...") time.sleep(60) continue - log(f" Started batch {batch_id}") + log.info(f" Started batch {batch_id}") result = wait_for_batch(base_url, batch_id, engine, deadline=deadline) if result: @@ -366,19 +408,19 @@ def run_overnight(cfg): for deck in result.get("decks", []): wr = deck.get("winRate", "?") name = deck.get("deckName", "?") - log(f" {name}: {wr}% WR") + log.info(f" {name}: {wr}% WR") else: - log(" Batch failed, continuing to next...") + log.info(" Batch failed, continuing to next...") except Exception as e: - log(f" ERROR starting batch: {e}") - log(" Waiting 60s before retry...") + log.error(f" ERROR starting batch: {e}") + log.info(" Waiting 60s before retry...") time.sleep(60) continue # Pause between batches if pause_sec > 0: - log(f" Cooling down {pause_sec}s...") + log.info(f" Cooling down {pause_sec}s...") time.sleep(pause_sec) # ── Summary ─────────────────────────────────────────────── @@ -387,26 +429,26 @@ def run_overnight(cfg): new_decisions = decisions_after - decisions_before new_files = files_after - files_before - log("") - log("=" * 60) - log(" BATCH SIMULATION COMPLETE") - log("=" * 60) - log(f" Batches run: {batch_num}") - log(f" Total games: ~{total_games}") - log(f" New ML decisions: {new_decisions} (in {new_files} new files)") - log(f" Total ML data: {decisions_after} decisions") - log(f" Elapsed time: {str(timedelta(seconds=int(total_elapsed)))}") - log("") + log.info("") + log.info("=" * 60) + log.info(" BATCH SIMULATION COMPLETE") + log.info("=" * 60) + log.info(f" Batches run: {batch_num}") + log.info(f" Total games: ~{total_games}") + log.info(f" New ML decisions: {new_decisions} (in {new_files} new files)") + log.info(f" Total ML data: {decisions_after} decisions") + log.info(f" Elapsed time: {str(timedelta(seconds=int(total_elapsed)))}") + log.info("") # ── Auto-train ──────────────────────────────────────────── if cfg["auto_train"]: if decisions_after < 100: - log("Skipping training — too few decisions (need at least 100)") + log.info("Skipping training — too few decisions (need at least 100)") return True - log("Starting ML training pipeline...") - log(f" Epochs: {cfg['train_epochs']}, LR: {cfg['train_lr']}, " - f"Batch: {cfg['train_batch_size']}, Patience: {cfg['train_patience']}") + log.info("Starting ML training pipeline...") + log.info(f" Epochs: {cfg['train_epochs']}, LR: {cfg['train_lr']}, " + f"Batch: {cfg['train_batch_size']}, Patience: {cfg['train_patience']}") try: start_training( @@ -416,21 +458,21 @@ def run_overnight(cfg): batch_size=cfg["train_batch_size"], patience=cfg["train_patience"], ) - log("Training started, monitoring progress...") + log.info("Training started, monitoring progress...") success = wait_for_training(base_url) if success: - log("") - log("=" * 60) - log(" TRAINING COMPLETE — model updated!") - log("=" * 60) + log.info("") + log.info("=" * 60) + log.info(" TRAINING COMPLETE — model updated!") + log.info("=" * 60) else: - log("Training finished with errors. Check the Training tab for details.") + log.info("Training finished with errors. Check the Training tab for details.") except Exception as e: - log(f"ERROR starting training: {e}") + log.error(f"ERROR starting training: {e}") return False - log("") - log("Overnight run finished. You can close this window.") + log.info("") + log.info("Overnight run finished. You can close this window.") return True diff --git a/scanner/pipeline.py b/scanner/pipeline.py index a16eed1..dc79bc1 100644 --- a/scanner/pipeline.py +++ b/scanner/pipeline.py @@ -13,6 +13,10 @@ No local OCR or OpenCV needed — all recognition is done by the Ximilar cloud API using visual AI. """ from typing import Callable, Optional +import logging + +log = logging.getLogger("commander_ai_lab.scanner") + from .ximilar_client import identify_cards, XimilarResult @@ -160,7 +164,7 @@ def _ximilar_to_scan_result(xr: XimilarResult, try: scryfall_data = scryfall_lookup(xr.name) except Exception as e: - print(f" [SCAN] Scryfall lookup failed for '{xr.name}': {e}") + log.error(f" Scryfall lookup failed for '{xr.name}': {e}") if scryfall_data and scryfall_data.get("object") != "error": result.scryfall_id = scryfall_data.get("id", "") @@ -181,6 +185,6 @@ def _ximilar_to_scan_result(xr: XimilarResult, # Extract image from scryfall URL pattern # e.g., https://scryfall.com/card/m11/149/lightning-bolt result.image_uri = "" # Will be fetched by frontend via scryfall_id - print(f" [SCAN] No Scryfall match for '{xr.name}' — using Ximilar data only") + log.info(f" No Scryfall match for '{xr.name}' — using Ximilar data only") return result diff --git a/scanner/ximilar_client.py b/scanner/ximilar_client.py index 4d6dfcb..7ef0a87 100644 --- a/scanner/ximilar_client.py +++ b/scanner/ximilar_client.py @@ -13,6 +13,10 @@ import json from typing import Optional, List from urllib.request import Request, urlopen from urllib.error import URLError, HTTPError +import logging + +log = logging.getLogger("commander_ai_lab.scanner.ximilar") + XIMILAR_ENDPOINT = "https://api.ximilar.com/collectibles/v2/tcg_id" @@ -82,7 +86,7 @@ def identify_cards(image_bytes: bytes, api_key: str, ) try: - print(f" [XIMILAR] Sending {len(image_bytes):,} bytes to API (analyze_all={analyze_all})") + log.info(f" Sending {len(image_bytes):,} bytes to API (analyze_all={analyze_all})") with urlopen(req, timeout=60) as resp: resp_data = json.loads(resp.read().decode("utf-8")) except HTTPError as e: @@ -168,12 +172,12 @@ def _parse_response(resp_data: dict) -> List[XimilarResult]: if not results: results.append(XimilarResult(error="Ximilar could not identify any cards")) - print(f" [XIMILAR] Identified {len(results)} card(s)") + log.info(f" Identified {len(results)} card(s)") for r in results: if r.name: - print(f" [XIMILAR] - {r.name} ({r.set_code}) conf={r.confidence:.2f}") + log.info(f" - {r.name} ({r.set_code}) conf={r.confidence:.2f}") elif r.error: - print(f" [XIMILAR] - ERROR: {r.error}") + log.error(f" - ERROR: {r.error}") return results diff --git a/src/commander_ai_lab/lab/experiments.py b/src/commander_ai_lab/lab/experiments.py index 464a9ce..33d7e4d 100644 --- a/src/commander_ai_lab/lab/experiments.py +++ b/src/commander_ai_lab/lab/experiments.py @@ -13,6 +13,10 @@ Functions: """ from __future__ import annotations +import logging + +log = logging.getLogger("commander_ai_lab.lab.experiments") + import time from typing import Optional @@ -238,27 +242,27 @@ def _generate_training_deck() -> list[Card]: def _print_stats(stats: dict) -> None: """Pretty-print simulation stats.""" - print() - print("=" * 60) - print(f" SIMULATION RESULTS: {stats['deck_name']} vs {stats['opponent_name']}") - print("=" * 60) - print(f" Games played: {stats['total_games']}") - print(f" Wins / Losses: {stats['wins']} / {stats['losses']}") - print(f" Win Rate: {stats['win_rate']}%") - print(f" Avg Turns: {stats['avg_turns']}") - print("-" * 60) - print(f" Avg Damage Dealt: {stats['avg_damage_dealt']}") - print(f" Avg Damage Received: {stats['avg_damage_received']}") - print(f" Avg Spells Cast: {stats['avg_spells_cast']}") - print(f" Avg Creatures Played: {stats['avg_creatures_played']}") - print(f" Avg Removal Used: {stats['avg_removal_used']}") - print(f" Avg Ramp Played: {stats['avg_ramp_played']}") - print(f" Avg Cards Drawn: {stats['avg_cards_drawn']}") - print(f" Avg Max Board Size: {stats['avg_max_board_size']}") - print("-" * 60) - print(f" Elapsed: {stats['elapsed_seconds']}s") - print("=" * 60) - print() + log.info("") + log.info("=" * 60) + log.info(f" SIMULATION RESULTS: {stats['deck_name']} vs {stats['opponent_name']}") + log.info("=" * 60) + log.info(f" Games played: {stats['total_games']}") + log.info(f" Wins / Losses: {stats['wins']} / {stats['losses']}") + log.info(f" Win Rate: {stats['win_rate']}%") + log.info(f" Avg Turns: {stats['avg_turns']}") + log.info("-" * 60) + log.info(f" Avg Damage Dealt: {stats['avg_damage_dealt']}") + log.info(f" Avg Damage Received: {stats['avg_damage_received']}") + log.info(f" Avg Spells Cast: {stats['avg_spells_cast']}") + log.info(f" Avg Creatures Played: {stats['avg_creatures_played']}") + log.info(f" Avg Removal Used: {stats['avg_removal_used']}") + log.info(f" Avg Ramp Played: {stats['avg_ramp_played']}") + log.info(f" Avg Cards Drawn: {stats['avg_cards_drawn']}") + log.info(f" Avg Max Board Size: {stats['avg_max_board_size']}") + log.info("-" * 60) + log.info(f" Elapsed: {stats['elapsed_seconds']}s") + log.info("=" * 60) + log.info("") def _cli_main() -> None: @@ -294,15 +298,15 @@ def _run_smoke_test() -> None: "Harmonize", "Read the Bones", "Phyrexian Arena", ] - print("Building test deck (Korvold Aristocrats)...") + log.info("Building test deck (Korvold Aristocrats)...") test_deck = build_deck(test_decklist) - print(f" Deck size: {len(test_deck)} cards") + log.info(f" Deck size: {len(test_deck)} cards") - print("\nRunning single game...") + log.info("\nRunning single game...") single = run_single_game(test_deck, name_a="Korvold") - print(f" Winner: {single['winner_name']} in {single['turns']} turns") + log.info(f" Winner: {single['winner_name']} in {single['turns']} turns") - print("\nRunning Monte Carlo simulation (10 games)...") + log.info("\nRunning Monte Carlo simulation (10 games)...") stats = run_simulation(test_deck, num_games=10, name_a="Korvold") _print_stats(stats)