Compare commits

..
Author SHA1 Message Date
ChuckBuildsandClaude Opus 5 0e0b89388d fix(odds): identify the odds requests to ESPN
The odds fetch used a bare requests.get, so it went out as
python-requests/x.y -- the one agent ESPN is known to reject. Around
2026-08-04 it began 403ing browser strings and bare custom tokens alike;
what it accepts is a token carrying a URL that says who is calling.
Every other ESPN caller in the tree already sends that header
(src/common/api_helper.py, src/base_classes/data_sources.py); this path
was simply missed.

It is the worst one to miss. Odds are fetched per live game from inside
the live update loop, so its failures are the ones that cost the caller
its whole update budget -- the same path the 5s timeout and the cooldown
were added to protect.

Sent via a session rather than per-call, which also reuses the
connection across a slate. Deliberately no retry adapter, unlike
api_helper: retries multiply request_timeout, which is 5s precisely to
stay inside the 30s operation budget.

The existing tests patched the module's requests.get, which this change
bypasses -- test_base_odds_manager was consequently reaching the real
ESPN and taking 404s. Both files now patch the session, and the new
tests pin the agent against api_helper's live value so the two cannot
drift apart the next time ESPN moves the goalposts.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Udr6MfaFLUPhX5Fgo67Jf5
2026-08-11 15:39:42 -04:00
5 changed files with 115 additions and 296 deletions
+19 -1
View File
@@ -45,6 +45,24 @@ class BaseOddsManager:
self.logger = logging.getLogger(__name__)
self.base_url = "https://sports.core.api.espn.com/v2/sports"
# This path used a bare requests.get, so it identified itself as
# python-requests/x.y -- the one thing ESPN is known to reject. Around
# 2026-08-04 it began 403ing browser strings and bare custom tokens
# alike; what it accepts is a token with a URL that says who is
# calling. Every other ESPN caller in the tree already sends this
# (src/common/api_helper.py, src/base_classes/data_sources.py); the
# odds path was simply missed, and it is the one whose failures cost
# the caller its whole update budget.
#
# Deliberately no retry adapter, unlike api_helper: retries multiply
# request_timeout, which is set to 5s precisely to stay inside that
# budget. One try, then the cooldown below.
self.session = requests.Session()
self.session.headers.update({
'User-Agent': 'LEDMatrix/1.0 (+https://github.com/ChuckBuilds/LEDMatrix)',
'Accept': 'application/json',
})
# Configuration with defaults
self.update_interval = 3600 # 1 hour default
# Well under the plugin executor's 30s operation budget. At 30s a
@@ -144,7 +162,7 @@ class BaseOddsManager:
url = f"{self.base_url}/{sport}/leagues/{espn_league}/events/{event_id}/competitions/{event_id}/odds"
self.logger.info(f"Requesting odds from URL: {url}")
response = requests.get(url, timeout=self.request_timeout)
response = self.session.get(url, timeout=self.request_timeout)
response.raise_for_status()
raw_data = response.json()
+3 -125
View File
@@ -12,11 +12,8 @@ Supports three display modes per plugin:
"""
import logging
import os
import sys
import threading
import time
import traceback
import threading
from typing import Optional, Dict, Any, List, Callable, TYPE_CHECKING
from src.vegas_mode.config import VegasModeConfig
@@ -32,81 +29,6 @@ if TYPE_CHECKING:
logger = logging.getLogger(__name__)
# A frame is a "hitch" once it takes this many times the typical frame. Two
# is deliberately forgiving: one dropped frame at 120fps is 8ms and invisible,
# whereas a marquee moving a steady few pixels per frame shows a stall of
# twice that as a visible jerk.
_HITCH_FACTOR = 2.0
# How many recent frames define "typical". Big enough to ride out noise, small
# enough to track a genuine change in what the loop costs.
_TYPICAL_SAMPLE = 60
# A stall long enough that a viewer sees the marquee stop dead. Frame-time
# statistics say one happened but not what did it, and by the time the numbers
# are logged the stack is long gone -- so a watchdog samples every thread while
# the loop is still wedged. Off unless LEDMATRIX_STALL_WATCHDOG is set, since
# it dumps a lot of text.
_STALL_DUMP_SECONDS = float(os.environ.get('LEDMATRIX_STALL_WATCHDOG', '0') or 0)
class _StallWatchdog:
"""Dumps every thread's stack when the render loop stops checking in."""
def __init__(self, threshold: float):
self.threshold = threshold
self._beat = time.time()
self._lock = threading.Lock()
self._stop = threading.Event()
self._dumped_for = 0.0
self._thread = threading.Thread(
target=self._watch, name="VegasStallWatchdog", daemon=True)
self._thread.start()
def beat(self) -> None:
with self._lock:
self._beat = time.time()
def stop(self) -> None:
self._stop.set()
def _watch(self) -> None:
poll = self.threshold / 4.0
while True:
woke_at = time.time()
if self._stop.wait(poll):
break
with self._lock:
last = self._beat
now = time.time()
stalled = now - last
# A stall inside a C call that holds the GIL never shows up as a
# late beat: this thread cannot run during it, and by the time it
# does the loop has already checked in. What it can see is that
# its own sleep ran long. Treat a badly overshot wait as a stall
# in its own right -- the stacks are stale by then, but knowing
# the freeze is GIL-holding is itself the diagnosis.
overshoot = (now - woke_at) - poll
if overshoot > self.threshold:
logger.warning(
"render loop stalled %.2fs holding the GIL -- no Python "
"frames ran, so the stacks below are from after it ended; "
"look for one long C call (a large PIL operation, a "
"compress, a big allocation)", overshoot)
stalled = overshoot
elif stalled < self.threshold or last == self._dumped_for:
continue
self._dumped_for = last # one dump per stall, not per poll
frames = sys._current_frames()
names = {t.ident: t.name for t in threading.enumerate()}
lines = ["render loop stalled %.2fs -- thread stacks:" % stalled]
for ident, frame in frames.items():
lines.append(" --- %s (%s) ---" % (names.get(ident, "?"), ident))
for fn, lineno, func, _text in traceback.extract_stack(frame)[-8:]:
lines.append(" %s:%d in %s" % (fn, lineno, func))
logger.warning("\n".join(lines))
class VegasModeCoordinator:
"""
@@ -197,7 +119,6 @@ class VegasModeCoordinator:
'static_pauses': 0,
}
self._start_time: Optional[float] = None
self._stall_watchdog: Optional['_StallWatchdog'] = None
logger.info(
"VegasModeCoordinator initialized: enabled=%s, fps=%d, buffer_ahead=%d",
@@ -461,20 +382,6 @@ class VegasModeCoordinator:
fps_log_interval = 5.0 # Log FPS every 5 seconds
last_fps_log_time = start_time
fps_frame_count = 0
# Stutter is invisible in a mean. At 120fps a 5s window covers ~600
# frames, so a 200ms freeze -- plainly visible on a marquee -- moves
# the average from 120.0 to 115.4 and reads as healthy. What a viewer
# notices is the worst frame, so track that separately.
frame_worst = 0.0
frame_hitches = 0
frame_times: List[float] = []
frame_typical = 0.0
# One per coordinator, not per iteration -- run_iteration is called
# repeatedly, so building one here would leak a thread each time.
if _STALL_DUMP_SECONDS > 0 and self._stall_watchdog is None:
self._stall_watchdog = _StallWatchdog(_STALL_DUMP_SECONDS)
watchdog = self._stall_watchdog
logger.info("Starting Vegas iteration for %.1fs", duration)
@@ -510,25 +417,6 @@ class VegasModeCoordinator:
frame_elapsed = time.time() - frame_started
time.sleep(max(0.0, frame_interval - frame_elapsed))
# Measured before the sleep, so this is time spent working rather
# than time spent pacing. A frame that overruns the budget is one
# the viewer sees as a jerk in otherwise smooth motion.
if frame_elapsed > frame_worst:
frame_worst = frame_elapsed
# Measured against what frames actually cost here, not against
# the configured target. The target is routinely set above what
# the panel can hold so vsync does the pacing -- against that
# budget every ordinary frame looks like a hitch, which is how
# the first version of this counter reported 250 per window on a
# display that was running perfectly smoothly.
if frame_typical and frame_elapsed > _HITCH_FACTOR * frame_typical:
frame_hitches += 1
if len(frame_times) >= _TYPICAL_SAMPLE:
frame_typical = sorted(frame_times[-_TYPICAL_SAMPLE:])[_TYPICAL_SAMPLE // 2]
frame_times.append(frame_elapsed)
if watchdog:
watchdog.beat()
# Increment frame count and check for interrupt periodically
frame_count += 1
fps_frame_count += 1
@@ -537,22 +425,12 @@ class VegasModeCoordinator:
current_time = time.time()
if current_time - last_fps_log_time >= fps_log_interval:
fps = fps_frame_count / (current_time - last_fps_log_time)
p99 = 0.0
if frame_times:
ordered = sorted(frame_times)
p99 = ordered[min(len(ordered) - 1,
int(len(ordered) * 0.99))]
logger.info(
"Vegas FPS: %.1f (target: %d, frames: %d) "
"p99 %.1fms worst %.1fms hitches %d",
fps, self.vegas_config.target_fps, fps_frame_count,
p99 * 1000.0, frame_worst * 1000.0, frame_hitches
"Vegas FPS: %.1f (target: %d, frames: %d)",
fps, self.vegas_config.target_fps, fps_frame_count
)
last_fps_log_time = current_time
fps_frame_count = 0
frame_worst = 0.0
frame_hitches = 0
frame_times.clear()
if (self._interrupt_check and
frame_count % self._interrupt_check_interval == 0):
+4 -2
View File
@@ -8,7 +8,9 @@ is_odds_available's ML-blind truth table, the fixed format_odds_summary
gate (money-line-only odds now format), get_odds_for_games, and
configuration loading.
No real network: src.base_odds_manager.requests.get is always patched.
No real network: requests.Session.get is always patched. The odds path sends
its requests through a session so it can identify itself to ESPN, so patching
the module-level requests.get would no longer intercept anything.
"""
from unittest.mock import MagicMock, patch
@@ -59,7 +61,7 @@ def manager(cache_manager):
@pytest.fixture
def mock_get():
with patch('src.base_odds_manager.requests.get') as m:
with patch('src.base_odds_manager.requests.Session.get') as m:
m.return_value = _make_response({'items': [dict(FULL_ITEM)]})
yield m
+89 -49
View File
@@ -10,10 +10,15 @@ and the update carrying every game's score was killed:
Invisible out of season -- preseason week 1 returns a single game -- and a
Sunday slate is around sixteen.
The request now goes through a session that identifies the caller, so the
tests patch `manager.session.get` rather than the module's `requests.get`.
"""
from unittest.mock import Mock
import requests
from src.base_odds_manager import BaseOddsManager
PLUGIN_BUDGET = 30.0 # PluginExecutor(default_timeout=30.0)
@@ -25,43 +30,83 @@ def _manager(cache=None):
return BaseOddsManager(cache_manager=cache, config_manager=None)
def _timing_out(manager):
"""Point the manager's session at a request that always times out."""
manager.session.get = Mock(side_effect=requests.exceptions.Timeout("x"))
return manager.session.get
def _returning(manager, payload):
resp = Mock()
resp.json.return_value = payload
resp.raise_for_status.return_value = None
manager.session.get = Mock(return_value=resp)
return manager.session.get
class TestRequestTimeout:
def test_leaves_room_in_the_operation_budget(self):
assert _manager().request_timeout < PLUGIN_BUDGET / 2
def test_the_timeout_is_the_one_actually_used(self):
m = _manager()
import src.base_odds_manager as mod
real = mod.requests.get
try:
mod.requests.get = Mock(side_effect=mod.requests.exceptions.Timeout("x"))
m.get_odds("football", "nfl", "401")
assert mod.requests.get.call_args.kwargs["timeout"] == m.request_timeout
finally:
mod.requests.get = real
get = _timing_out(m)
m.get_odds("football", "nfl", "401")
assert get.call_args.kwargs["timeout"] == m.request_timeout
class TestIdentifiesItselfToEspn:
"""ESPN 403s python-requests' default agent, and bare custom tokens.
What it accepts is a token carrying a URL that says who is calling. This
path used a bare requests.get and so sent the default -- the one thing
known to be rejected. Everything else in the tree that talks to ESPN
already sends the header below.
"""
def test_the_user_agent_names_the_project_and_links_to_it(self):
ua = _manager().session.headers["User-Agent"]
assert "python-requests" not in ua
assert "LEDMatrix" in ua
assert "github.com/ChuckBuilds/LEDMatrix" in ua
def test_it_is_the_same_agent_the_rest_of_the_tree_sends(self):
# Compared against the live value rather than a copied literal, so the
# two cannot drift apart the next time ESPN moves the goalposts.
from src.common.api_helper import APIHelper
assert (_manager().session.headers["User-Agent"]
== APIHelper().session.headers["User-Agent"])
def test_the_header_reaches_the_request(self):
m = _manager()
get = _returning(m, {})
m._extract_espn_data = Mock(return_value=None)
m.get_odds("football", "nfl", "401")
# Sent via the session, so it applies without being passed per-call.
assert get.call_count == 1
assert "User-Agent" in m.session.headers
def test_no_retry_adapter_multiplies_the_timeout(self):
# api_helper mounts a retrying adapter; this path must not, or a 5s
# timeout becomes 15s and the budget fix is undone.
m = _manager()
for adapter in m.session.adapters.values():
retries = getattr(adapter, "max_retries", None)
assert getattr(retries, "total", 0) in (0, None), (
"odds session mounts a retrying adapter (total=%r); retries "
"multiply request_timeout" % getattr(retries, "total", None))
class TestSlowEspnCannotKillTheUpdate:
def test_one_failure_stops_the_rest_of_the_slate_hitting_the_network(self):
m = _manager()
import src.base_odds_manager as mod
real = mod.requests.get
calls = {"n": 0}
get = _timing_out(m)
for i in range(16): # a full slate, one game at a time
m.get_odds("football", "nfl", "4018730%02d" % i)
def timeout(*a, **k):
calls["n"] += 1
raise mod.requests.exceptions.Timeout("timed out")
try:
mod.requests.get = timeout
for i in range(16): # a full slate, one game at a time
m.get_odds("football", "nfl", "4018730%02d" % i)
finally:
mod.requests.get = real
assert calls["n"] == 1, (
assert get.call_count == 1, (
"%d games each paid the timeout; the breaker should have stopped "
"after the first" % calls["n"])
"after the first" % get.call_count)
def test_worst_case_slate_stays_inside_the_budget(self):
m = _manager()
@@ -70,53 +115,48 @@ class TestSlowEspnCannotKillTheUpdate:
def test_recovery_is_automatic(self):
m = _manager()
import src.base_odds_manager as mod
real_get, real_monotonic = mod.requests.get, mod.time.monotonic
real_monotonic = mod.time.monotonic
clock = {"t": 1000.0}
try:
mod.time.monotonic = lambda: clock["t"]
mod.requests.get = Mock(
side_effect=mod.requests.exceptions.Timeout("timed out"))
get = _timing_out(m)
m.get_odds("football", "nfl", "401")
assert m._skip_network_until > clock["t"], "breaker did not open"
clock["t"] += 1
before = mod.requests.get.call_count
before = get.call_count
m.get_odds("football", "nfl", "402")
assert mod.requests.get.call_count == before, "should not have retried"
assert get.call_count == before, "should not have retried"
clock["t"] += m._FAILURE_COOLDOWN
m.get_odds("football", "nfl", "403")
assert mod.requests.get.call_count > before, "never retried"
assert get.call_count > before, "never retried"
finally:
mod.requests.get, mod.time.monotonic = real_get, real_monotonic
mod.time.monotonic = real_monotonic
def test_a_healthy_fetch_clears_the_breaker(self):
m = _manager()
m._skip_network_until = 0.0
m._extract_espn_data = Mock(return_value=None)
import src.base_odds_manager as mod
real = mod.requests.get
try:
resp = Mock()
resp.json.return_value = {}
resp.raise_for_status.return_value = None
mod.requests.get = Mock(return_value=resp)
m.get_odds("football", "nfl", "401")
finally:
mod.requests.get = real
_returning(m, {})
m.get_odds("football", "nfl", "401")
assert m._skip_network_until == 0.0
def test_a_403_opens_the_breaker_rather_than_hammering(self):
# raise_for_status raises HTTPError, a RequestException -- so a wrong
# or missing agent backs off instead of 403ing once per game.
m = _manager()
resp = Mock()
resp.raise_for_status.side_effect = requests.exceptions.HTTPError("403")
m.session.get = Mock(return_value=resp)
m.get_odds("football", "nfl", "401")
assert m._skip_network_until > 0.0
def test_the_stale_cache_fallback_still_works(self):
# The failing request must still hand back whatever was cached; only
# the *subsequent* games skip the network.
cache = Mock()
cache.get_with_auto_strategy.side_effect = [None, {"details": "stale"}]
m = BaseOddsManager(cache_manager=cache, config_manager=None)
import src.base_odds_manager as mod
real = mod.requests.get
try:
mod.requests.get = Mock(
side_effect=mod.requests.exceptions.Timeout("timed out"))
assert m.get_odds("football", "nfl", "401") == {"details": "stale"}
finally:
mod.requests.get = real
_timing_out(m)
assert m.get_odds("football", "nfl", "401") == {"details": "stale"}
-119
View File
@@ -1,119 +0,0 @@
"""Tests the watchdog that catches a stalled render loop in the act.
Frame-time statistics can say a stall happened but not what caused it, and by
the time the numbers reach the log the stack is long gone. On a live rig the
Vegas loop showed a 3.2s freeze roughly twice an hour with every other frame
under 25ms -- invisible in the mean, and unattributable from the log alone.
This watchdog samples every thread's stack while the loop is still wedged,
which is how that freeze was traced to a plugin generating a 17,000px scroll
image, logo PNG decode and all, on the render thread.
"""
import threading
import time
import pytest
from src.vegas_mode.coordinator import _StallWatchdog
@pytest.fixture
def watchdog():
made = []
def build(threshold):
w = _StallWatchdog(threshold)
made.append(w)
return w
yield build
for w in made:
w.stop()
for w in made:
w._thread.join(timeout=2.0)
assert not w._thread.is_alive(), "watchdog thread outlived its owner"
def _dumps(caplog):
return [r for r in caplog.records if 'render loop stalled' in r.getMessage()]
class TestItFiresOnlyWhenStalled:
def test_a_beating_loop_is_never_reported(self, watchdog, caplog):
w = watchdog(0.2)
deadline = time.time() + 0.9
while time.time() < deadline:
w.beat()
time.sleep(0.02)
assert not _dumps(caplog)
def test_a_stalled_loop_is_reported(self, watchdog, caplog):
w = watchdog(0.2)
w.beat()
time.sleep(0.9)
assert _dumps(caplog), "no stall dump for a loop that stopped beating"
def test_one_dump_per_stall_not_per_poll(self, watchdog, caplog):
# The watchdog polls at threshold/4, so a stall lasting many poll
# intervals must not flood the log with a dump each time.
w = watchdog(0.2)
w.beat()
time.sleep(1.2)
assert len(_dumps(caplog)) == 1, (
"%d dumps for one stall" % len(_dumps(caplog)))
def test_a_later_stall_is_reported_again(self, watchdog, caplog):
w = watchdog(0.2)
w.beat()
time.sleep(0.6)
first = len(_dumps(caplog))
w.beat() # recovered
time.sleep(0.6) # then stalled again
assert len(_dumps(caplog)) == first + 1
class TestWhatItReports:
def test_the_dump_names_threads_and_shows_frames(self, watchdog, caplog):
started = threading.Event()
release = threading.Event()
def parked():
started.set()
release.wait(3.0)
t = threading.Thread(target=parked, name="CulpritThread", daemon=True)
t.start()
started.wait(2.0)
try:
w = watchdog(0.2)
w.beat()
time.sleep(0.7)
dumps = _dumps(caplog)
assert dumps
text = dumps[0].getMessage()
assert "CulpritThread" in text, text
assert " in " in text, "no frames in the dump"
assert ".py:" in text, "no file:line in the dump"
finally:
release.set()
t.join(timeout=2.0)
def test_it_reports_how_long_the_stall_ran(self, watchdog, caplog):
w = watchdog(0.2)
w.beat()
time.sleep(0.8)
text = _dumps(caplog)[0].getMessage()
assert "stalled" in text
# Long enough to have tripped, and not an absurd value.
stalled = float(text.split("stalled")[1].split("s")[0])
assert 0.2 <= stalled <= 3.0, stalled
class TestItIsCheapWhenIdle:
def test_stop_is_prompt(self, caplog):
w = _StallWatchdog(4.0) # long threshold, long poll interval
t0 = time.time()
w.stop()
w._thread.join(timeout=3.0)
assert not w._thread.is_alive(), "stop() did not end the thread"
assert time.time() - t0 < 2.0, "stop() waited out the poll interval"