fez5587/commander-ai-lab
1
0 Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

refactor: adopt Python logging module with named loggers

Browse Source 
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)
This commit is contained in:
KoalaTrapLord committed 2026-03-13 18:09:52 +00:00
1 parent 8d2e6199db
commit a1fd290d5f
13 files changed
+390 -257
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

deck_sources/archidekt_adapter.py
+5 -1
View File
@@ -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 []
deck_sources/edhrec_adapter.py
+5 -1
View File
@@ -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 []
deck_sources/moxfield_adapter.py
+5 -1
View File
@@ -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 []
deck_sources/mtggoldfish_adapter.py
+5 -1
View File
@@ -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 []
lab_api.py
+160 -100
View File
@@ -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")
ml/actions/labeler.py
+5 -5
View File
@@ -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
ml/data/dataset_builder.py
+8 -8
View File
@@ -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__":
ml/training/policy_network.py
+6 -2
View File
@@ -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"):
ml/training/trainer.py
+26 -27
View File
@@ -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)
overnight-run.py
+121 -79
View File
@@ -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
scanner/pipeline.py
+6 -2
View File
@@ -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
scanner/ximilar_client.py
+8 -4
View File
@@ -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
src/commander_ai_lab/lab/experiments.py
+30 -26
View File
@@ -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)