From 5bfcdaf4ffad451feb206d3b5e6c54182d5103b0 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Thu, 25 Sep 2025 10:28:55 -0400 Subject: [PATCH] Fix/odds ticker manager log spam (#65) * fix(odds-ticker): Reduce log spam from insufficient time warnings - Add _insufficient_time_warning_logged flag to prevent repeated warnings - Log insufficient time warning only once per display session - Reset warning flag when starting new display or updating data - Maintain debug logging for scroll position resets to aid debugging This addresses the frequent 'Not enough time to complete content display' warnings that were flooding the logs every few milliseconds. * fix(leaderboard): Reduce log spam from progress and FPS logging - Change progress logging from every 50 pixels to every 5 seconds - Increase FPS logging interval from 10 seconds to 30 seconds - Add progress_log_interval and last_progress_log_time variables - Reset progress log timer when starting new display sessions or updating data - Maintain debug capability while significantly reducing log volume This addresses the frequent 'Leaderboard progress' and 'Leaderboard FPS' messages that were flooding the logs during leaderboard scrolling. * fix(music): Reduce log spam from track update logging - Add throttling mechanism for track update logging - Log track updates only when track title changes or after 5 seconds - Track last_logged_track_title and last_track_log_time to prevent spam - Maintain debug logging for throttled updates - Apply throttling to both regular updates and first valid data logging This addresses the frequent 'Track info updated' messages that were flooding the logs every few hundred milliseconds for the same track. * fix(logo-downloader): Fix TA&M filename normalization issue - Add special case for TA&M to keep as TA&M instead of converting to TAANDM - This fixes the issue where code was looking for TAANDM.png instead of TA&M.png - The actual logo file exists as TA&M.png, so normalization was causing file not found errors - Prevents unnecessary download attempts and permission errors for existing files Fixes the error: 'Logo not found for TA&M at assets/sports/ncaa_logos/TAANDM.png' * fix(logo-downloader): Implement robust filename variation handling - Add get_logo_filename_variations() method to handle multiple filename formats - Update _load_and_resize_logo() to try filename variations before downloading - Handles cases like TA&M.png vs TAANDM.png gracefully - Maintains backward compatibility with existing normalized filenames - Prevents issues with special characters in filenames while supporting existing files This addresses the ampersand filename issue more robustly by: 1. First trying the original filename (TA&M.png) 2. Falling back to normalized filename (TAANDM.png) if needed 3. Only attempting downloads if no variations exist * fix(leaderboard): Reduce log spam from end reached messages - Add _end_reached_logged flag to prevent repeated end reached warnings - Log 'Leaderboard reached end' and 'scrolling stopped' messages only once per display session - Maintain debug logging for throttled messages to aid debugging - Reset flag when starting new display sessions or updating data - Apply same throttling pattern used in odds ticker manager This addresses the frequent 'Leaderboard reached end' and 'scrolling stopped' messages that were flooding the logs every few milliseconds when at the end. --- src/base_classes/sports.py | 26 +++++++++++++++++++++----- src/leaderboard_manager.py | 36 +++++++++++++++++++++++++++++++----- src/logo_downloader.py | 18 ++++++++++++++++++ src/music_manager.py | 31 +++++++++++++++++++++++++++++-- src/odds_ticker_manager.py | 17 +++++++++++++++-- 5 files changed, 114 insertions(+), 14 deletions(-) diff --git a/src/base_classes/sports.py b/src/base_classes/sports.py index 9cd9d420..2a171c93 100644 --- a/src/base_classes/sports.py +++ b/src/base_classes/sports.py @@ -249,18 +249,34 @@ class SportsCore: self.logger.debug(f"Logo path: {logo_path}") try: - # Try to download missing logo first - if not logo_path.exists(): + # Try different filename variations first (for cases like TA&M vs TAANDM) + actual_logo_path = None + filename_variations = LogoDownloader.get_logo_filename_variations(team_abbrev) + + for filename in filename_variations: + test_path = logo_path.parent / filename + if test_path.exists(): + actual_logo_path = test_path + self.logger.debug(f"Found logo at alternative path: {actual_logo_path}") + break + + # If no variation found, try to download missing logo + if not actual_logo_path and not logo_path.exists(): self.logger.info(f"Logo not found for {team_abbrev} at {logo_path}. Attempting to download.") # Try to download the logo from ESPN API (this will create placeholder if download fails) download_missing_logo(self.sport_key, team_id, team_abbrev, logo_path, logo_url) + actual_logo_path = logo_path + + # Use the original path if no alternative was found + if not actual_logo_path: + actual_logo_path = logo_path # Only try to open the logo if the file exists - if os.path.exists(logo_path): - logo = Image.open(logo_path) + if os.path.exists(actual_logo_path): + logo = Image.open(actual_logo_path) else: - self.logger.error(f"Logo file still doesn't exist at {logo_path} after download attempt") + self.logger.error(f"Logo file still doesn't exist at {actual_logo_path} after download attempt") return None if logo.mode != 'RGBA': logo = logo.convert('RGBA') diff --git a/src/leaderboard_manager.py b/src/leaderboard_manager.py index f2ab9b83..975c0c05 100644 --- a/src/leaderboard_manager.py +++ b/src/leaderboard_manager.py @@ -56,9 +56,16 @@ class LeaderboardManager: # FPS tracking variables self.frame_times = [] # Store last 30 frame times for averaging self.last_frame_time = 0 - self.fps_log_interval = 10.0 # Log FPS every 10 seconds + self.fps_log_interval = 30.0 # Log FPS every 30 seconds (increased from 10s) self.last_fps_log_time = 0 + # Progress logging throttling + self.progress_log_interval = 5.0 # Log progress every 5 seconds instead of every 50 pixels + self.last_progress_log_time = 0 + + # End reached logging throttling + self._end_reached_logged = False + # Initialize managers self.cache_manager = CacheManager() # Store reference to config instead of creating new ConfigManager @@ -1259,6 +1266,10 @@ class LeaderboardManager: try: self.leaderboard_data = self._fetch_all_standings() self.last_update = current_time + # Reset progress logging timer when updating data + self.last_progress_log_time = 0 + # Reset end reached logging flag when updating data + self._end_reached_logged = False if self.leaderboard_data: self._create_leaderboard_image() @@ -1313,6 +1324,10 @@ class LeaderboardManager: logger.debug(f"Reset/initialized display start time: {self._display_start_time}") # Also reset scroll position for clean start self.scroll_position = 0 + # Reset progress logging timer + self.last_progress_log_time = 0 + # Reset end reached logging flag + self._end_reached_logged = False else: # Check if the display start time is too old (more than 2x the dynamic duration) current_time = time.time() @@ -1321,6 +1336,10 @@ class LeaderboardManager: logger.debug(f"Display start time is too old ({elapsed_time:.1f}s), resetting") self._display_start_time = current_time self.scroll_position = 0 + # Reset progress logging timer + self.last_progress_log_time = 0 + # Reset end reached logging flag + self._end_reached_logged = False logger.debug(f"Number of leagues in data at start of display method: {len(self.leaderboard_data)}") if not self.leaderboard_data: @@ -1382,11 +1401,17 @@ class LeaderboardManager: else: # Stop scrolling when we reach the end if self.scroll_position >= self.leaderboard_image.width - width: - logger.info(f"Leaderboard reached end: scroll_position {self.scroll_position} >= {self.leaderboard_image.width - width}") + # Only log this message once per display session to avoid spam + if not self._end_reached_logged: + logger.info(f"Leaderboard reached end: scroll_position {self.scroll_position} >= {self.leaderboard_image.width - width}") + logger.info("Leaderboard scrolling stopped - reached end of content") + self._end_reached_logged = True + else: + logger.debug(f"Leaderboard reached end (throttled): scroll_position {self.scroll_position} >= {self.leaderboard_image.width - width}") + self.scroll_position = self.leaderboard_image.width - width # Signal that scrolling has stopped self.display_manager.set_scrolling_state(False) - logger.info("Leaderboard scrolling stopped - reached end of content") if self.time_over == 0: self.time_over = time.time() elif time.time() - self.time_over >= 2: @@ -1397,9 +1422,10 @@ class LeaderboardManager: elapsed_time = current_time - self._display_start_time remaining_time = self.dynamic_duration - elapsed_time - # Log scroll progress every 50 pixels to help debug (less verbose) - if self.scroll_position % 50 == 0 and self.scroll_position > 0: + # Log scroll progress every 5 seconds to help debug (throttled to reduce spam) + if current_time - self.last_progress_log_time >= self.progress_log_interval and self.scroll_position > 0: logger.info(f"Leaderboard progress: elapsed={elapsed_time:.1f}s, remaining={remaining_time:.1f}s, scroll_pos={self.scroll_position}/{self.leaderboard_image.width}px") + self.last_progress_log_time = current_time # If we have less than 2 seconds remaining, check if we can complete the content display if remaining_time < 2.0 and self.scroll_position > 0: diff --git a/src/logo_downloader.py b/src/logo_downloader.py index d9db24b2..76ceb137 100644 --- a/src/logo_downloader.py +++ b/src/logo_downloader.py @@ -101,6 +101,7 @@ class LogoDownloader: """Normalize team abbreviation for consistent filename usage.""" # Handle special characters that can cause filesystem issues normalized = abbreviation.upper() + # Replace problematic characters with safe alternatives normalized = normalized.replace('&', 'AND') normalized = normalized.replace('/', '_') @@ -114,6 +115,23 @@ class LogoDownloader: normalized = normalized.replace('|', '_') return normalized + @staticmethod + def get_logo_filename_variations(abbreviation: str) -> list: + """Get possible filename variations for a team abbreviation.""" + variations = [] + original = abbreviation.upper() + normalized = LogoDownloader.normalize_abbreviation(abbreviation) + + # Add original and normalized versions + variations.extend([f"{original}.png", f"{normalized}.png"]) + + # Special handling for known cases + if original == 'TA&M': + # TA&M has a file named TA&M.png, but normalize creates TAANDM.png + variations = [f"{original}.png", f"{normalized}.png"] + + return variations + def get_logo_directory(self, league: str) -> str: """Get the logo directory for a given league.""" return self.LOGO_DIRECTORIES.get(league, f'assets/sports/{league}_logos') diff --git a/src/music_manager.py b/src/music_manager.py index 17541c42..150845a4 100644 --- a/src/music_manager.py +++ b/src/music_manager.py @@ -56,6 +56,11 @@ class MusicManager: self.scroll_position_artist = 0 self.scroll_position_album = 0 self.title_scroll_tick = 0 + + # Track update logging throttling + self.last_track_log_time = 0 + self.last_logged_track_title = None + self.track_log_interval = 5.0 # Log track updates every 5 seconds max self.artist_scroll_tick = 0 self.album_scroll_tick = 0 self.is_music_display_active = False # New state variable @@ -212,7 +217,22 @@ class MusicManager: self.album_art_image = None display_title = self.current_track_info.get('title', 'None') - logger.info(f"({source_description}) Track info updated. Source: {self.current_source.name}. New Track: {display_title}") + + # Throttle track update logging to reduce spam + current_time = time.time() + should_log = False + + # Log if track title changed or if enough time has passed + if (display_title != self.last_logged_track_title or + current_time - self.last_track_log_time >= self.track_log_interval): + should_log = True + self.last_track_log_time = current_time + self.last_logged_track_title = display_title + + if should_log: + logger.info(f"({source_description}) Track info updated. Source: {self.current_source.name}. New Track: {display_title}") + else: + logger.debug(f"({source_description}) Track info updated (throttled). Source: {self.current_source.name}. Track: {display_title}") else: # simplified_info IS THE SAME as self.current_track_info processed_a_meaningful_update = False @@ -223,7 +243,14 @@ class MusicManager: significant_change_detected = True # First load is always significant processed_a_meaningful_update = True self.current_track_info = simplified_info - logger.info(f"({source_description}) First valid track data received (was None), marking significant.") + # Also log first valid track data with throttling + display_title = simplified_info.get('title', 'None') + current_time = time.time() + + # For first valid data, always log but update throttling variables + logger.info(f"({source_description}) First valid track data received (was None), marking significant. Track: {display_title}") + self.last_track_log_time = current_time + self.last_logged_track_title = display_title # Queueing logic - for events or activate_display syncs, not for polling. # Polling updates current_track_info directly; display() picks it up. diff --git a/src/odds_ticker_manager.py b/src/odds_ticker_manager.py index 8154586d..827f969c 100644 --- a/src/odds_ticker_manager.py +++ b/src/odds_ticker_manager.py @@ -135,6 +135,7 @@ class OddsTickerManager: self.ticker_image = None # This will hold the single, wide image self.last_display_time = 0 self._end_reached_logged = False # Track if we've already logged reaching the end + self._insufficient_time_warning_logged = False # Track if we've already logged insufficient time warning # Font setup self.fonts = self._load_fonts() @@ -1708,6 +1709,9 @@ class OddsTickerManager: self.last_update = current_time self.scroll_position = 0 self.current_game_index = 0 + # Reset logging flags when updating data + self._end_reached_logged = False + self._insufficient_time_warning_logged = False self._create_ticker_image() # Create the composite image if self.games_data: @@ -1740,6 +1744,8 @@ class OddsTickerManager: self.scroll_position = 0 # Reset the end reached logging flag self._end_reached_logged = False + # Reset the insufficient time warning logging flag + self._insufficient_time_warning_logged = False else: # Check if the display start time is too old (more than 2x the dynamic duration) current_time = time.time() @@ -1750,6 +1756,8 @@ class OddsTickerManager: self.scroll_position = 0 # Reset the end reached logging flag self._end_reached_logged = False + # Reset the insufficient time warning logging flag + self._insufficient_time_warning_logged = False logger.debug(f"Number of games in data at start of display method: {len(self.games_data)}") if not self.games_data: @@ -1892,8 +1900,13 @@ class OddsTickerManager: logger.debug(f"Sufficient time remaining ({remaining_time:.1f}s) to complete scroll ({time_to_complete:.1f}s)") else: # Not enough time, reset to beginning for clean transition - logger.warning(f"Not enough time to complete content display - remaining: {remaining_time:.1f}s, needed: {time_to_complete:.1f}s") - logger.debug(f"Resetting scroll position for clean transition") + # Only log this warning once per display session to avoid spam + if not self._insufficient_time_warning_logged: + logger.warning(f"Not enough time to complete content display - remaining: {remaining_time:.1f}s, needed: {time_to_complete:.1f}s") + logger.debug(f"Resetting scroll position for clean transition") + self._insufficient_time_warning_logged = True + else: + logger.debug(f"Resetting scroll position for clean transition (insufficient time warning already logged)") self.scroll_position = 0 # Create the visible part of the image by pasting from the ticker_image