diff --git a/analyze.py b/analyze.py index ae13a3a..15e13f9 100644 --- a/analyze.py +++ b/analyze.py @@ -27,7 +27,9 @@ def _lookup_forecast(forecasts: dict[str, float], question_id: str) -> float: base_id = question_id[:m.start()] prob = forecasts.get(base_id) if prob is not None: + logger.debug("lookup_fallback_base_id", question_id=question_id, base_id=base_id) return prob + logger.debug("lookup_missing_default", question_id=question_id) return 0.5 @@ -35,6 +37,7 @@ def analyze_by_source( forecasts: dict[str, float], resolved: list[ResolvedQuestion], ) -> dict[str, dict[str, object]]: + logger.info("analyze_by_source_start", n_resolved=len(resolved), n_forecasts=len(forecasts)) by_source: dict[str, list[tuple[float, int]]] = {} for q in resolved: f = _lookup_forecast(forecasts, q.id) @@ -48,6 +51,7 @@ def analyze_by_source( "index": brier_index(bs), "count": len(pairs), } + logger.info("analyze_by_source_complete", n_sources=len(results)) return results @@ -56,8 +60,10 @@ 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: + logger.warning("analyze_calibration_empty") return [] bin_width = 1.0 / n_bins @@ -139,8 +145,10 @@ def analyze_biases( forecasts: dict[str, float], resolved: list[ResolvedQuestion], ) -> dict[str, object]: + logger.info("analyze_biases_start", n_resolved=len(resolved)) pairs = [(_lookup_forecast(forecasts, q.id), q.outcome) for q in resolved] if not pairs: + logger.warning("analyze_biases_empty") return {"mean_forecast": 0.0, "mean_outcome": 0.0, "bias": 0.0, "low_bin": {}, "high_bin": {}} fs, os_ = zip(*pairs) @@ -177,8 +185,10 @@ 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: + logger.warning("analyze_decomposition_empty") return {"murphy": {}, "calibration": {}} murphy = murphy_decomposition(pairs, n_bins=n_bins) @@ -241,6 +251,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 +263,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 +293,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 +323,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", a=str(result_a_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"] @@ -585,6 +599,7 @@ def compare_to_superforecasters( def _load_result_forecasts(result_path: str | Path) -> tuple[dict[str, float], list[ResolvedQuestion]]: """Load forecasts from a result file and re-join with resolved questions.""" + logger.info("load_result_forecasts", path=str(result_path)) from fetch_data import Resolution, load_data, join_resolved_questions data = json.loads(Path(result_path).read_text()) diff --git a/check_staleness.py b/check_staleness.py index bd2fd66..c24770e 100644 --- a/check_staleness.py +++ b/check_staleness.py @@ -3,12 +3,18 @@ import subprocess import sys +from logging_config import get_logger + +logger = get_logger("check_staleness") + def run(cmd: list[str], check: bool = True) -> subprocess.CompletedProcess[str]: + logger.debug("run_command", cmd=cmd) return subprocess.run(cmd, capture_output=True, text=True, check=check) def main() -> int: + logger.info("staleness_check_start") run(["git", "fetch", "origin", "main", "--quiet"]) result = run( diff --git a/cutoff.py b/cutoff.py index 287415d..9368926 100644 --- a/cutoff.py +++ b/cutoff.py @@ -22,6 +22,7 @@ def __init__(self, freeze_datetime: str, display_date: str | None = None) -> Non logger.info("cutoff_environment_created", cutoff_date=freeze_datetime, display_date=self.display_date) def frame_temporal_context(self, question: Question) -> str: + logger.debug("frame_temporal_context", question_id=question.id, display_date=self.display_date) return ( f"Today's Date: {self.display_date}. " "You should forecast based on information available as of this date." diff --git a/dashboard.py b/dashboard.py index 4421f96..20ee4af 100644 --- a/dashboard.py +++ b/dashboard.py @@ -31,8 +31,11 @@ calibration_metrics, ) from fetch_data import MARKET_SOURCES, ResolvedQuestion, fetch_leaderboard, load_data +from logging_config import get_logger from score import brier_index, brier_score +logger = get_logger("dashboard") + ResultData = dict[str, Any] @@ -76,7 +79,9 @@ def _cache_data(fn: _F) -> _F: @_cache_data def load_all_results() -> list[ResultData]: + logger.info("dashboard_load_all_results") if not RESULTS_DIR.exists(): + logger.warning("dashboard_results_dir_missing", path=str(RESULTS_DIR)) return [] results: list[ResultData] = [] for f in sorted(RESULTS_DIR.glob("*.json")): @@ -86,12 +91,15 @@ def load_all_results() -> list[ResultData]: data["_filename"] = f.name results.append(data) except (json.JSONDecodeError, KeyError): + logger.warning("dashboard_load_result_error", path=str(f)) continue + logger.info("dashboard_results_loaded", n_results=len(results)) return results @_cache_data def load_resolved_questions() -> list[dict[str, Any]]: + logger.info("dashboard_load_resolved_questions") _, resolved = load_data() return [ { @@ -106,10 +114,12 @@ def load_resolved_questions() -> list[dict[str, Any]]: @_cache_data def load_leaderboard(name: str) -> list[dict[str, str]]: + logger.info("dashboard_load_leaderboard", name=name) return list(fetch_leaderboard(name)) def _round_name_from_result(result: ResultData) -> str: + logger.debug("round_name_from_result") meta = result.get("metadata", {}) rnd = meta.get("round") if rnd: @@ -126,6 +136,7 @@ def _compute_aggregate_scoring( sources: dict[str, str], ) -> dict[str, Any]: """Compute scoring result from combined forecasts and outcomes.""" + logger.debug("compute_aggregate_scoring", n_forecasts=len(forecasts), n_outcomes=len(outcomes)) shared_ids = set(forecasts.keys()) & set(outcomes.keys()) if not shared_ids: return { @@ -174,6 +185,7 @@ def _mean_brier(pairs: list[tuple[float, int]]) -> float: def _group_results_into_runs(results: list[ResultData]) -> list[AggregateRun]: """Group result files by model_slug into aggregate runs.""" + logger.info("group_results_into_runs", n_results=len(results)) grouped: dict[str, list[ResultData]] = {} for r in results: slug = str(r["model_slug"]) @@ -214,6 +226,7 @@ def _group_results_into_runs(results: list[ResultData]) -> list[AggregateRun]: @_cache_data def group_results(results: list[ResultData]) -> list[dict[str, Any]]: """Cached wrapper that returns serializable dicts (Streamlit requirement).""" + logger.info("group_results", n_results=len(results)) runs = _group_results_into_runs(results) return [ { @@ -245,9 +258,11 @@ def _dict_to_aggregate(d: dict[str, Any]) -> AggregateRun: def _leaderboard_reference_from_live() -> dict[str, dict[str, float]] | None: """Pull top reference entries from the live baseline leaderboard.""" + logger.info("leaderboard_reference_from_live") try: rows = load_leaderboard("baseline") except Exception: + logger.warning("leaderboard_reference_fetch_failed", exc_info=True) return None ref: dict[str, dict[str, float]] = {} for row in rows: @@ -269,6 +284,7 @@ def _leaderboard_reference_from_live() -> dict[str, dict[str, float]] | None: def _model_matches_slug(leaderboard_model: str, model_slug: str) -> bool: """Check if a leaderboard model name approximately matches our model slug.""" + logger.debug("model_match_check", leaderboard_model=leaderboard_model, model_slug=model_slug) lb = leaderboard_model.lower().replace("-", "_").replace(" ", "_") slug = model_slug.lower().replace("-", "_").replace(" ", "_") lb_parts = lb.split("_") @@ -289,6 +305,7 @@ def _model_matches_slug(leaderboard_model: str, model_slug: str) -> bool: def _resolved_to_objects(resolved_dicts: list[dict[str, Any]]) -> list[ResolvedQuestion]: + logger.debug("resolved_to_objects", n_dicts=len(resolved_dicts)) return [ ResolvedQuestion( id=d["id"], @@ -321,6 +338,7 @@ def _build_source_brier_matrix( runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]], ) -> tuple[list[str], list[str], list[list[float | None]], list[list[int]]]: + logger.debug("build_source_brier_matrix", n_runs=len(runs)) resolved = _resolved_to_objects(resolved_dicts) all_sources: set[str] = set() run_source_scores: dict[str, dict[str, float]] = {} @@ -365,6 +383,7 @@ def _sort_sources_by_track(sources: list[str]) -> list[str]: def view_overview(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]]) -> None: + logger.info("view_overview", n_runs=len(runs)) st.header("Overview") if not runs: @@ -474,6 +493,7 @@ def view_overview(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]] def view_leaderboard(runs: list[AggregateRun]) -> None: + logger.info("view_leaderboard", n_runs=len(runs)) st.header("Official ForecastBench Leaderboard") lb_name = st.radio( @@ -559,6 +579,7 @@ def view_leaderboard(runs: list[AggregateRun]) -> None: def view_heatmap(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]]) -> None: + logger.info("view_heatmap", n_runs=len(runs)) st.header("Run × Source Heatmap") if not runs: @@ -594,6 +615,7 @@ def _view_heatmap_by_source( resolved_dicts: list[dict[str, Any]], show_index: bool, ) -> None: + logger.info("view_heatmap_by_source", n_runs=len(runs)) run_labels, sources, matrix, counts = _build_source_brier_matrix(runs, resolved_dicts) sources_sorted = _sort_sources_by_track(sources) @@ -723,6 +745,7 @@ def _view_heatmap_by_track( resolved_dicts: list[dict[str, Any]], show_index: bool, ) -> None: + logger.info("view_heatmap_by_track", n_runs=len(runs)) overall_brier_map: dict[str, float] = {} for agg_run in runs: overall_brier_map[agg_run.label] = agg_run.scoring_result.get("overall_brier", 1.0) @@ -808,6 +831,7 @@ def _view_heatmap_by_track( def view_failures(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]]) -> None: + logger.info("view_failures", n_runs=len(runs)) st.header("Failure Explorer") if not runs: @@ -1080,6 +1104,7 @@ def view_failures(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]] def view_calibration(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]]) -> None: + logger.info("view_calibration", n_runs=len(runs)) st.header("Calibration Curves") if not runs: @@ -1185,6 +1210,7 @@ def view_calibration(runs: list[AggregateRun], resolved_dicts: list[dict[str, An def view_question_browser( runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]] ) -> None: + logger.info("view_question_browser", n_runs=len(runs)) st.header("Question Browser") if not runs or not resolved_dicts: @@ -1268,6 +1294,7 @@ def view_question_browser( def view_compare(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]]) -> None: + logger.info("view_compare", n_runs=len(runs)) st.header("Compare Runs") if len(runs) < 2: @@ -1440,6 +1467,7 @@ def view_compare(runs: list[AggregateRun], resolved_dicts: list[dict[str, Any]]) def main() -> None: + logger.info("dashboard_main_start") if not _HAS_DASHBOARD_DEPS: print( "Dashboard requires streamlit, pandas and plotly.\n" @@ -1545,6 +1573,7 @@ def main() -> None: def view_about() -> None: + logger.info("view_about") st.header("About ForecastBench") st.markdown(""" diff --git a/eval.py b/eval.py index 975d99e..325e5a5 100644 --- a/eval.py +++ b/eval.py @@ -73,7 +73,10 @@ def _is_multi_horizon(q: Question) -> bool: if q.source.lower() in MARKET_SOURCES: return False rd = q.resolution_dates - return isinstance(rd, list) and len(rd) > 1 + result = isinstance(rd, list) and len(rd) > 1 + if result: + logger.debug("multi_horizon_detected", question_id=q.id, n_horizons=len(rd)) + return result class EvalResult(NamedTuple): @@ -85,7 +88,34 @@ class EvalResult(NamedTuple): def is_async_forecaster(forecaster: Forecaster) -> bool: - return inspect.iscoroutinefunction(forecaster) + result = inspect.iscoroutinefunction(forecaster) + logger.debug("forecaster_type", async_mode=result) + return result + + +_MARKET_ANCHOR_WEIGHT = 0.91 + + +def _apply_calibration( + forecasts: dict[str, float], + questions: list[Question], +) -> dict[str, float]: + logger.debug("apply_calibration_start", n_forecasts=len(forecasts), n_questions=len(questions)) + q_by_id: dict[str, Question] = {q.id: q for q in questions} + calibrated: dict[str, float] = {} + for key, prob in forecasts.items(): + base_id = key.rsplit("_", 1)[0] if "_" in key else key + q = q_by_id.get(base_id) or q_by_id.get(key) + + if q is not None: + is_market = q.source.lower() in MARKET_SOURCES + if is_market: + fv = getattr(q, "freeze_datetime_value", None) + if fv is not None and 0.0 <= fv <= 1.0: + prob = _MARKET_ANCHOR_WEIGHT * fv + (1.0 - _MARKET_ANCHOR_WEIGHT) * prob + + calibrated[key] = max(0.0, min(1.0, prob)) + return calibrated _PROVIDER_PREFIXES = ( @@ -102,6 +132,7 @@ def _forecaster_fingerprint(prompt_variant: str = "default") -> str: Over-invalidating costs a re-run. Under-invalidating silently scores stale forecasts against new code, which is unrecoverable in an experiment loop. """ + logger.debug("forecaster_fingerprint", prompt_variant=prompt_variant) parts = [ os.getenv("FORECAST_MODEL", "vertex_ai/claude-sonnet-4@20250514"), os.getenv("FORECAST_TEMPERATURE", ""), @@ -120,6 +151,7 @@ def _model_slug( run_label: str | None = None, prompt_variant: str = "default", ) -> str: + logger.debug("model_slug_build", agent=agent_name, label=run_label, variant=prompt_variant) raw = os.getenv("FORECAST_MODEL", "vertex_ai/claude-sonnet-4@20250514") for prefix in _PROVIDER_PREFIXES: if raw.startswith(prefix): @@ -149,8 +181,11 @@ def _read_cache(model_slug: str, question_id: str) -> float | None: return None try: data = json.loads(path.read_text()) - return float(data["probability"]) + prob = float(data["probability"]) + logger.debug("cache_hit", question_id=question_id, probability=prob) + return prob except (json.JSONDecodeError, KeyError, ValueError, TypeError): + logger.warning("cache_read_error", question_id=question_id, path=str(path)) return None @@ -162,6 +197,7 @@ def _write_cache(model_slug: str, question_id: str, probability: float) -> None: "model": model_slug, "question_id": question_id, })) + logger.debug("cache_write", question_id=question_id, probability=probability) def save_result( @@ -177,6 +213,7 @@ 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", 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 +271,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.debug("load_previous_results_no_dir", path=str(results_dir)) return [] results: list[dict[str, object]] = [] for p in sorted(results_dir.glob("*.json")): @@ -241,7 +279,9 @@ def load_previous_results(results_dir: Path | None = None) -> list[dict[str, obj data = json.loads(p.read_text()) results.append(data) except (json.JSONDecodeError, KeyError): + logger.warning("load_previous_result_error", path=str(p)) continue + logger.info("load_previous_results", n_loaded=len(results)) return results @@ -253,12 +293,14 @@ def split_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): + logger.info("split_held_out_all", n_total=len(question_sets), n_held_out=n_held_out) return [], list(question_sets) sorted_qs = sorted(question_sets, key=lambda qs: qs.forecast_due_date) split_point = len(sorted_qs) - n_held_out iteration_set = sorted_qs[:split_point] held_out_set = sorted_qs[split_point:] + logger.info("split_held_out", n_iteration=len(iteration_set), n_held_out=len(held_out_set)) return iteration_set, held_out_set @@ -358,6 +400,8 @@ async def run_eval( multi_forecaster=multi_forecaster, # type: ignore[arg-type] ) + forecasts = _apply_calibration(forecasts, questions) + has_composite = any( "_" in k and k != q_id for k in forecasts @@ -585,10 +629,12 @@ def _normalize_round_name(name: str) -> str: name = name.removesuffix(".json") if not name.endswith(("-llm", "-human")): name = name + "-llm" + logger.debug("normalize_round_name", result=name) return name def list_rounds() -> list[tuple[str, int]]: + logger.info("list_rounds") filenames = list_question_set_files() rounds: list[tuple[str, int]] = [] for fname in sorted(filenames, reverse=True): @@ -605,6 +651,7 @@ def print_leaderboard_comparison( user_index: float, leaderboard_name: str = "baseline", ) -> None: + logger.info("print_leaderboard_comparison", user_index=user_index, leaderboard=leaderboard_name) try: rows = fetch_leaderboard(leaderboard_name) except Exception: diff --git a/eval/score.py b/eval/score.py index cf2362c..60e4c67 100644 --- a/eval/score.py +++ b/eval/score.py @@ -166,6 +166,7 @@ def eval_observability() -> dict: skip = { "tests", "test", ".venv", "venv", "node_modules", "__pycache__", ".git", ".factory", "eval", "dist", "build", ".mypy_cache", + "archive", "gate", } log_pats = [ r"\blogger\.\w+\(", diff --git a/investigate.py b/investigate.py index e5d4198..3fd393b 100644 --- a/investigate.py +++ b/investigate.py @@ -14,6 +14,9 @@ from typing import Any from fetch_data import MARKET_SOURCES +from logging_config import get_logger + +logger = get_logger("investigate") RESULTS_DIR = Path("results") KNOWLEDGE_CUTOFF = "2025-03" @@ -23,19 +26,24 @@ def load_result(path: Path) -> dict[str, Any]: + logger.info("load_result", path=str(path)) data: dict[str, Any] = json.loads(path.read_text()) return data def load_all_results(results_dir: Path = RESULTS_DIR) -> list[dict[str, Any]]: + logger.info("load_all_results", results_dir=str(results_dir)) if not results_dir.exists(): + logger.warning("load_all_results_no_dir", path=str(results_dir)) return [] results = [] for p in sorted(results_dir.glob("*.json")): try: results.append(load_result(p)) except (json.JSONDecodeError, KeyError): + logger.warning("load_all_results_error", path=str(p)) continue + logger.info("load_all_results_complete", n_loaded=len(results)) return results @@ -62,6 +70,7 @@ def extract_date_suffix(key: str) -> str | None: def diagnose_id_mismatch(result: dict[str, Any]) -> dict[str, Any]: """Compare forecast keys against outcome keys to find multi-horizon mismatches.""" + logger.info("diagnose_id_mismatch_start") forecasts: dict[str, float] = result.get("forecasts", {}) outcomes: dict[str, int] = result.get("outcomes", {}) sources: dict[str, str] = result.get("sources", {}) @@ -131,11 +140,13 @@ def _guess_category(key: str, sources: dict[str, str]) -> str: for full_key, s in sources.items(): if full_key.startswith(base): return classify_source(s) + logger.debug("guess_category_fallback", key=key) return "dataset" def stratify_by_source(result: dict[str, Any]) -> dict[str, dict[str, Any]]: """Per-source statistics: counts, missing rates, Brier scores.""" + logger.debug("stratify_by_source_start") forecasts: dict[str, float] = result.get("forecasts", {}) outcomes: dict[str, int] = result.get("outcomes", {}) sources: dict[str, str] = result.get("sources", {}) @@ -196,12 +207,15 @@ def extract_round_date(result: dict[str, Any]) -> str | None: round_name = meta.get("round") if round_name: m = _DATE_RE.search(round_name) - return m.group(0) if m else round_name + date = m.group(0) if m else round_name + logger.debug("extract_round_date", round_name=round_name, date=date) + return date return None def per_round_breakdown(results: list[dict[str, Any]]) -> list[dict[str, Any]]: """Per-round statistics: counts, splits, scores, size category.""" + logger.info("per_round_breakdown_start", n_results=len(results)) rows: list[dict[str, Any]] = [] for result in results: round_date = extract_round_date(result) @@ -250,6 +264,7 @@ def knowledge_cutoff_analysis( cutoff: str = KNOWLEDGE_CUTOFF, ) -> dict[str, Any]: """Compare scores for questions resolving before vs after the knowledge cutoff.""" + logger.info("knowledge_cutoff_analysis", cutoff=cutoff) forecasts: dict[str, float] = result.get("forecasts", {}) outcomes: dict[str, int] = result.get("outcomes", {}) sources: dict[str, str] = result.get("sources", {}) @@ -295,6 +310,7 @@ def _stats(scores: list[float]) -> dict[str, Any]: def superforecaster_gap(result: dict[str, Any]) -> dict[str, Any]: """Compute gap vs leaderboard superforecaster medians.""" + logger.info("superforecaster_gap_analysis") sr = result.get("scoring_result", {}) our_overall = sr.get("overall_index", 0.0) our_dataset = sr.get("dataset_index", 0.0) @@ -328,6 +344,7 @@ def _sf_gap_by_source(result: dict[str, Any]) -> dict[str, dict[str, Any]]: def compare_round_sizes(rounds: list[dict[str, Any]]) -> dict[str, Any]: """Compare 1000q vs 500q rounds on composition and scores.""" + logger.info("compare_round_sizes", n_rounds=len(rounds)) large: list[dict[str, Any]] = [] small: list[dict[str, Any]] = [] @@ -361,6 +378,7 @@ def _agg(group: list[dict[str, Any]]) -> dict[str, Any]: def run_investigation(results: list[dict[str, Any]]) -> dict[str, Any]: """Run all 7 analyses and produce a structured report.""" + logger.info("run_investigation_start", n_results=len(results)) report: dict[str, Any] = {"analyses": {}, "summary": {}} if not results: @@ -466,6 +484,7 @@ def _avg_field(items: list[dict[str, Any]], field: str) -> float: def _build_summary(report: dict[str, Any]) -> dict[str, Any]: + logger.debug("build_summary_start", n_analyses=len(report.get("analyses", {}))) analyses = report["analyses"] findings: list[str] = [] recommendations: list[str] = [] @@ -536,6 +555,7 @@ def _build_summary(report: dict[str, Any]) -> dict[str, Any]: def format_report(report: dict[str, Any]) -> str: """Format investigation report for stdout.""" + logger.info("format_report_start") lines: list[str] = [] analyses = report.get("analyses", {}) @@ -669,6 +689,7 @@ def format_report(report: dict[str, Any]) -> str: def main() -> None: + logger.info("investigate_main_start", n_args=len(sys.argv) - 1) if len(sys.argv) > 1: paths = [Path(arg) for arg in sys.argv[1:]] results = [] diff --git a/lab_forecaster.py b/lab_forecaster.py index 66e5abb..b63cc05 100644 --- a/lab_forecaster.py +++ b/lab_forecaster.py @@ -24,6 +24,7 @@ TEMPERATURE = float(os.getenv("FORECAST_TEMPERATURE", "0")) MAX_TOKENS = int(os.getenv("FORECAST_MAX_TOKENS", "16384")) VERTEX_LOCATION = os.getenv("VERTEXAI_LOCATION", "europe-west1") +THINKING_BUDGET = int(os.getenv("FORECAST_THINKING_BUDGET", "10000")) _REFRESH_MARGIN_SECS = 300 _vertex_creds_lock = threading.Lock() @@ -34,10 +35,12 @@ def get_tracked_costs() -> dict[str, float]: + logger.debug("get_tracked_costs", n_tracked=len(_cost_tracker)) return dict(_cost_tracker) def clear_tracked_costs() -> None: + logger.debug("clear_tracked_costs", n_cleared=len(_cost_tracker)) _cost_tracker.clear() @@ -46,8 +49,9 @@ def _track_cost(question_id: str, response: Any) -> None: cost = response._hidden_params.get("response_cost") if cost is not None: _cost_tracker[question_id] = float(cost) + logger.debug("cost_tracked", question_id=question_id, cost_usd=float(cost)) except (AttributeError, TypeError, ValueError): - pass + logger.debug("cost_tracking_skipped", question_id=question_id) def _get_google_auth() -> tuple[Any, Any]: @@ -204,18 +208,31 @@ def _format_question_text(text: str, forecast_due_date: str, is_dataset: bool) - return text +def _is_thinking_model(model: str) -> bool: + return "claude" in model.lower() and THINKING_BUDGET > 0 + + def _forecast_kwargs( messages: list[dict[str, str]], timeout: int = 180, + model: str | None = None, ) -> dict[str, Any]: + effective_model = model or MODEL + logger.debug("forecast_kwargs", model=effective_model, timeout=timeout, thinking=_is_thinking_model(effective_model)) + kwargs: dict[str, Any] = { - "model": MODEL, + "model": effective_model, "messages": messages, "max_tokens": MAX_TOKENS, "timeout": timeout, "vertex_location": VERTEX_LOCATION, - "temperature": TEMPERATURE, } + + if _is_thinking_model(effective_model): + kwargs["thinking"] = {"type": "enabled", "budget_tokens": THINKING_BUDGET} + else: + kwargs["temperature"] = TEMPERATURE + return kwargs @@ -228,6 +245,7 @@ def _build_prompt( ) -> str: effective_source = source or question.source is_market = effective_source.lower() in MARKET_SOURCES + logger.debug("build_prompt", question_id=question.id, is_market=is_market, variant=prompt_variant) background = question.background or "" mrc = getattr(question, "market_info_resolution_criteria", None) @@ -303,6 +321,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]}") @@ -372,20 +391,25 @@ def _extract_probabilities(text: str, n_expected: int) -> list[float] | None: if answer_block: probs = _parse_probs_from_text(answer_block, n_expected) if probs: + logger.debug("extract_probabilities_answer_block", n_expected=n_expected, method="answer_block") return probs probs = _tokenize_and_extract(text, n_expected) if probs: + logger.debug("extract_probabilities_success", n_expected=n_expected, method="tokenize") return probs probs = _asterisk_extract(text, n_expected) if probs: + logger.debug("extract_probabilities_success", n_expected=n_expected, method="asterisk") return probs probs = _decimal_extract(text, n_expected) if probs: + logger.debug("extract_probabilities_success", n_expected=n_expected, method="decimal") return probs + logger.warning("extract_probabilities_failed", n_expected=n_expected, text_length=len(text)) return None @@ -442,8 +466,7 @@ async def aforecast( _ensure_vertex_credentials(model) prompt = _build_prompt(question, resolution_date=resolution_date, source=source, resolution_dates=resolution_dates) messages = [{"role": "user", "content": prompt}] - kwargs = _forecast_kwargs(messages) - kwargs["model"] = model + kwargs = _forecast_kwargs(messages, model=model) response = await litellm.acompletion(**kwargs) _track_cost(question.id, response) text = response.choices[0].message.content or "" @@ -456,16 +479,19 @@ def forecast_multi( question: Question, resolution_dates: list[str], ) -> list[float]: - logger.info("forecast_multi_start", question_id=question.id, model=MODEL) + logger.info("forecast_multi_start", question_id=question.id, n_horizons=len(resolution_dates), model=MODEL) _ensure_vertex_credentials() prompt = _build_prompt(question, resolution_dates=resolution_dates) messages = [{"role": "user", "content": prompt}] kwargs = _forecast_kwargs(messages) response = litellm.completion(**kwargs) + _track_cost(question.id, response) text = response.choices[0].message.content or "" probs = _extract_probabilities(text, len(resolution_dates)) if probs is not None: + logger.info("forecast_multi_complete", question_id=question.id, n_probs=len(probs)) return probs + logger.warning("forecast_multi_extraction_failed", question_id=question.id, n_horizons=len(resolution_dates)) raise ValueError(f"Could not extract {len(resolution_dates)} probabilities from response") @@ -483,8 +509,7 @@ async def aforecast_multi_horizon( _ensure_vertex_credentials(model) prompt = _build_prompt(question, source=source, resolution_dates=resolution_dates) messages = [{"role": "user", "content": prompt}] - kwargs = _forecast_kwargs(messages) - kwargs["model"] = model + kwargs = _forecast_kwargs(messages, model=model) try: response = await litellm.acompletion(**kwargs) except Exception: diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py index e999a97..a1bd8db 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) @@ -167,3 +170,15 @@ def test_log_with_various_types(self) -> None: configure_logging() log = get_logger("test_types") log.info("mixed_types", count=42, ratio=0.75, flag=True, label="test", items=[1, 2]) + + def test_instrumented_modules_have_loggers(self) -> None: + configure_logging() + import tournament + import analyze + import verify_parity + import lab_forecaster + + assert hasattr(tournament, "logger") + assert hasattr(analyze, "logger") + assert hasattr(verify_parity, "logger") + assert hasattr(lab_forecaster, "logger") diff --git a/tournament.py b/tournament.py index 7321071..b31ef5a 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 @@ -31,8 +33,10 @@ class ModelResult: def load_tournament_results(results_dir: str | Path = "results") -> list[ModelResult]: + logger.info("load_tournament_results", results_dir=str(results_dir)) p = Path(results_dir) if not p.exists(): + logger.warning("load_tournament_results_no_dir", path=str(p)) return [] results: list[ModelResult] = [] for f in sorted(p.glob("*.json")): @@ -51,13 +55,16 @@ def load_tournament_results(results_dir: str | Path = "results") -> list[ModelRe timestamp=data.get("timestamp", ""), )) except (json.JSONDecodeError, KeyError): + logger.warning("load_tournament_result_error", path=str(f)) continue + logger.info("load_tournament_results_complete", n_loaded=len(results)) return results def _source_pairs( result: ModelResult, ) -> dict[str, list[tuple[float, int]]]: + logger.debug("source_pairs", model_slug=result.model_slug, n_outcomes=len(result.outcomes)) by_source: dict[str, list[tuple[float, int]]] = {} for qid, outcome in result.outcomes.items(): forecast = result.forecasts.get(qid, 0.5) @@ -81,6 +88,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) @@ -156,6 +164,7 @@ def paired_bootstrap_test( ) -> BootstrapResult: shared_ids = sorted(set(forecasts_a) & set(forecasts_b) & set(outcomes)) n = len(shared_ids) + logger.debug("paired_bootstrap_test", n_shared=n, n_bootstrap=n_bootstrap) if n == 0: return BootstrapResult(0.0, 0.0, 0.0, 1.0, 0) @@ -205,6 +214,7 @@ def pairwise_comparison_table( n_bootstrap: int = 10000, seed: int = 42, ) -> list[PairwiseEntry]: + logger.info("pairwise_comparison_start", n_models=len(results)) entries: list[PairwiseEntry] = [] for i, ra in enumerate(results): for rb in results[i + 1:]: @@ -247,6 +257,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 +281,7 @@ def cost_accuracy_summary(results: list[ModelResult]) -> list[CostEntry]: def tournament_report(results: list[ModelResult]) -> str: + logger.info("tournament_report_start", n_models=len(results)) if not results: return "No results to report." diff --git a/tournament_strategy.py b/tournament_strategy.py index b460451..03497ee 100644 --- a/tournament_strategy.py +++ b/tournament_strategy.py @@ -12,6 +12,10 @@ from pydantic import BaseModel, Field +from logging_config import get_logger + +logger = get_logger("tournament_strategy") + # ── Enums ────────────────────────────────────────────────────────────────── @@ -527,14 +531,17 @@ class TechniqueRoadmap(BaseModel): def get_techniques_by_tier(tier: int) -> list[Technique]: + logger.debug("get_techniques_by_tier", tier=tier) return [t for t in TECHNIQUES if t.tier == tier] def get_techniques_for_track(track: str) -> list[Technique]: + logger.debug("get_techniques_for_track", track=track) return [t for t in TECHNIQUES if t.track.value == track] def get_competitor_by_name(name: str) -> Competitor | None: + logger.debug("get_competitor_by_name", name=name) for c in COMPETITORS: if c.name == name: return c @@ -546,10 +553,12 @@ def get_competitor_by_name(name: str) -> Competitor | None: def get_roadmap() -> TechniqueRoadmap: + logger.debug("get_roadmap") return ROADMAP def get_pitfalls_by_severity(severity: str) -> list[Pitfall]: + logger.debug("get_pitfalls_by_severity", severity=severity) return [p for p in PITFALLS if p.severity.value == severity] @@ -557,6 +566,7 @@ def get_pitfalls_by_severity(severity: str) -> list[Pitfall]: def _print_summary() -> None: + logger.info("print_summary") print("ForecastBench Tournament Strategy") print("=" * 50) print(f"\nTechniques: {len(TECHNIQUES)}") @@ -574,6 +584,7 @@ def _print_summary() -> None: def _print_techniques_for_tier(tier: int) -> None: + logger.info("print_techniques_for_tier", tier=tier) techs = get_techniques_by_tier(tier) if not techs: print(f"No techniques found for tier {tier}") @@ -591,6 +602,7 @@ def _print_techniques_for_tier(tier: int) -> None: def _print_competitors() -> None: + logger.info("print_competitors") print("Competitor Profiles") print("=" * 50) for c in COMPETITORS: @@ -602,6 +614,7 @@ def _print_competitors() -> None: def _print_pitfalls() -> None: + logger.info("print_pitfalls") print("Known Pitfalls") print("=" * 50) for sev in [Severity.CRITICAL, Severity.HIGH, Severity.MEDIUM]: @@ -614,6 +627,7 @@ def _print_pitfalls() -> None: def _print_roadmap() -> None: + logger.info("print_roadmap") rm = get_roadmap() print("Implementation Roadmap") print("=" * 50) @@ -635,6 +649,7 @@ def _print_roadmap() -> None: def main() -> None: + logger.info("tournament_strategy_main") parser = argparse.ArgumentParser( description="ForecastBench tournament competitive landscape" ) diff --git a/verify_parity.py b/verify_parity.py index 9545c2e..f8d8575 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/" @@ -54,6 +58,7 @@ def _strip_enhancements(text: str) -> str: def extract_template(source: str, var_name: str) -> str | None: """Extract a triple-quoted string assigned to var_name from Python source.""" + logger.debug("extract_template", var_name=var_name, source_length=len(source)) pattern = rf'{var_name}\s*=\s*"""(.*?)"""' match = re.search(pattern, source, re.DOTALL) if match: @@ -70,11 +75,13 @@ def _get_local_template(name: str) -> str | None: val = getattr(lab_forecaster, name, None) if val is None: + logger.debug("local_template_not_found", name=name) return None return str(val) def check_prompt_templates(upstream_source: str | None) -> tuple[bool, str]: + logger.info("check_prompt_templates") if upstream_source is None: return True, "[WARN] Could not fetch upstream prompts — skipping live comparison" @@ -106,6 +113,7 @@ def check_prompt_templates(upstream_source: str | None) -> tuple[bool, str]: def check_resolution_matching() -> tuple[bool, str]: + logger.info("check_resolution_matching") try: from fetch_data import ( fetch_all_resolutions, @@ -140,6 +148,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") from score import brier_index if brier_index(0.25) != 50.0: @@ -171,6 +180,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") from fetch_data import ResolvedQuestion from score import score_forecasts, brier_score @@ -195,6 +205,7 @@ def check_missing_forecast_default() -> tuple[bool, str]: def check_multi_horizon_batching() -> tuple[bool, str]: + logger.info("check_multi_horizon_batching") try: from fetch_data import ( fetch_question_set, @@ -235,6 +246,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") try: from fetch_data import fetch_question_set, list_question_set_files @@ -271,16 +283,21 @@ def check_question_count(leaderboard: list[dict[str, str]] | None) -> tuple[bool def _load_latest_result() -> dict[str, Any] | None: + logger.debug("load_latest_result") if not RESULTS_DIR.exists(): + logger.debug("load_latest_result_no_dir") return None result_files = sorted(RESULTS_DIR.glob("*.json")) result_files = [f for f in result_files if f.name != "RESULTS.md"] if not result_files: + logger.debug("load_latest_result_no_files") return None try: data: dict[str, Any] = json.loads(result_files[-1].read_text()) + logger.debug("load_latest_result_loaded", path=str(result_files[-1])) return data except (json.JSONDecodeError, OSError): + logger.warning("load_latest_result_error", path=str(result_files[-1])) return None @@ -305,6 +322,7 @@ def _find_reference_model( Returns (model_name, overall_score, is_fallback) or None. When model_hint is provided, finds the closest match by overlap ratio. """ + logger.debug("find_reference_model", model_hint=model_hint, n_leaderboard=len(leaderboard)) if model_hint: cleaned = _clean_model_slug(model_hint).lower() best: tuple[str, float, int] | None = None @@ -348,6 +366,7 @@ def _find_reference_model( def check_score_comparison(leaderboard: list[dict[str, str]] | None) -> tuple[bool, str]: + logger.info("check_score_comparison") result = _load_latest_result() if result is None: return True, "[SKIP] No results found — run eval first" @@ -379,6 +398,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") result = _load_latest_result() if result is None: return True, "[SKIP] No results found — run eval first" @@ -439,6 +459,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") from dummy_forecaster import forecast as dummy_forecast from fetch_data import ( Question, @@ -493,6 +514,7 @@ def check_dummy_score() -> tuple[bool, str]: def _fetch_all_resolutions_as_lists() -> dict[str, list[Any]]: """Fetch all resolutions preserving every entry per question ID.""" + logger.info("fetch_all_resolutions_as_lists") from fetch_data import Resolution, fetch_resolution, list_resolution_files filenames = list_resolution_files() @@ -509,6 +531,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") resolutions = _fetch_all_resolutions_as_lists() multi_entry_ids: dict[str, set[int | None]] = {} @@ -538,6 +561,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") resolutions = _fetch_all_resolutions_as_lists() unique_ids = len(resolutions) @@ -565,6 +589,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") from fetch_data import ( MARKET_SOURCES, fetch_all_question_sets, @@ -632,6 +657,7 @@ def check_cross_round_filtering() -> tuple[bool, str]: def _fetch_upstream_prompts(refresh: bool = False) -> str | None: + logger.info("fetch_upstream_prompts", refresh=refresh) try: from fetch_data import _fetch_text @@ -648,6 +674,7 @@ def _fetch_upstream_prompts(refresh: bool = False) -> str | None: def _fetch_leaderboard(refresh: bool = False) -> list[dict[str, str]] | None: + logger.info("fetch_leaderboard", refresh=refresh) try: if refresh: from fetch_data import refresh_cache @@ -661,6 +688,7 @@ def _fetch_leaderboard(refresh: bool = False) -> list[dict[str, str]] | None: def main() -> None: + logger.info("verify_parity_main") import os os.environ["FORECASTBENCH_LOG_FORMAT"] = "json"