SXXXXXXX_FlightMonitor/flightmonitor/utils/logger.py

481 lines
24 KiB
Python

# FlightMonitor/utils/logger.py
import logging
import logging.handlers # For RotatingFileHandler
import tkinter as tk
from tkinter.scrolledtext import ScrolledText
from queue import Queue, Empty as QueueEmpty # Renamed for clarity
from typing import Optional, Dict, Any
# --- Module-level globals for the new centralized logging queue system ---
_global_log_queue: Optional[Queue[logging.LogRecord]] = None
_actual_console_handler: Optional[logging.StreamHandler] = None
_actual_file_handler: Optional[logging.handlers.RotatingFileHandler] = None
_actual_tkinter_handler: Optional["TkinterTextHandler"] = None # Forward declaration
_log_processor_after_id: Optional[str] = None
_logging_system_active: bool = False
_tk_root_instance_for_processing: Optional[tk.Tk] = None
_base_formatter: Optional[logging.Formatter] = None # Store the main formatter
# Interval for polling the global log queue by the GUI thread processor
GLOBAL_LOG_QUEUE_POLL_INTERVAL_MS = 50
class TkinterTextHandler(logging.Handler):
"""
A logging handler that directs log messages to a Tkinter Text widget.
This handler itself is now called by _process_global_log_queue,
which runs in the GUI thread. Its internal queue is for batching updates
to the Text widget if needed, or could be simplified later.
"""
def __init__(
self,
text_widget: tk.Text, # ScrolledText is a tk.Text
level_colors: Dict[int, str],
# root_tk_instance and queue_poll_interval_ms for its own internal queue might be redundant
# if _process_global_log_queue handles batching, but kept for now.
# For now, this handler will still use its own internal queue and after loop for safety.
root_tk_instance_for_widget_update: tk.Tk,
internal_poll_interval_ms: int = 100
):
super().__init__()
self.text_widget = text_widget
self.level_colors = level_colors
self._is_active = True # Internal active state for this specific handler
self._widget_update_queue = Queue()
self._root_for_widget_update = root_tk_instance_for_widget_update
self._internal_poll_interval_ms = internal_poll_interval_ms
self._internal_after_id: Optional[str] = None
if not (
self.text_widget
and hasattr(self.text_widget, "winfo_exists")
and self.text_widget.winfo_exists()
):
print("ERROR: TkinterTextHandler initialized with an invalid or non-existent text_widget.", flush=True)
self._is_active = False
return
if not (
self._root_for_widget_update
and hasattr(self._root_for_widget_update, "winfo_exists")
and self._root_for_widget_update.winfo_exists()
):
print("ERROR: TkinterTextHandler initialized with an invalid root for widget update.", flush=True)
self._is_active = False
return
if self._is_active:
self._configure_tags()
self._process_widget_update_queue() # Start its own update loop
def _configure_tags(self):
if not self._is_active or not self.text_widget.winfo_exists(): return
for level, color_value in self.level_colors.items():
level_name = logging.getLevelName(level)
if color_value:
try:
self.text_widget.tag_config(level_name, foreground=color_value)
except tk.TclError:
print(f"Warning: Could not configure tag for {level_name} in TkinterTextHandler.", flush=True)
def emit(self, record: logging.LogRecord):
# This emit is called by _process_global_log_queue (already in GUI thread)
if not self._is_active or not self.text_widget.winfo_exists():
# This case should ideally not happen if setup is correct
print(f"DEBUG: TkinterTextHandler.emit called but inactive or widget gone. Record: {record.getMessage()}", flush=True)
return
try:
msg = self.format(record) # Format the record using the formatter set on this handler
level_name = record.levelname
# Put in its own queue for batched widget updates
self._widget_update_queue.put_nowait((level_name, msg))
except Exception as e:
print(f"Error in TkinterTextHandler.emit (to internal queue): {e}", flush=True)
def _process_widget_update_queue(self):
if not self._is_active or \
not self.text_widget.winfo_exists() or \
not self._root_for_widget_update.winfo_exists():
self._is_active = False
if self._internal_after_id and self._root_for_widget_update.winfo_exists():
try: self._root_for_widget_update.after_cancel(self._internal_after_id)
except Exception: pass
self._internal_after_id = None
# print("DEBUG: TkinterTextHandler._process_widget_update_queue stopping (inactive/widget gone).", flush=True)
return
had_messages = False
try:
while not self._widget_update_queue.empty():
had_messages = True
level_name, msg = self._widget_update_queue.get_nowait()
if self.text_widget.winfo_exists():
self.text_widget.configure(state=tk.NORMAL)
self.text_widget.insert(tk.END, msg + "\n", (level_name,))
self.text_widget.configure(state=tk.DISABLED)
else: # Widget destroyed during processing
self._is_active = False; break
self._widget_update_queue.task_done()
if had_messages and self.text_widget.winfo_exists():
self.text_widget.see(tk.END)
except tk.TclError as e_tcl:
print(f"TkinterTextHandler TclError during widget update: {e_tcl}. Handler stopping.", flush=True)
self._is_active = False
except Exception as e_update:
print(f"Unexpected error updating TkinterTextHandler widget: {e_update}. Handler stopping.", flush=True)
self._is_active = False
if self._is_active and self._root_for_widget_update.winfo_exists():
self._internal_after_id = self._root_for_widget_update.after(
self._internal_poll_interval_ms, self._process_widget_update_queue
)
else: # Ensure it's cleaned up if we are stopping
if self._internal_after_id and self._root_for_widget_update.winfo_exists():
try: self._root_for_widget_update.after_cancel(self._internal_after_id)
except Exception: pass
self._internal_after_id = None
def close(self):
print("INFO: TkinterTextHandler close called.", flush=True)
self._is_active = False
if self._internal_after_id and hasattr(self, '_root_for_widget_update') and \
self._root_for_widget_update and self._root_for_widget_update.winfo_exists():
try:
self._root_for_widget_update.after_cancel(self._internal_after_id)
except Exception: pass
self._internal_after_id = None
# Drain its internal queue
while not self._widget_update_queue.empty():
try: self._widget_update_queue.get_nowait(); self._widget_update_queue.task_done()
except Exception: break
super().close()
class QueuePuttingHandler(logging.Handler):
"""
A simple handler that puts any received LogRecord into a global queue.
"""
def __init__(self, handler_queue: Queue[logging.LogRecord]):
super().__init__()
self.handler_queue = handler_queue
def emit(self, record: logging.LogRecord):
try:
# We can choose to make a copy of the record if there's any concern
# about it being modified before processing, though typically not an issue.
# For now, put the original record.
self.handler_queue.put_nowait(record)
except queue.Full:
print(f"CRITICAL: Global log queue is full! Log record for '{record.name}' might be lost.", flush=True)
except Exception as e:
print(f"CRITICAL: Error putting log record into global queue: {e}", flush=True)
def _process_global_log_queue():
"""
GUI Thread: Periodically processes LogRecords from the _global_log_queue
and dispatches them to the actual configured handlers.
"""
global _logging_system_active, _log_processor_after_id
# print(f"DEBUG: _process_global_log_queue called. Active: {_logging_system_active}", flush=True) # Can be very verbose
if not _logging_system_active:
if _log_processor_after_id and _tk_root_instance_for_processing and _tk_root_instance_for_processing.winfo_exists():
try: _tk_root_instance_for_processing.after_cancel(_log_processor_after_id)
except Exception: pass
_log_processor_after_id = None
return
if not (_tk_root_instance_for_processing and _tk_root_instance_for_processing.winfo_exists()):
# print("DEBUG: Global log queue processor: Tk root instance gone. Stopping.", flush=True)
_logging_system_active = False # Stop if root is gone
_log_processor_after_id = None
return
processed_count = 0
try:
while _global_log_queue and not _global_log_queue.empty():
if not _logging_system_active: break # Check before processing each item
try:
record = _global_log_queue.get_nowait()
processed_count +=1
# Dispatch to actual handlers
if _actual_console_handler:
try: _actual_console_handler.handle(record)
except Exception as e_con: print(f"Error in console_handler.handle: {e_con}", flush=True)
if _actual_file_handler:
try: _actual_file_handler.handle(record)
except Exception as e_file: print(f"Error in file_handler.handle: {e_file}", flush=True)
if _actual_tkinter_handler:
try: _actual_tkinter_handler.handle(record)
except Exception as e_tk: print(f"Error in tkinter_handler.handle: {e_tk}", flush=True)
_global_log_queue.task_done()
except QueueEmpty:
break # Should not happen due to outer loop condition, but defensive
except Exception as e_proc_item:
print(f"Error processing a log item from global queue: {e_proc_item}", flush=True)
# Potentially re-queue or log to a failsafe if critical
except Exception as e_outer_loop:
print(f"Critical error in _process_global_log_queue outer loop: {e_outer_loop}", flush=True)
if _logging_system_active and _tk_root_instance_for_processing.winfo_exists():
_log_processor_after_id = _tk_root_instance_for_processing.after(
GLOBAL_LOG_QUEUE_POLL_INTERVAL_MS, _process_global_log_queue
)
# else: print(f"DEBUG: Not rescheduling _process_global_log_queue. Active: {_logging_system_active}", flush=True)
def setup_logging(
gui_log_widget: Optional[tk.Text] = None,
root_tk_instance: Optional[tk.Tk] = None,
logging_config_dict: Optional[Dict[str, Any]] = None,
):
global _global_log_queue, _actual_console_handler, _actual_file_handler
global _actual_tkinter_handler, _logging_system_active, _tk_root_instance_for_processing
global _log_processor_after_id, _base_formatter
print("INFO: Configuring centralized queued logging system...", flush=True)
if _logging_system_active:
print("INFO: Logging system already active. Shutting down existing to reconfigure.", flush=True)
shutdown_logging_system() # Ensure clean state before re-setup
if logging_config_dict is None:
print("Warning: No logging_config_dict. Using basic console-only defaults for queued logging.", flush=True)
logging_config_dict = {
"default_root_level": logging.INFO, "specific_levels": {},
"format": "%(asctime)s [%(levelname)-8s] %(name)-25s : %(message)s",
"date_format": "%Y-%m-%d %H:%M:%S",
"colors": {logging.INFO: "black", logging.DEBUG: "blue", logging.WARNING:"orange", logging.ERROR:"red", logging.CRITICAL:"purple"},
"queue_poll_interval_ms": 100, # For TkinterTextHandler's internal queue
"enable_console": True, "enable_file": False,
}
# --- Extract Config ---
root_log_level = logging_config_dict.get("default_root_level", logging.INFO)
specific_levels = logging_config_dict.get("specific_levels", {})
log_format_str = logging_config_dict.get("format", "%(asctime)s [%(levelname)-8s] %(name)-25s : %(message)s")
log_date_format_str = logging_config_dict.get("date_format", "%Y-%m-%d %H:%M:%S")
level_colors = logging_config_dict.get("colors", {})
tkinter_handler_poll_ms = logging_config_dict.get("queue_poll_interval_ms", 100) # For TkinterTextHandler's internal queue
enable_console = logging_config_dict.get("enable_console", True)
enable_file = logging_config_dict.get("enable_file", False)
_base_formatter = logging.Formatter(log_format_str, datefmt=log_date_format_str)
_global_log_queue = Queue() # Initialize the global queue for LogRecords
_tk_root_instance_for_processing = root_tk_instance # Store for the after() loop
# --- Configure Root Logger ---
root_logger = logging.getLogger()
# Remove ALL existing handlers from the root logger to ensure clean state
for handler in root_logger.handlers[:]:
try:
handler.close() # Close handler first
root_logger.removeHandler(handler)
print(f"DEBUG: Removed and closed old handler from root: {handler}", flush=True)
except Exception as e_rem:
print(f"Error removing/closing old handler {handler}: {e_rem}", flush=True)
root_logger.handlers = [] # Ensure it's empty
root_logger.setLevel(root_log_level)
print(f"INFO: Root logger level set to {logging.getLevelName(root_logger.level)}.", flush=True)
# --- Configure Specific Logger Levels ---
for logger_name, level in specific_levels.items():
named_logger = logging.getLogger(logger_name)
named_logger.setLevel(level)
# Ensure propagation is on if they are not root, or if they should also go to root's QueuePuttingHandler
named_logger.propagate = True
print(f"INFO: Logger '{logger_name}' level set to {logging.getLevelName(named_logger.level)}.", flush=True)
# --- Create Actual Handlers (but don't add to root logger yet) ---
if enable_console:
try:
_actual_console_handler = logging.StreamHandler() # Defaults to stderr
_actual_console_handler.setFormatter(_base_formatter)
_actual_console_handler.setLevel(logging.DEBUG) # Let console handler decide based on record level
print("INFO: Actual ConsoleHandler created.", flush=True)
except Exception as e:
print(f"ERROR: Failed to create actual ConsoleHandler: {e}", flush=True)
_actual_console_handler = None
if enable_file:
try:
file_path = logging_config_dict.get("file_path", "flight_monitor_app.log")
file_max_bytes = logging_config_dict.get("file_max_bytes", 5 * 1024 * 1024) # 5MB
file_backup_count = logging_config_dict.get("file_backup_count", 3)
_actual_file_handler = logging.handlers.RotatingFileHandler(
file_path, maxBytes=file_max_bytes, backupCount=file_backup_count, encoding='utf-8'
)
_actual_file_handler.setFormatter(_base_formatter)
_actual_file_handler.setLevel(logging.DEBUG) # Let file handler decide
print(f"INFO: Actual RotatingFileHandler created for '{file_path}'.", flush=True)
except Exception as e:
print(f"ERROR: Failed to create actual FileHandler for '{file_path}': {e}", flush=True)
_actual_file_handler = None
if gui_log_widget and root_tk_instance:
is_widget_valid = (
isinstance(gui_log_widget, (tk.Text, ScrolledText)) and
hasattr(gui_log_widget, "winfo_exists") and gui_log_widget.winfo_exists()
)
if is_widget_valid:
try:
_actual_tkinter_handler = TkinterTextHandler(
text_widget=gui_log_widget,
level_colors=level_colors,
root_tk_instance_for_widget_update=root_tk_instance, # Pass root for its own after loop
internal_poll_interval_ms=tkinter_handler_poll_ms
)
_actual_tkinter_handler.setFormatter(_base_formatter)
_actual_tkinter_handler.setLevel(logging.DEBUG) # Let Tkinter handler decide
print("INFO: Actual TkinterTextHandler created.", flush=True)
except Exception as e:
print(f"ERROR: Failed to create actual TkinterTextHandler: {e}", flush=True)
_actual_tkinter_handler = None
else:
print("ERROR: GUI log widget invalid or non-existent, cannot create TkinterTextHandler.", flush=True)
elif gui_log_widget and not root_tk_instance:
print("WARNING: GUI log widget provided, but root_tk_instance missing for TkinterTextHandler.", flush=True)
# --- Add ONLY the QueuePuttingHandler to the root logger ---
if _global_log_queue is not None:
queue_putter = QueuePuttingHandler(handler_queue=_global_log_queue)
queue_putter.setLevel(logging.DEBUG) # Capture all messages from root level downwards
root_logger.addHandler(queue_putter)
print(f"INFO: QueuePuttingHandler added to root logger. All logs will go to global queue.", flush=True)
else:
print("CRITICAL ERROR: Global log queue not initialized. Logging will not function correctly.", flush=True)
# Fallback to basic console if queue setup failed badly
if not _actual_console_handler: # If even this failed
_bf = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
_ch = logging.StreamHandler()
_ch.setFormatter(_bf)
root_logger.addHandler(_ch)
print("CRITICAL: Added basic emergency console logger.", flush=True)
# --- Start the global log queue processor (if root_tk_instance is available) ---
_logging_system_active = True
if _tk_root_instance_for_processing and _tk_root_instance_for_processing.winfo_exists():
if _log_processor_after_id: # Cancel previous if any (shouldn't happen if shutdown was called)
try: _tk_root_instance_for_processing.after_cancel(_log_processor_after_id)
except Exception: pass
_log_processor_after_id = _tk_root_instance_for_processing.after(
GLOBAL_LOG_QUEUE_POLL_INTERVAL_MS, _process_global_log_queue
)
print(f"INFO: Global log queue processor scheduled with Tkinter.after (ID: {_log_processor_after_id}).", flush=True)
elif root_tk_instance is None and (gui_log_widget is not None or enable_file or enable_console):
# This case means we want logging but have no Tkinter root to schedule the queue processor.
# This is problematic for GUI logging. For console/file, logs will just queue up.
# A dedicated thread could process the queue if no Tkinter available, but adds complexity.
print("WARNING: No Tkinter root instance provided to setup_logging. "
"Logs will be queued but not processed by GUI/File/Console handlers unless _process_global_log_queue is run manually or by another mechanism.", flush=True)
elif not (enable_console or enable_file or gui_log_widget):
print("INFO: No log output handlers (console, file, gui) are enabled. Logs will be queued but not displayed.", flush=True)
print("INFO: Centralized queued logging system setup complete.", flush=True)
# Test log
test_logger = logging.getLogger("FlightMonitor.LoggerTest")
test_logger.info("Logging system initialized. This is a test message from setup_logging.")
def get_logger(name: str) -> logging.Logger:
"""
Retrieves a logger instance by name.
Module-level loggers should use `get_logger(__name__)`.
"""
return logging.getLogger(name)
def shutdown_logging_system():
"""
Shuts down the centralized logging system, processing remaining logs
and closing actual handlers.
"""
global _logging_system_active, _log_processor_after_id
global _actual_console_handler, _actual_file_handler, _actual_tkinter_handler
global _global_log_queue, _tk_root_instance_for_processing
print("INFO: Initiating shutdown of centralized logging system...", flush=True)
_logging_system_active = False # Signal processor to stop
if _log_processor_after_id and _tk_root_instance_for_processing and _tk_root_instance_for_processing.winfo_exists():
try:
_tk_root_instance_for_processing.after_cancel(_log_processor_after_id)
print("INFO: Cancelled global log queue processor task.", flush=True)
except Exception as e_cancel:
print(f"Warning: Error cancelling log processor task: {e_cancel}", flush=True)
_log_processor_after_id = None
# Attempt to process any remaining logs in the global queue
print("INFO: Processing any remaining logs in the global queue before full shutdown...", flush=True)
if _global_log_queue:
final_processed_count = 0
while not _global_log_queue.empty():
try:
record = _global_log_queue.get_nowait()
final_processed_count += 1
if _actual_console_handler: _actual_console_handler.handle(record)
if _actual_file_handler: _actual_file_handler.handle(record)
if _actual_tkinter_handler: _actual_tkinter_handler.handle(record)
_global_log_queue.task_done()
except QueueEmpty:
break
except Exception as e_final_proc:
print(f"Error during final log processing: {e_final_proc}", flush=True)
break # Stop if error during final processing
if final_processed_count > 0:
print(f"INFO: Processed {final_processed_count} remaining log messages.", flush=True)
else:
print("INFO: No remaining log messages in global queue to process.", flush=True)
# Close actual handlers
if _actual_tkinter_handler:
try:
print("INFO: Closing actual TkinterTextHandler.", flush=True)
_actual_tkinter_handler.close()
except Exception as e: print(f"Error closing TkinterTextHandler: {e}", flush=True)
_actual_tkinter_handler = None
if _actual_console_handler:
try:
print("INFO: Closing actual ConsoleHandler.", flush=True)
_actual_console_handler.close()
except Exception as e: print(f"Error closing ConsoleHandler: {e}", flush=True)
_actual_console_handler = None
if _actual_file_handler:
try:
print("INFO: Closing actual FileHandler.", flush=True)
_actual_file_handler.close()
except Exception as e: print(f"Error closing FileHandler: {e}", flush=True)
_actual_file_handler = None
# Clear the root logger's handlers (should only be the QueuePuttingHandler)
root_logger = logging.getLogger()
for handler in root_logger.handlers[:]:
try:
if isinstance(handler, QueuePuttingHandler): # Specifically target our handler
handler.close()
root_logger.removeHandler(handler)
print(f"INFO: Removed and closed QueuePuttingHandler: {handler}", flush=True)
except Exception as e_rem_qph:
print(f"Error removing QueuePuttingHandler: {e_rem_qph}", flush=True)
_global_log_queue = None # Allow it to be garbage collected
_tk_root_instance_for_processing = None # Clear reference
_base_formatter = None
print("INFO: Centralized logging system shutdown complete.", flush=True)