From 4a3a82826d5e9a7c0bdcc28367f2611d3daafb08 Mon Sep 17 00:00:00 2001 From: cottongin Date: Sun, 23 Feb 2025 09:02:46 -0800 Subject: [PATCH] feat(logging): Enhance logging system with colored identifiers and error handling - Add colored and right-aligned bot identifiers in logs with consistent column width - Implement unique color assignment for each bot instance (falls back to hash-based when colors exhausted) - Add padding system to maintain uniform column alignment across all bot instances - Redirect asif library logs to ERROR.log file - Add ERROR.log to .gitignore - Improve log formatting with timestamps and bot identifiers - Implement dynamic column width adjustment when new bots join --- .gitignore | 1 + main.py | 177 ++++++++++++++++++++++++++++++++++++++++++++++------- 2 files changed, 155 insertions(+), 23 deletions(-) diff --git a/.gitignore b/.gitignore index 83b4d30..92088ae 100644 --- a/.gitignore +++ b/.gitignore @@ -34,6 +34,7 @@ config*.yaml # Logs *.log logs/ +ERROR.log # Unit test / coverage reports htmlcov/ diff --git a/main.py b/main.py index 59d7c75..18dba00 100644 --- a/main.py +++ b/main.py @@ -1,30 +1,158 @@ #!/usr/bin/env python3 -from asif import Client -import asyncio -import re -import aiohttp -import json -import time +# Set up logging configuration before imports import logging -import argparse -import yaml -from pathlib import Path -from typing import List, Optional -# Set up logging - only show important info +class AsifFilter(logging.Filter): + def filter(self, record): + # Block messages from asif module or if they start with "Joined channel" + return not (record.module == 'asif' or + record.name.startswith('asif') or + (isinstance(record.msg, str) and record.msg.startswith('Joined channel'))) + +# Set up base logging configuration logging.basicConfig( level=logging.INFO, format='%(asctime)s - %(message)s', datefmt='%H:%M:%S' ) -logger = logging.getLogger(__name__) + +# Apply filter to root logger +logging.getLogger().addFilter(AsifFilter()) + +# Also apply to asif's logger specifically +asif_logger = logging.getLogger('asif') +asif_logger.addFilter(AsifFilter()) +asif_logger.setLevel(logging.CRITICAL) +asif_logger.propagate = False + +from asif import Client + +# Set up error logging for asif +error_handler = logging.FileHandler('ERROR.log') +error_handler.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')) + +# Patch asif's Client class to use error logger +def silent_client_init(self, *args, **kwargs): + # Create a logger that writes to ERROR.log + error_logger = logging.getLogger('asif.client') + error_logger.addHandler(error_handler) + error_logger.propagate = False # Don't send to console + error_logger.setLevel(logging.INFO) # Capture all messages + + # Store the logger + self._log = error_logger + + # Call the original __init__ + original_init(self, *args, **kwargs) + +# Save original __init__ and replace it +original_init = Client.__init__ +Client.__init__ = silent_client_init + +import asyncio +import re +import aiohttp +import json +import time +import argparse +import yaml +from pathlib import Path +from typing import List, Optional + +# ANSI color codes +class Colors: + COLORS = [ + '\033[94m', # BLUE + '\033[96m', # CYAN + '\033[92m', # GREEN + '\033[93m', # YELLOW + '\033[95m', # MAGENTA + '\033[91m', # RED + ] + ENDC = '\033[0m' + BOLD = '\033[1m' + + # Track used colors + used_colors = {} # botname -> color mapping + + @classmethod + def get_color_for_bot(cls, botname: str) -> str: + """Get a consistent color for a bot based on its name.""" + # If this bot already has a color, return it + if botname in cls.used_colors: + return cls.used_colors[botname] + + # If we still have unused colors, use the next available one + unused_colors = [c for c in cls.COLORS if c not in cls.used_colors.values()] + if unused_colors: + color = unused_colors[0] + else: + # If we're out of unique colors, fall back to hash-based selection + color = cls.COLORS[hash(botname) % len(cls.COLORS)] + + cls.used_colors[botname] = color + return color + +class BotLoggerAdapter(logging.LoggerAdapter): + # Class variables to track maximum lengths + max_nick_length = 0 + max_endpoint_length = 0 + instances = [] # Keep track of all instances to update padding + + def __init__(self, logger, extra): + super().__init__(logger, extra) + botname = extra['botname'] + nick, endpoint = botname.split('@') + self.nick = nick + self.endpoint = endpoint + + # Update max lengths (without ANSI codes) + old_max_nick = BotLoggerAdapter.max_nick_length + old_max_endpoint = BotLoggerAdapter.max_endpoint_length + + BotLoggerAdapter.max_nick_length = max( + BotLoggerAdapter.max_nick_length, + len(nick) + ) + BotLoggerAdapter.max_endpoint_length = max( + BotLoggerAdapter.max_endpoint_length, + len(endpoint) + ) + + # If max lengths changed, update all existing instances + if (old_max_nick != BotLoggerAdapter.max_nick_length or + old_max_endpoint != BotLoggerAdapter.max_endpoint_length): + for instance in BotLoggerAdapter.instances: + instance.update_padding() + + # Add self to instances list + BotLoggerAdapter.instances.append(self) + + # Initial padding calculation + self.update_padding() + + def update_padding(self): + """Update the colored botname with current padding requirements.""" + # Right-align nick, then @ symbol, then colored endpoint + nick_padding = " " * (BotLoggerAdapter.max_nick_length - len(self.nick)) + endpoint_padding = " " * (BotLoggerAdapter.max_endpoint_length - len(self.endpoint)) + self.colored_botname = f"{nick_padding}{self.nick}@{Colors.BOLD}{Colors.get_color_for_bot(self.nick+'@'+self.endpoint)}{self.endpoint}{Colors.ENDC}{endpoint_padding}" + + def process(self, msg, kwargs): + return f'[{self.colored_botname}] {msg}', kwargs class IcecastBot: def __init__(self, config_path: Optional[str] = None): # Load config self.config = self.load_config(config_path) + # Set up bot-specific logger + self.logger = BotLoggerAdapter( + logging.getLogger(__name__), + {'botname': f'{self.config["irc"]["nick"]}@{self.config["stream"]["endpoint"]}'} + ) + # Initialize IRC bot with config self.bot = Client( host=self.config['irc']['host'], @@ -58,7 +186,9 @@ class IcecastBot: with open(config_path) as f: config = yaml.safe_load(f) except FileNotFoundError: - logger.warning(f"Config file not found at {config_path}, using defaults") + # Create a temporary logger for config loading + temp_logger = logging.getLogger(__name__) + temp_logger.warning(f"Config file not found at {config_path}, using defaults") config = { 'irc': {}, 'stream': {}, @@ -79,14 +209,15 @@ class IcecastBot: async def connected(): try: self.channel = await self.bot.join(self.channel_name) - logger.info(f"Connected to IRC and joined {self.channel_name}") + self.logger.info(f"Connected to IRC and joined {self.channel_name}") except Exception as e: - logger.error(f"Error joining channel: {e}") + self.logger.error(f"Error joining channel: {e}") asyncio.create_task(self.monitor_metadata()) @self.bot.on_join() async def on_join(channel): + # Silently store the channel without logging if not self.channel: self.channel = channel @@ -118,7 +249,7 @@ class IcecastBot: return "Unable to fetch metadata" except Exception as e: - logger.error(f"Error fetching JSON metadata: {e}") + self.logger.error(f"Error fetching JSON metadata: {e}") return "Error fetching metadata" async def monitor_metadata(self): @@ -140,7 +271,7 @@ class IcecastBot: stderr=asyncio.subprocess.PIPE ) - logger.info("Started stream monitoring") + self.logger.info("Started stream monitoring") buffer = b"" last_json_check = time.time() @@ -156,14 +287,14 @@ class IcecastBot: # Periodic health check if current_time - self.last_health_check >= self.health_check_interval: - logger.info("Monitor status: Active - processing stream data") + self.logger.info("Monitor status: Active - processing stream data") self.last_health_check = current_time # Look for metadata marker but fetch from JSON if b"StreamTitle='" in buffer: new_song = await self.fetch_json_metadata() if new_song and new_song != self.current_song and "Unable to fetch metadata" not in new_song: - logger.info(f"Now Playing: {new_song}") + self.logger.info(f"Now Playing: {new_song}") self.current_song = new_song await self.announce_song(new_song) @@ -181,7 +312,7 @@ class IcecastBot: if "Unable to fetch metadata" in new_song: break if new_song and new_song != self.current_song: - logger.info(f"Now Playing (fallback): {new_song}") + self.logger.info(f"Now Playing (fallback): {new_song}") self.current_song = new_song await self.announce_song(new_song) last_json_check = current_time @@ -189,11 +320,11 @@ class IcecastBot: await asyncio.sleep(0.1) await process.wait() - logger.warning("Stream monitor ended, restarting...") + self.logger.warning("Stream monitor ended, restarting...") await asyncio.sleep(5) except Exception as e: - logger.error(f"Stream monitor error: {e}") + self.logger.error(f"Stream monitor error: {e}") await asyncio.sleep(5) async def announce_song(self, song: str): @@ -202,7 +333,7 @@ class IcecastBot: if self.channel and self.should_announce_song(song): await self.channel.message(self.reply.format(song=song)) except Exception as e: - logger.error(f"Error announcing song: {e}") + self.logger.error(f"Error announcing song: {e}") async def start(self): await self.bot.run()