diff --git a/src/display_controller.py b/src/display_controller.py index 5a341902..01877279 100644 --- a/src/display_controller.py +++ b/src/display_controller.py @@ -1137,6 +1137,29 @@ class DisplayController: remaining = self.on_demand_expires_at - time.time() return max(0.0, remaining) + def _publish_current_mode_state(self) -> None: + """Publish the currently active display mode/plugin to cache for the web UI.""" + try: + state = { + 'mode': self.current_display_mode, + 'plugin_id': self.mode_to_plugin_id.get(self.current_display_mode), + 'mode_index': self.current_mode_index, + 'total_modes': len(self.available_modes), + 'on_demand_active': self.on_demand_active, + 'is_display_active': self.is_display_active, + 'last_updated': time.time(), + } + self.cache_manager.set('display_current_state', state) + self._last_published_mode = self.current_display_mode + except (OSError, RuntimeError, ValueError, TypeError) as err: + logger.error("Failed to publish current display state: %s", err, exc_info=True) + + def _publish_current_mode_state_if_changed(self) -> None: + """Publish current mode state only when it actually changed, to avoid + writing to the shared cache on every render tick.""" + if self.current_display_mode != getattr(self, '_last_published_mode', None): + self._publish_current_mode_state() + def _publish_on_demand_state(self) -> None: """Publish current on-demand state to cache for external consumers.""" try: @@ -1656,6 +1679,7 @@ class DisplayController: logger.info("Starting display with cached data (fast startup mode)") self.current_display_mode = self.available_modes[self.current_mode_index] if self.available_modes else 'none' logger.info(f"Initial mode set to: {self.current_display_mode} (index: {self.current_mode_index}, total modes: {len(self.available_modes)})") + self._publish_current_mode_state() while True: # Apply plugin enable/disable edits saved via the web UI. The @@ -1716,9 +1740,11 @@ class DisplayController: logger.debug(f"Error clearing display when inactive: {e}") logger.info(f"Display not active (is_display_active={self.is_display_active}), sleeping...") + self._publish_current_mode_state() self._sleep_with_plugin_updates(60) continue + self._publish_current_mode_state_if_changed() logger.debug("Display active, processing mode: %s", self.current_display_mode) # Plugins update on their own schedules - no forced sync updates needed diff --git a/src/logging_config.py b/src/logging_config.py index 4211e861..48eba67c 100644 --- a/src/logging_config.py +++ b/src/logging_config.py @@ -139,23 +139,41 @@ def setup_logging( sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n") -def get_logger(name: str, plugin_id: Optional[str] = None) -> logging.Logger: +class PluginLoggerAdapter(logging.LoggerAdapter): + """LoggerAdapter that stamps every record with its plugin_id. + + A plain `logging.Logger` attribute (the old approach) is never copied + onto individual `LogRecord`s, so `ContextualFormatter`/`StructuredFormatter` + only ever saw `plugin_id` on calls that explicitly passed + `extra={'plugin_id': ...}` (i.e. `log_with_context`). This adapter injects + it into `extra` on every call, so `self.logger.info(...)` in plugin code + is tagged automatically. + """ + + def process(self, msg, kwargs): + extra = dict(kwargs.get('extra') or {}) + extra.setdefault('plugin_id', self.extra.get('plugin_id')) + kwargs['extra'] = extra + return msg, kwargs + + +def get_logger(name: str, plugin_id: Optional[str] = None): """ Get a logger with consistent configuration. - + Args: name: Logger name (typically __name__) plugin_id: Optional plugin ID for automatic context - + Returns: - Configured logger instance + Configured logger instance (or a PluginLoggerAdapter when plugin_id + is given, which supports the same .debug/.info/.warning/.error API) """ logger = logging.getLogger(name) - - # Add plugin_id as attribute for formatters + if plugin_id: - logger.plugin_id = plugin_id - + return PluginLoggerAdapter(logger, {'plugin_id': plugin_id}) + return logger diff --git a/src/plugin_system/base_plugin.py b/src/plugin_system/base_plugin.py index a990ecd9..54759855 100644 --- a/src/plugin_system/base_plugin.py +++ b/src/plugin_system/base_plugin.py @@ -86,7 +86,9 @@ class BasePlugin(ABC): self.display_manager: Any = display_manager self.cache_manager: Any = cache_manager self.plugin_manager: Any = plugin_manager - self.logger: logging.Logger = get_logger(f"plugin.{plugin_id}", plugin_id=plugin_id) + # get_logger returns a PluginLoggerAdapter here (plugin_id given), which + # stamps every record with plugin_id so it survives into formatted output. + self.logger = get_logger(f"plugin.{plugin_id}", plugin_id=plugin_id) self.enabled: bool = config.get("enabled", True) self.logger.info("Initialized plugin: %s", plugin_id) diff --git a/web_interface/blueprints/api_v3.py b/web_interface/blueprints/api_v3.py index 9777ed4a..e6846ceb 100644 --- a/web_interface/blueprints/api_v3.py +++ b/web_interface/blueprints/api_v3.py @@ -7022,6 +7022,29 @@ def list_plugin_assets(): logger.error('Unhandled exception', exc_info=True) return jsonify({'status': 'error', 'message': 'An error occurred; see logs for details'}), 500 +@api_v3.route('/display/current-status', methods=['GET']) +def get_current_display_status(): + """Return the display mode/plugin currently intended to be shown. + + Published by the display process (display_controller._publish_current_mode_state) + to the shared cache whenever the active mode changes, so the web UI (e.g. the + System Logs page) can show what's on screen without querying the display + process directly. + """ + try: + cache = _ensure_cache_manager() + state = cache.get('display_current_state', max_age=120) + if state is None: + state = { + 'mode': None, + 'plugin_id': None, + 'last_updated': None, + } + return jsonify({'status': 'success', 'data': state}) + except Exception: + logger.error('Error in get_current_display_status', exc_info=True) + return jsonify({'status': 'error', 'message': 'An error occurred; see logs for details'}), 500 + @api_v3.route('/logs', methods=['GET']) def get_logs(): """Get system logs from journalctl""" diff --git a/web_interface/templates/v3/partials/logs.html b/web_interface/templates/v3/partials/logs.html index cb2cff73..9e7794de 100644 --- a/web_interface/templates/v3/partials/logs.html +++ b/web_interface/templates/v3/partials/logs.html @@ -4,6 +4,17 @@

