From a61086e78febb81ef64f101327756dc65c3fcb6f Mon Sep 17 00:00:00 2001 From: Luke Inglis Date: Wed, 19 Aug 2026 15:15:10 -0400 Subject: [PATCH] Add structured logging to tournament, analyze, verify_parity, eval, and lab_forecaster Closes #157 Co-Authored-By: Claude Opus 4.6 (1M context) --- analyze.py | 8 ++++++++ eval.py | 8 ++++++++ lab_forecaster.py | 3 +++ tests/test_logging_config.py | 5 ++++- tournament.py | 9 +++++++++ verify_parity.py | 16 ++++++++++++++++ 6 files changed, 48 insertions(+), 1 deletion(-) diff --git a/analyze.py b/analyze.py index ae13a3a..aacb916 100644 --- a/analyze.py +++ b/analyze.py @@ -35,6 +35,7 @@ def analyze_by_source( forecasts: dict[str, float], resolved: list[ResolvedQuestion], ) -> dict[str, dict[str, object]]: + logger.info("analyze_by_source_start", n_forecasts=len(forecasts), n_resolved=len(resolved)) by_source: dict[str, list[tuple[float, int]]] = {} for q in resolved: f = _lookup_forecast(forecasts, q.id) @@ -56,6 +57,7 @@ def analyze_calibration( resolved: list[ResolvedQuestion], n_bins: int = 10, ) -> list[dict[str, object]]: + logger.info("analyze_calibration_start", n_resolved=len(resolved), n_bins=n_bins) pairs = [(_lookup_forecast(forecasts, q.id), q.outcome) for q in resolved] if not pairs: return [] @@ -139,6 +141,7 @@ def analyze_biases( forecasts: dict[str, float], resolved: list[ResolvedQuestion], ) -> dict[str, object]: + logger.info("analyze_biases_start", n_forecasts=len(forecasts), n_resolved=len(resolved)) pairs = [(_lookup_forecast(forecasts, q.id), q.outcome) for q in resolved] if not pairs: return {"mean_forecast": 0.0, "mean_outcome": 0.0, "bias": 0.0, "low_bin": {}, "high_bin": {}} @@ -177,6 +180,7 @@ def analyze_decomposition( n_bins: int = 10, ) -> dict[str, dict[str, float]]: """Run Murphy decomposition and calibration metrics on forecast/outcome pairs.""" + logger.info("analyze_decomposition_start", n_resolved=len(resolved), n_bins=n_bins) pairs = [(_lookup_forecast(forecasts, q.id), q.outcome) for q in resolved] if not pairs: return {"murphy": {}, "calibration": {}} @@ -241,6 +245,7 @@ def print_analysis(analysis: dict[str, Any]) -> None: def save_analysis(analysis: dict[str, Any], path: str | Path) -> None: + logger.info("save_analysis", path=str(path)) p = Path(path) p.parent.mkdir(parents=True, exist_ok=True) p.write_text(json.dumps(analysis, indent=2)) @@ -252,6 +257,7 @@ def analyze_worst_questions( top_n: int = 50, ) -> list[dict[str, object]]: """Find the N questions with highest individual Brier scores.""" + logger.info("analyze_worst_questions_start", n_resolved=len(resolved), top_n=top_n) errors: list[dict[str, object]] = [] for q in resolved: f = forecasts.get(q.id, 0.5) @@ -281,6 +287,7 @@ def analyze_by_horizon( resolved: list[ResolvedQuestion], ) -> dict[str, dict[str, object]]: """Break down dataset question performance by resolution horizon.""" + logger.info("analyze_by_horizon_start", n_resolved=len(resolved)) horizon_pattern = re.compile(r"^(.+)_(\d{4}-\d{2}-\d{2})$") horizon_groups: dict[str, list[tuple[float, int]]] = {} @@ -310,6 +317,7 @@ def compare_paired( result_b_path: str | Path, ) -> dict[str, object]: """Paired comparison of two runs on shared questions.""" + logger.info("compare_paired_start", path_a=str(result_a_path), path_b=str(result_b_path)) data_a = json.loads(Path(result_a_path).read_text()) data_b = json.loads(Path(result_b_path).read_text()) forecasts_a: dict[str, float] = data_a["forecasts"] diff --git a/eval.py b/eval.py index 975d99e..05119b7 100644 --- a/eval.py +++ b/eval.py @@ -177,6 +177,8 @@ def save_result( costs: dict[str, float] | None = None, ) -> Path: """Save run result to results/{prefix}{timestamp}_{model_slug}[_{round}].json.""" + logger.info("save_result_start", model_slug=model_slug, n_forecasts=len(forecasts), + round_name=round_name) timestamp = datetime.datetime.now(timezone.utc).strftime("%Y%m%dT%H%M%SZ") metadata: dict[str, object] = { "n_questions": result.n_dataset + result.n_market, @@ -234,6 +236,7 @@ def load_previous_results(results_dir: Path | None = None) -> list[dict[str, obj if results_dir is None: results_dir = RESULTS_DIR if not results_dir.exists(): + logger.info("load_previous_results_no_dir", path=str(results_dir)) return [] results: list[dict[str, object]] = [] for p in sorted(results_dir.glob("*.json")): @@ -242,6 +245,7 @@ def load_previous_results(results_dir: Path | None = None) -> list[dict[str, obj results.append(data) except (json.JSONDecodeError, KeyError): continue + logger.info("load_previous_results", n_results=len(results), path=str(results_dir)) return results @@ -250,6 +254,7 @@ def split_held_out( n_held_out: int = 2, ) -> tuple[list[QuestionSet], list[QuestionSet]]: """Split question sets into iteration and held-out sets by forecast_due_date.""" + logger.info("split_held_out", n_question_sets=len(question_sets), n_held_out=n_held_out) if n_held_out < 0: raise ValueError(f"n_held_out must be non-negative, got {n_held_out}") if n_held_out >= len(question_sets): @@ -589,6 +594,7 @@ def _normalize_round_name(name: str) -> str: def list_rounds() -> list[tuple[str, int]]: + logger.info("list_rounds_start") filenames = list_question_set_files() rounds: list[tuple[str, int]] = [] for fname in sorted(filenames, reverse=True): @@ -605,6 +611,8 @@ def print_leaderboard_comparison( user_index: float, leaderboard_name: str = "baseline", ) -> None: + logger.info("print_leaderboard_comparison_start", user_index=round(user_index, 1), + leaderboard_name=leaderboard_name) try: rows = fetch_leaderboard(leaderboard_name) except Exception: diff --git a/lab_forecaster.py b/lab_forecaster.py index 66e5abb..6151cb7 100644 --- a/lab_forecaster.py +++ b/lab_forecaster.py @@ -303,6 +303,7 @@ def _parse_probability(text: str) -> float: match = re.search(r"(0?\.\d+|1\.0{0,})", text) if match: return float(match.group(1)) + logger.warning("parse_probability_failed", text_preview=text[:100]) raise ValueError(f"Could not parse probability from response: {text[:100]}") @@ -368,6 +369,7 @@ def _decimal_extract(text: str, n_expected: int) -> list[float] | None: def _extract_probabilities(text: str, n_expected: int) -> list[float] | None: + logger.info("extract_probabilities_start", n_expected=n_expected, text_len=len(text)) answer_block = _extract_answer_block(text) if answer_block: probs = _parse_probs_from_text(answer_block, n_expected) @@ -386,6 +388,7 @@ def _extract_probabilities(text: str, n_expected: int) -> list[float] | None: if probs: return probs + logger.warning("extract_probabilities_failed", n_expected=n_expected, text_preview=text[:100]) return None diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py index e999a97..0eb30c3 100644 --- a/tests/test_logging_config.py +++ b/tests/test_logging_config.py @@ -149,7 +149,10 @@ def teardown_method(self) -> None: def test_multiple_loggers(self) -> None: configure_logging() - for name in ["eval", "score", "fetch_data", "lab_forecaster", "cutoff", "dummy_forecaster"]: + for name in [ + "eval", "score", "fetch_data", "lab_forecaster", "cutoff", + "dummy_forecaster", "tournament", "analyze", "verify_parity", + ]: log = get_logger(name) log.info("smoke_test", module=name) log.debug("smoke_debug", module=name) diff --git a/tournament.py b/tournament.py index 7321071..63be225 100644 --- a/tournament.py +++ b/tournament.py @@ -12,8 +12,10 @@ from pathlib import Path from typing import Any +from logging_config import get_logger from score import brier_score, brier_index +logger = get_logger("tournament") SMALL_N_THRESHOLD = 100 @@ -33,6 +35,7 @@ class ModelResult: def load_tournament_results(results_dir: str | Path = "results") -> list[ModelResult]: p = Path(results_dir) if not p.exists(): + logger.info("load_tournament_results_no_dir", path=str(p)) return [] results: list[ModelResult] = [] for f in sorted(p.glob("*.json")): @@ -52,6 +55,7 @@ def load_tournament_results(results_dir: str | Path = "results") -> list[ModelRe )) except (json.JSONDecodeError, KeyError): continue + logger.info("load_tournament_results", n_results=len(results), path=str(p)) return results @@ -81,6 +85,7 @@ def model_source_matrix( n_bootstrap: int = 1000, seed: int = 42, ) -> dict[str, dict[str, CellStats]]: + logger.info("model_source_matrix_start", n_models=len(results), n_bootstrap=n_bootstrap) matrix: dict[str, dict[str, CellStats]] = {} for result in results: by_source = _source_pairs(result) @@ -157,6 +162,7 @@ def paired_bootstrap_test( shared_ids = sorted(set(forecasts_a) & set(forecasts_b) & set(outcomes)) n = len(shared_ids) if n == 0: + logger.info("paired_bootstrap_test_no_shared") return BootstrapResult(0.0, 0.0, 0.0, 1.0, 0) diffs = [ @@ -205,6 +211,7 @@ def pairwise_comparison_table( n_bootstrap: int = 10000, seed: int = 42, ) -> list[PairwiseEntry]: + logger.info("pairwise_comparison_start", n_models=len(results), n_bootstrap=n_bootstrap) entries: list[PairwiseEntry] = [] for i, ra in enumerate(results): for rb in results[i + 1:]: @@ -247,6 +254,7 @@ class CostEntry: def cost_accuracy_summary(results: list[ModelResult]) -> list[CostEntry]: + logger.info("cost_accuracy_summary_start", n_models=len(results)) entries: list[CostEntry] = [] for r in results: if not r.costs: @@ -270,6 +278,7 @@ def cost_accuracy_summary(results: list[ModelResult]) -> list[CostEntry]: def tournament_report(results: list[ModelResult]) -> str: + logger.info("tournament_report_start", n_results=len(results)) if not results: return "No results to report." diff --git a/verify_parity.py b/verify_parity.py index 9545c2e..8dc92d8 100644 --- a/verify_parity.py +++ b/verify_parity.py @@ -17,6 +17,10 @@ import requests +from logging_config import get_logger + +logger = get_logger("verify_parity") + UPSTREAM_PROMPTS_URL = ( "https://raw.githubusercontent.com/forecastingresearch/" @@ -75,6 +79,7 @@ def _get_local_template(name: str) -> str | None: def check_prompt_templates(upstream_source: str | None) -> tuple[bool, str]: + logger.info("check_prompt_templates_start", has_upstream=upstream_source is not None) if upstream_source is None: return True, "[WARN] Could not fetch upstream prompts — skipping live comparison" @@ -106,6 +111,7 @@ def check_prompt_templates(upstream_source: str | None) -> tuple[bool, str]: def check_resolution_matching() -> tuple[bool, str]: + logger.info("check_resolution_matching_start") try: from fetch_data import ( fetch_all_resolutions, @@ -140,6 +146,7 @@ def check_resolution_matching() -> tuple[bool, str]: def check_scoring_formula(leaderboard: list[dict[str, str]] | None) -> tuple[bool, str]: + logger.info("check_scoring_formula_start", has_leaderboard=leaderboard is not None) from score import brier_index if brier_index(0.25) != 50.0: @@ -171,6 +178,7 @@ def check_scoring_formula(leaderboard: list[dict[str, str]] | None) -> tuple[boo def check_missing_forecast_default() -> tuple[bool, str]: + logger.info("check_missing_forecast_default_start") from fetch_data import ResolvedQuestion from score import score_forecasts, brier_score @@ -195,6 +203,7 @@ def check_missing_forecast_default() -> tuple[bool, str]: def check_multi_horizon_batching() -> tuple[bool, str]: + logger.info("check_multi_horizon_batching_start") try: from fetch_data import ( fetch_question_set, @@ -235,6 +244,7 @@ def check_multi_horizon_batching() -> tuple[bool, str]: def check_question_count(leaderboard: list[dict[str, str]] | None) -> tuple[bool, str]: + logger.info("check_question_count_start", has_leaderboard=leaderboard is not None) try: from fetch_data import fetch_question_set, list_question_set_files @@ -348,6 +358,7 @@ def _find_reference_model( def check_score_comparison(leaderboard: list[dict[str, str]] | None) -> tuple[bool, str]: + logger.info("check_score_comparison_start") result = _load_latest_result() if result is None: return True, "[SKIP] No results found — run eval first" @@ -379,6 +390,7 @@ def check_score_comparison(leaderboard: list[dict[str, str]] | None) -> tuple[bo def check_per_source_breakdown(leaderboard: list[dict[str, str]] | None) -> tuple[bool, str]: + logger.info("check_per_source_breakdown_start") result = _load_latest_result() if result is None: return True, "[SKIP] No results found — run eval first" @@ -439,6 +451,7 @@ def check_per_source_breakdown(leaderboard: list[dict[str, str]] | None) -> tupl def check_dummy_score() -> tuple[bool, str]: """Dummy forecaster (always 0.5) must score overall_index == 50.0 ± 0.01.""" + logger.info("check_dummy_score_start") from dummy_forecaster import forecast as dummy_forecast from fetch_data import ( Question, @@ -509,6 +522,7 @@ def _fetch_all_resolutions_as_lists() -> dict[str, list[Any]]: def check_resolution_outcome_diversity() -> tuple[bool, str]: """Resolution entries with the same ID but different dates must have diverse outcomes.""" + logger.info("check_resolution_outcome_diversity_start") resolutions = _fetch_all_resolutions_as_lists() multi_entry_ids: dict[str, set[int | None]] = {} @@ -538,6 +552,7 @@ def check_resolution_outcome_diversity() -> tuple[bool, str]: def check_resolution_entry_preservation() -> tuple[bool, str]: """Total resolution entries must significantly exceed unique question IDs.""" + logger.info("check_resolution_entry_preservation_start") resolutions = _fetch_all_resolutions_as_lists() unique_ids = len(resolutions) @@ -565,6 +580,7 @@ def check_cross_round_filtering() -> tuple[bool, str]: so their effective dates include all resolution_dates from all questions in the round. Dataset questions still use only their own resolution_dates list. """ + logger.info("check_cross_round_filtering_start") from fetch_data import ( MARKET_SOURCES, fetch_all_question_sets,