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

@@ -34,6 +34,7 @@ config*.yaml
 # Logs
 *.log
 logs/
+ERROR.log
 
 # Unit test / coverage reports
 htmlcov/

main.py

@@ -1,30 +1,158 @@
 #!/usr/bin/env python3
 
-from asif import Client
+# Set up logging configuration before imports
-import asyncio
-import re
-import aiohttp
-import json
-import time
 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()