View real-time logs from the LED matrix service for troubleshooting.

+ + +
@@ -27,6 +38,11 @@ + + +
@@ -139,6 +155,7 @@ window._filteredLogs = []; const realtimeToggle = document.getElementById('log-realtime-toggle'); const refreshBtn = document.getElementById('refresh-logs-btn'); const levelFilter = document.getElementById('log-level-filter'); + const pluginFilter = document.getElementById('log-plugin-filter'); const searchInput = document.getElementById('log-search'); const autoscrollToggle = document.getElementById('log-autoscroll'); const clearBtn = document.getElementById('clear-logs-btn'); @@ -160,6 +177,11 @@ window._filteredLogs = []; levelFilter.parentNode.replaceChild(newFilter, levelFilter); newFilter.addEventListener('change', filterLogs); } + if (pluginFilter) { + const newFilter = pluginFilter.cloneNode(true); + pluginFilter.parentNode.replaceChild(newFilter, pluginFilter); + newFilter.addEventListener('change', filterLogs); + } if (searchInput) { const newInput = searchInput.cloneNode(true); searchInput.parentNode.replaceChild(newInput, searchInput); @@ -180,6 +202,24 @@ window._filteredLogs = []; downloadBtn.parentNode.replaceChild(newBtn, downloadBtn); newBtn.addEventListener('click', downloadLogs); } + const currentPluginFilterBtn = document.getElementById('current-plugin-filter-btn'); + if (currentPluginFilterBtn) { + const newBtn = currentPluginFilterBtn.cloneNode(true); + currentPluginFilterBtn.parentNode.replaceChild(newBtn, currentPluginFilterBtn); + newBtn.addEventListener('click', function() { + const pluginFilterEl = document.getElementById('log-plugin-filter'); + if (pluginFilterEl && window._currentPluginId) { + pluginFilterEl.value = window._currentPluginId; + filterLogs(); + } + }); + } + + refreshCurrentPluginStatus(); + if (window._currentPluginPollTimer) { + clearInterval(window._currentPluginPollTimer); + } + window._currentPluginPollTimer = setInterval(refreshCurrentPluginStatus, 5000); // Handle window resize for responsive height window.addEventListener('resize', function() { @@ -284,37 +324,25 @@ function processLogs(logsText, append = false) { // Skip empty lines if (!line.trim()) return; - // Try to parse journalctl format: "MMM DD HH:MM:SS hostname service[pid]: message" - // Example: "Oct 13 14:23:45 raspberrypi ledmatrix[1234]: INFO: Starting display" - + // journalctl (--output=short-iso) emits: "YYYY-MM-DDTHH:MM:SS+ZZZZ hostname service[pid]: message" + // Example: "2024-01-15T10:23:45+0000 raspberrypi ledmatrix[1234]: INFO - plugin.nhl_scoreboard - [Plugin: nhl_scoreboard] Updated scores" + // Also accept the older syslog-style "MMM DD HH:MM:SS" timestamp for compatibility. + let timestamp = ''; let level = 'INFO'; let message = line; - - // Extract timestamp (first part before hostname) - const timestampMatch = line.match(/^([A-Z][a-z]{2}\s+\d{1,2}\s+\d{2}:\d{2}:\d{2})/); - if (timestampMatch) { - timestamp = timestampMatch[1]; - - // Find the message part (after service name and pid) - const messageMatch = line.match(/:\s*(.+)$/); - if (messageMatch) { - message = messageMatch[1]; - - // Detect log level from message - if (message.match(/\b(ERROR|CRITICAL|FATAL)\b/i)) { - level = 'ERROR'; - } else if (message.match(/\b(WARNING|WARN)\b/i)) { - level = 'WARNING'; - } else if (message.match(/\bDEBUG\b/i)) { - level = 'DEBUG'; - } else if (message.match(/\bINFO\b/i)) { - level = 'INFO'; - } - - // Clean up level prefix from message if it exists - message = message.replace(/^(ERROR|WARNING|WARN|INFO|DEBUG):\s*/i, ''); - } + let plugin = ''; + let rest = null; + + const isoMatch = line.match(/^(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?(?:[+-]\d{2}:?\d{2}|Z))\s+(.*)$/); + const syslogMatch = !isoMatch && line.match(/^([A-Z][a-z]{2}\s+\d{1,2}\s+\d{2}:\d{2}:\d{2})\s+(.*)$/); + + if (isoMatch) { + timestamp = isoMatch[1]; + rest = isoMatch[2]; + } else if (syslogMatch) { + timestamp = syslogMatch[1]; + rest = syslogMatch[2]; } else { // If no timestamp, use current time timestamp = new Date().toLocaleString('en-US', { @@ -327,14 +355,58 @@ function processLogs(logsText, append = false) { }); } + if (rest !== null) { + // Find the message part (after hostname + service name/pid) + const messageMatch = rest.match(/:\s*(.+)$/); + if (messageMatch) { + message = messageMatch[1]; + + // Detect log level from message + if (message.match(/\b(ERROR|CRITICAL|FATAL)\b/i)) { + level = 'ERROR'; + } else if (message.match(/\b(WARNING|WARN)\b/i)) { + level = 'WARNING'; + } else if (message.match(/\bDEBUG\b/i)) { + level = 'DEBUG'; + } else if (message.match(/\bINFO\b/i)) { + level = 'INFO'; + } + + // Clean up level prefix from message if it exists + message = message.replace(/^(ERROR|WARNING|WARN|INFO|DEBUG)\s*[-:]\s*/i, ''); + + // journalctl already carries its own timestamp; strip the app's + // internal "YYYY-MM-DD HH:MM:SS.mmm - LEVEL - logger.name - " + // prefix (see ContextualFormatter in src/logging_config.py) so + // it isn't duplicated in the displayed message. + message = message.replace( + /^\d{4}-\d{2}-\d{2}\s+\d{2}:\d{2}:\d{2}(?:\.\d+)?\s*-\s*(ERROR|WARNING|WARN|INFO|DEBUG|CRITICAL)\s*-\s*[\w.]+\s*-\s*/i, + '' + ); + + // Extract the "[Plugin: ]" context tag emitted by + // ContextualFormatter for every plugin logger (see + // src/logging_config.py PluginLoggerAdapter), and pull it out + // of the displayed message into its own field. + const pluginMatch = message.match(/^\[Plugin:\s*([^\]]+)\]\s*/); + if (pluginMatch) { + plugin = pluginMatch[1].trim(); + message = message.replace(pluginMatch[0], ''); + } + } else { + message = rest; + } + } + const logEntry = { timestamp: timestamp, level: level, + plugin: plugin, message: message, raw: line, id: Date.now() + Math.random() }; - + // Don't add duplicate entries when appending if (!append || !window._allLogs.find(log => log.raw === line)) { window._allLogs.push(logEntry); @@ -346,9 +418,26 @@ function processLogs(logsText, append = false) { window._allLogs = window._allLogs.slice(-window._MAX_LOGS); } + updatePluginFilterOptions(); filterLogs(); } +function updatePluginFilterOptions() { + const pluginFilterEl = document.getElementById('log-plugin-filter'); + if (!pluginFilterEl) return; + + const previousValue = pluginFilterEl.value; + const plugins = Array.from(new Set(window._allLogs.map(log => log.plugin).filter(Boolean))).sort(); + + pluginFilterEl.innerHTML = '' + + plugins.map(p => ``).join(''); + + // Restore previous selection if it's still a valid option + if (previousValue && plugins.includes(previousValue)) { + pluginFilterEl.value = previousValue; + } +} + function renderLogs() { if (window._filteredLogs.length === 0) { showEmptyState(); @@ -364,10 +453,14 @@ function renderLogs() { window._filteredLogs.forEach(log => { const logElement = document.createElement('div'); logElement.className = `log-entry py-1 px-2 hover:bg-gray-800 rounded transition-colors duration-150 ${getLogLevelClass(log.level)}`; + const pluginBadge = log.plugin + ? `${escapeHtml(log.plugin)}` + : ''; logElement.innerHTML = `
${escapeHtml(log.timestamp)} ${log.level} + ${pluginBadge} ${escapeHtml(log.message)}
`; @@ -410,10 +503,12 @@ function getLogLevelTextClass(level) { function filterLogs() { const levelFilterEl = document.getElementById('log-level-filter'); + const pluginFilterEl = document.getElementById('log-plugin-filter'); const searchEl = document.getElementById('log-search'); if (!levelFilterEl || !searchEl) return; - + const levelFilter = levelFilterEl.value; + const pluginFilter = pluginFilterEl ? pluginFilterEl.value : ''; const searchTerm = searchEl.value.toLowerCase(); window._filteredLogs = window._allLogs.filter(log => { @@ -430,8 +525,14 @@ function filterLogs() { } } + // Plugin filter + if (pluginFilter && log.plugin !== pluginFilter) { + return false; + } + // Search filter - if (searchTerm && !log.message.toLowerCase().includes(searchTerm)) { + if (searchTerm && !log.message.toLowerCase().includes(searchTerm) && + !(log.plugin && log.plugin.toLowerCase().includes(searchTerm))) { return false; } @@ -617,10 +718,45 @@ function escapeHtml(text) { return div.innerHTML; } +function refreshCurrentPluginStatus() { + fetch('/api/v3/display/current-status') + .then(response => response.json()) + .then(data => { + if (data.status !== 'success' || !data.data) return; + const state = data.data; + const banner = document.getElementById('current-plugin-banner'); + const modeEl = document.getElementById('current-plugin-mode'); + const idWrap = document.getElementById('current-plugin-id-wrap'); + const idEl = document.getElementById('current-plugin-id'); + const filterBtn = document.getElementById('current-plugin-filter-btn'); + if (!banner || !modeEl) return; + + window._currentPluginId = state.plugin_id || null; + + modeEl.textContent = state.mode || 'unknown'; + if (state.plugin_id) { + idEl.textContent = state.plugin_id; + idWrap.classList.remove('hidden'); + if (filterBtn) filterBtn.classList.remove('hidden'); + } else { + idWrap.classList.add('hidden'); + if (filterBtn) filterBtn.classList.add('hidden'); + } + banner.classList.remove('hidden'); + }) + .catch(() => { + // Silently ignore - banner just stays hidden/stale + }); +} + // Cleanup on page unload window.addEventListener('beforeunload', function() { if (window._logsEventSource) { window._logsEventSource.close(); } + if (window._currentPluginPollTimer) { + clearInterval(window._currentPluginPollTimer); + window._currentPluginPollTimer = null; + } });