Improve observability: add structured logging to tournament, analyze, and verify_parity

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"]

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:

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
 
 

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)

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."
 

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,