diff --git a/src/common/logo_helper.py b/src/common/logo_helper.py index 743e7b7b..a64ca340 100644 --- a/src/common/logo_helper.py +++ b/src/common/logo_helper.py @@ -143,8 +143,10 @@ def load_logo_with_download(self, team_abbr: str, logo_path: Union[str, Path], """ logo_path = Path(logo_path) - # Try to load existing logo first - if logo_path.exists(): + # Try to load existing logo first. A placeholder written by a previous + # failed download does not count: it wears the real logo's filename, so + # trusting the file's existence is what left teams as grey boxes. + if logo_path.exists() and not self._is_stale_placeholder(logo_path): return self.load_logo(team_abbr, logo_path, max_width, max_height) # Download if URL provided and file doesn't exist @@ -152,13 +154,61 @@ def load_logo_with_download(self, team_abbr: str, logo_path: Union[str, Path], try: self.logger.info(f"Downloading logo for {team_abbr} from {logo_url}") self._download_logo(logo_url, logo_path) + # The file on disk just changed. Any cached image for it is the + # placeholder we came here to replace, and load_logo() answers + # from the cache before touching the disk -- so without this the + # real logo would not appear until the process restarted. + self._invalidate_cached_logo(team_abbr, logo_path) return self.load_logo(team_abbr, logo_path, max_width, max_height) except Exception as e: self.logger.error(f"Failed to download logo for {team_abbr}: {e}") + # The retry failed, so restart the back-off. The stale + # placeholder is still on disk with its old timestamp, and + # leaving it there means the next call retries immediately -- + # a download attempt per call, which is what the back-off + # exists to prevent. + self._refresh_stale_placeholder(logo_path) # Create placeholder if all else fails return self._create_placeholder_logo(team_abbr, max_width, max_height) + def _invalidate_cached_logo(self, team_abbr: str, logo_path: Path) -> None: + """Drop every cached size of one logo after its file changed on disk.""" + prefix = f"{team_abbr}_{logo_path}_" + for key in [k for k in self._logo_cache if k.startswith(prefix)]: + self._logo_cache.pop(key, None) + if key in self._cache_order: + self._cache_order.remove(key) + + @staticmethod + def _refresh_stale_placeholder(logo_path: Path) -> None: + """Restart the retry back-off after a failed download attempt.""" + try: + from src.logo_downloader import refresh_placeholder_timestamp + except ImportError: + return + refresh_placeholder_timestamp(logo_path) + + @staticmethod + def _is_stale_placeholder(logo_path: Path) -> bool: + """True if the file is a placeholder old enough to be worth retrying. + + Imported lazily so this module keeps working against a core build whose + logo_downloader predates placeholder marking. + """ + try: + from src.logo_downloader import ( + PLACEHOLDER_RETRY_SECONDS, + is_placeholder_logo, + placeholder_age_seconds, + ) + except ImportError: + return False + if not is_placeholder_logo(logo_path): + return False + age = placeholder_age_seconds(logo_path) + return age is None or age >= PLACEHOLDER_RETRY_SECONDS + def get_logo_variations(self, team_abbr: str) -> List[str]: """ Get possible filename variations for a team abbreviation. diff --git a/src/logo_downloader.py b/src/logo_downloader.py index b799b7c1..d6fbd7bc 100644 --- a/src/logo_downloader.py +++ b/src/logo_downloader.py @@ -14,6 +14,7 @@ from typing import Dict, List, Optional, Tuple from pathlib import Path from PIL import Image, ImageDraw, ImageFont +from PIL.PngImagePlugin import PngInfo from requests.adapters import HTTPAdapter from urllib3.util.retry import Retry from src.common.permission_utils import ( @@ -25,6 +26,96 @@ logger = logging.getLogger(__name__) +#: PNG text key stamped into a generated placeholder so a later run can tell it +#: apart from a real logo that happens to be small. +PLACEHOLDER_MARKER = "ledmatrix_placeholder" + +#: Geometry of a generated placeholder, used to recognise ones written before +#: the marker existed. Those are already on users' disks and would otherwise +#: never be retried. +PLACEHOLDER_SIZE = (64, 64) +PLACEHOLDER_BG = (100, 100, 100, 255) + +#: How long a placeholder is trusted before the real logo is attempted again. +#: A placeholder means the download failed, and download failures are usually +#: transient (no network at boot, ESPN blipping). Retrying every frame would +#: hammer the API from a Pi that is also driving a panel; never retrying leaves +#: the team a grey box forever, which is the bug this exists to avoid. +PLACEHOLDER_RETRY_SECONDS = 6 * 60 * 60 + + +def is_placeholder_logo(filepath: Path) -> bool: + """True if the file at ``filepath`` is a generated placeholder, not a logo. + + Checks the marker first, then falls back to matching the placeholder's + exact geometry and background colour so files written before the marker was + introduced are still recognised. + """ + try: + with Image.open(filepath) as img: + if img.info.get(PLACEHOLDER_MARKER): + return True + if img.size != PLACEHOLDER_SIZE: + return False + return img.convert("RGBA").getpixel((0, 0)) == PLACEHOLDER_BG + except Exception: + # Unreadable file: not provably a placeholder, and the caller's own + # error handling is better placed to deal with it. + return False + + +def should_attempt_download(filepath: Path, force_download: bool = False) -> bool: + """Whether a real logo is worth (re)fetching for ``filepath``. + + True when nothing is there, when the caller forced it, or when what is + there is a placeholder old enough to retry. A *fresh* placeholder says a + download just failed, so retrying it immediately would hammer the API for + a result that is very unlikely to have changed. + """ + if force_download or not filepath.exists(): + return True + if not is_placeholder_logo(filepath): + return False + age = placeholder_age_seconds(filepath) + return age is None or age >= PLACEHOLDER_RETRY_SECONDS + + +def refresh_placeholder_timestamp(filepath: Path) -> bool: + """Restamp a placeholder so a failed retry restarts the back-off clock. + + Without this a stale placeholder stays stale: every later call sees an + expired timestamp, retries, fails, and leaves the timestamp untouched -- + which is a download attempt per call, the opposite of what the back-off is + for. + """ + try: + if not is_placeholder_logo(filepath): + return False + metadata = PngInfo() + metadata.add_text(PLACEHOLDER_MARKER, str(time.time())) + with Image.open(filepath) as img: + img.copy().save(filepath, "PNG", pnginfo=metadata) + return True + except Exception: + logger.debug("Could not refresh placeholder timestamp for %s", filepath, + exc_info=True) + return False + + +def placeholder_age_seconds(filepath: Path) -> Optional[float]: + """Seconds since a placeholder was written, or None if unknown.""" + try: + with Image.open(filepath) as img: + stamped = img.info.get(PLACEHOLDER_MARKER) + if stamped and stamped != "1": + return max(0.0, time.time() - float(stamped)) + except Exception: + pass + try: + return max(0.0, time.time() - filepath.stat().st_mtime) + except OSError: + return None + class LogoDownloader: """Centralized logo downloader for team logos from ESPN API.""" @@ -499,8 +590,10 @@ def download_missing_logos_for_league(self, league: str, force_download: bool = filename = f"{self.normalize_abbreviation(abbreviation)}.png" filepath = Path(logo_dir) / filename - # Skip if already exists and not forcing download - if filepath.exists() and not force_download: + # A placeholder does not count as existing -- it is a previous + # failure, and a bulk pass is exactly where it should get another + # chance, subject to the same back-off as everywhere else. + if not should_attempt_download(filepath, force_download): logger.debug(f"Skipping {display_name}: {filename} already exists") continue @@ -559,8 +652,9 @@ def download_all_ncaa_football_logos(self, include_fcs: bool = True, force_downl filename = f"{self.normalize_abbreviation(abbreviation)}.png" filepath = Path(logo_dir) / filename - # Skip if already exists and not forcing download - if filepath.exists() and not force_download: + # Same eligibility rule as every other download site: a stale + # placeholder is a failed download, not a logo. + if not should_attempt_download(filepath, force_download): logger.debug(f"Skipping {display_name} ({category}, {conference}): {filename} already exists") continue @@ -674,11 +768,16 @@ def create_placeholder_logo(self, team_abbreviation: str, logo_dir: str) -> bool # Fallback without font draw.text((16, 24), text, fill=(255, 255, 255, 255)) - logo.save(filepath) - + # Stamp it so a later run can tell this apart from a real logo and + # retry the download, instead of treating the file's existence as + # proof the logo was fetched. + metadata = PngInfo() + metadata.add_text(PLACEHOLDER_MARKER, str(time.time())) + logo.save(filepath, "PNG", pnginfo=metadata) + # Set proper file permissions after saving ensure_file_permissions(filepath, get_assets_file_mode()) - + logger.info(f"Created placeholder logo for {team_abbreviation} at {filepath}") return True @@ -770,9 +869,18 @@ def download_missing_logo(league: str, team_id: str, team_abbreviation: str, log # Use the exact filepath that was passed in (respects config settings) filepath = logo_path - if filepath.exists(): + if filepath.exists() and not should_attempt_download(filepath): + # Either a real logo, or a placeholder too fresh to be worth retrying. logger.debug(f"Logo already exists for {team_abbreviation} ({league})") return True + if filepath.exists(): + # A placeholder is a *failed* download wearing the real logo's + # filename. Treating it as "already exists" is what pinned a team to a + # grey box permanently after one transient failure. + logger.info( + "Logo for %s (%s) is a placeholder from a failed download; " + "retrying the real logo", team_abbreviation, league, + ) # Try to download the real logo first logger.info(f"Attempting to download logo for {team_abbreviation} from {league}") diff --git a/test/test_logo_downloader.py b/test/test_logo_downloader.py index 9b79d45b..c14b3391 100644 --- a/test/test_logo_downloader.py +++ b/test/test_logo_downloader.py @@ -8,11 +8,27 @@ """ import os +import time + import pytest from pathlib import Path from unittest.mock import patch, Mock, MagicMock -from src.logo_downloader import LogoDownloader +from PIL import Image +from PIL.PngImagePlugin import PngInfo + +from src.logo_downloader import ( + PLACEHOLDER_BG, + PLACEHOLDER_MARKER, + PLACEHOLDER_RETRY_SECONDS, + PLACEHOLDER_SIZE, + LogoDownloader, + download_missing_logo, + is_placeholder_logo, + placeholder_age_seconds, + refresh_placeholder_timestamp, + should_attempt_download, +) # --------------------------------------------------------------------------- @@ -127,3 +143,211 @@ def mock_open(path, *args, **kwargs): with patch("builtins.open", side_effect=mock_open): result = downloader.ensure_logo_directory(test_dir) assert result is False + + +# --------------------------------------------------------------------------- +# Placeholder detection and retry +# +# A failed download used to be cached as a placeholder wearing the real logo's +# filename, and download_missing_logo returned early on "the file exists". One +# transient failure therefore pinned a team to a grey box permanently. +# --------------------------------------------------------------------------- + +class TestPlaceholderLogos: + def _placeholder(self, tmp_path, abbrev="COLL"): + downloader = LogoDownloader() + assert downloader.create_placeholder_logo(abbrev, str(tmp_path)) is True + return tmp_path / f"{abbrev}.png" + + def test_generated_placeholder_is_recognised(self, tmp_path): + assert is_placeholder_logo(self._placeholder(tmp_path)) is True + + def test_real_logo_is_not_a_placeholder(self, tmp_path): + real = tmp_path / "REAL.png" + Image.new("RGBA", (500, 500), (12, 34, 56, 255)).save(real) + assert is_placeholder_logo(real) is False + + def test_legacy_unmarked_placeholder_is_recognised(self, tmp_path): + """Placeholders written before the marker existed must still be caught. + + They are already sitting on users' disks; if they were not recognised + those teams would stay grey boxes forever even after this fix. + """ + legacy = tmp_path / "LEGACY.png" + Image.new("RGBA", PLACEHOLDER_SIZE, PLACEHOLDER_BG).save(legacy) + assert is_placeholder_logo(legacy) is True + + def test_same_size_but_different_colour_is_not_a_placeholder(self, tmp_path): + real = tmp_path / "SMALL.png" + Image.new("RGBA", PLACEHOLDER_SIZE, (10, 200, 10, 255)).save(real) + assert is_placeholder_logo(real) is False + + def test_missing_file_is_not_a_placeholder(self, tmp_path): + assert is_placeholder_logo(tmp_path / "nope.png") is False + + def test_existing_real_logo_short_circuits_without_downloading(self, tmp_path): + real = tmp_path / "REAL.png" + Image.new("RGBA", (500, 500), (1, 2, 3, 255)).save(real) + with patch.object(LogoDownloader, "download_logo") as download: + assert download_missing_logo( + "afl", "1", "REAL", real, logo_url="http://example/x.png") is True + download.assert_not_called() + + def _age_placeholder(self, path, seconds): + """Rewrite a placeholder's marker so it reads as `seconds` old.""" + metadata = PngInfo() + metadata.add_text(PLACEHOLDER_MARKER, str(time.time() - seconds)) + with Image.open(path) as img: + img.copy().save(path, "PNG", pnginfo=metadata) + + def test_stale_placeholder_triggers_a_retry(self, tmp_path): + path = self._placeholder(tmp_path) + self._age_placeholder(path, PLACEHOLDER_RETRY_SECONDS + 60) + assert placeholder_age_seconds(path) > PLACEHOLDER_RETRY_SECONDS + + with patch.object(LogoDownloader, "download_logo", return_value=True) as download: + assert download_missing_logo( + "afl", "1", "COLL", path, + logo_url="http://example/coll.png") is True + download.assert_called_once() + + def test_placeholder_age_survives_an_mtime_touch(self, tmp_path): + """The age comes from the stamp, not the filesystem. + + Anything that rewrites file times -- a backup restore, an rsync, a + permissions fix script -- would otherwise reset the retry clock. + """ + path = self._placeholder(tmp_path) + self._age_placeholder(path, PLACEHOLDER_RETRY_SECONDS + 60) + now = time.time() + os.utime(path, (now, now)) + assert placeholder_age_seconds(path) > PLACEHOLDER_RETRY_SECONDS + + def test_fresh_placeholder_does_not_retry(self, tmp_path): + """Rate limiting: a placeholder written seconds ago must not re-download. + + Without this the fix would trade a permanent grey box for an ESPN + request on every frame. + """ + path = self._placeholder(tmp_path) + with patch.object(LogoDownloader, "download_logo") as download: + assert download_missing_logo( + "afl", "1", "COLL", path, + logo_url="http://example/coll.png") is True + download.assert_not_called() + + +class TestDownloadEligibility: + """One rule, shared by every download site. + + The two bulk loops and the single-logo path each had their own idea of what + counted as "already have it", which is how one of them ended up retrying + fresh placeholders and the other skipping stale ones forever. + """ + + def _placeholder(self, tmp_path, abbrev="COLL"): + assert LogoDownloader().create_placeholder_logo(abbrev, str(tmp_path)) + return tmp_path / f"{abbrev}.png" + + def _age(self, path, seconds): + metadata = PngInfo() + metadata.add_text(PLACEHOLDER_MARKER, str(time.time() - seconds)) + with Image.open(path) as img: + img.copy().save(path, "PNG", pnginfo=metadata) + + def test_missing_file_is_eligible(self, tmp_path): + assert should_attempt_download(tmp_path / "nope.png") is True + + def test_real_logo_is_not_eligible(self, tmp_path): + real = tmp_path / "REAL.png" + Image.new("RGBA", (500, 500), (1, 2, 3, 255)).save(real) + assert should_attempt_download(real) is False + + def test_force_download_beats_a_real_logo(self, tmp_path): + real = tmp_path / "REAL.png" + Image.new("RGBA", (500, 500), (1, 2, 3, 255)).save(real) + assert should_attempt_download(real, force_download=True) is True + + def test_fresh_placeholder_is_not_eligible(self, tmp_path): + assert should_attempt_download(self._placeholder(tmp_path)) is False + + def test_stale_placeholder_is_eligible(self, tmp_path): + path = self._placeholder(tmp_path) + self._age(path, PLACEHOLDER_RETRY_SECONDS + 60) + assert should_attempt_download(path) is True + + def test_league_bulk_loop_skips_a_fresh_placeholder(self, tmp_path): + """A bulk pass honours the same back-off as everything else.""" + self._placeholder(tmp_path, "AAA") + downloader = LogoDownloader() + teams = [{"abbreviation": "AAA", "display_name": "A", "logo_url": "http://x/a.png"}] + with patch.object(LogoDownloader, "get_logo_directory", return_value=str(tmp_path)): + with patch.object(LogoDownloader, "fetch_teams_data", return_value={"sports": [{}]}): + with patch.object(LogoDownloader, "extract_teams_from_data", return_value=teams): + with patch.object(LogoDownloader, "download_logo") as download: + downloader.download_missing_logos_for_league("nfl") + download.assert_not_called() + + def test_league_bulk_loop_retries_a_stale_placeholder(self, tmp_path): + path = self._placeholder(tmp_path, "AAA") + self._age(path, PLACEHOLDER_RETRY_SECONDS + 60) + downloader = LogoDownloader() + teams = [{"abbreviation": "AAA", "display_name": "A", "logo_url": "http://x/a.png"}] + with patch.object(LogoDownloader, "get_logo_directory", return_value=str(tmp_path)): + with patch.object(LogoDownloader, "fetch_teams_data", return_value={"sports": [{}]}): + with patch.object(LogoDownloader, "extract_teams_from_data", return_value=teams): + with patch.object(LogoDownloader, "download_logo", return_value=True) as download: + downloader.download_missing_logos_for_league("nfl") + download.assert_called_once() + + def test_ncaa_bulk_loop_retries_a_stale_placeholder(self, tmp_path): + """This loop skipped placeholders forever; it now shares the rule.""" + path = self._placeholder(tmp_path, "AAA") + self._age(path, PLACEHOLDER_RETRY_SECONDS + 60) + downloader = LogoDownloader() + teams = [{"abbreviation": "AAA", "display_name": "A", + "logo_url": "http://x/a.png", "category": "FBS", + "conference": "SEC"}] + with patch.object(LogoDownloader, "get_logo_directory", return_value=str(tmp_path)): + with patch.object(LogoDownloader, "fetch_teams_data", return_value={"sports": [{}]}): + with patch.object(LogoDownloader, "extract_teams_from_data", return_value=teams): + with patch.object(LogoDownloader, "download_logo", return_value=True) as download: + downloader.download_all_ncaa_football_logos() + download.assert_called_once() + + def test_ncaa_bulk_loop_skips_a_fresh_placeholder(self, tmp_path): + self._placeholder(tmp_path, "AAA") + downloader = LogoDownloader() + teams = [{"abbreviation": "AAA", "display_name": "A", + "logo_url": "http://x/a.png", "category": "FBS", + "conference": "SEC"}] + with patch.object(LogoDownloader, "get_logo_directory", return_value=str(tmp_path)): + with patch.object(LogoDownloader, "fetch_teams_data", return_value={"sports": [{}]}): + with patch.object(LogoDownloader, "extract_teams_from_data", return_value=teams): + with patch.object(LogoDownloader, "download_logo") as download: + downloader.download_all_ncaa_football_logos() + download.assert_not_called() + + +class TestRefreshPlaceholderTimestamp: + def test_restarts_the_back_off(self, tmp_path): + assert LogoDownloader().create_placeholder_logo("COLL", str(tmp_path)) + path = tmp_path / "COLL.png" + metadata = PngInfo() + metadata.add_text(PLACEHOLDER_MARKER, str(time.time() - (PLACEHOLDER_RETRY_SECONDS + 60))) + with Image.open(path) as img: + img.copy().save(path, "PNG", pnginfo=metadata) + assert should_attempt_download(path) is True + + assert refresh_placeholder_timestamp(path) is True + assert should_attempt_download(path) is False + + def test_refuses_to_touch_a_real_logo(self, tmp_path): + real = tmp_path / "REAL.png" + Image.new("RGBA", (500, 500), (1, 2, 3, 255)).save(real) + before = real.read_bytes() + assert refresh_placeholder_timestamp(real) is False + assert real.read_bytes() == before + + def test_missing_file_is_not_an_error(self, tmp_path): + assert refresh_placeholder_timestamp(tmp_path / "nope.png") is False diff --git a/test/test_logo_helper.py b/test/test_logo_helper.py index 0b02af7d..cb5824b2 100644 --- a/test/test_logo_helper.py +++ b/test/test_logo_helper.py @@ -421,3 +421,76 @@ class TestSessionConfiguration: def test_user_agent_and_accept_headers(self, helper): assert helper.session.headers["User-Agent"] == "LEDMatrix-Common/1.0" assert helper.session.headers["Accept"] == "image/*" + + +class TestStalePlaceholderHandling: + """load_logo_with_download must not be fooled by a cached placeholder. + + A placeholder wears the real logo's filename, so both the file cache and + the in-memory cache can hold one and look like a hit. + """ + + def _placeholder(self, tmp_path, abbrev="COLL"): + from src.logo_downloader import LogoDownloader + assert LogoDownloader().create_placeholder_logo(abbrev, str(tmp_path)) + return tmp_path / f"{abbrev}.png" + + def _make_stale(self, path): + import time + from PIL.PngImagePlugin import PngInfo + from src.logo_downloader import PLACEHOLDER_MARKER, PLACEHOLDER_RETRY_SECONDS + metadata = PngInfo() + metadata.add_text(PLACEHOLDER_MARKER, str(time.time() - (PLACEHOLDER_RETRY_SECONDS + 60))) + with Image.open(path) as img: + img.copy().save(path, "PNG", pnginfo=metadata) + + def test_fresh_placeholder_is_served_without_a_download(self, helper, tmp_path): + path = self._placeholder(tmp_path) + with patch.object(LogoHelper, "_download_logo") as download: + assert helper.load_logo_with_download("COLL", path, "http://x/c.png") is not None + download.assert_not_called() + + def test_stale_placeholder_triggers_a_download(self, helper, tmp_path): + path = self._placeholder(tmp_path) + self._make_stale(path) + with patch.object(LogoHelper, "_download_logo") as download: + helper.load_logo_with_download("COLL", path, "http://x/c.png") + download.assert_called_once() + + def test_replacement_logo_is_not_masked_by_the_cached_placeholder(self, helper, tmp_path): + """The bug this guards: load_logo answers from cache before the disk. + + Without invalidation the freshly downloaded logo would not appear until + the process restarted. + """ + path = self._placeholder(tmp_path) + first = helper.load_logo_with_download("COLL", path, "http://x/c.png") + assert first is not None + + self._make_stale(path) + + def fake_download(_self, _url, file_path): + Image.new("RGB", (500, 500), (7, 8, 9)).save(file_path, format="PNG") + + with patch.object(LogoHelper, "_download_logo", fake_download): + second = helper.load_logo_with_download("COLL", path, "http://x/c.png") + + assert second is not None + from src.logo_downloader import is_placeholder_logo + assert is_placeholder_logo(path) is False + assert second.getpixel((0, 0))[:3] == (7, 8, 9) + + def test_failed_retry_restarts_the_back_off(self, helper, tmp_path): + """Otherwise a stale placeholder means a download attempt per call.""" + from src.logo_downloader import should_attempt_download + path = self._placeholder(tmp_path) + self._make_stale(path) + assert should_attempt_download(path) is True + + def boom(_self, _url, _file_path): + raise OSError("network down") + + with patch.object(LogoHelper, "_download_logo", boom): + helper.load_logo_with_download("COLL", path, "http://x/c.png") + + assert should_attempt_download(path) is False