Tag plugin logs structurally and surface the active plugin in System Logs (#418)

- get_logger() now returns a PluginLoggerAdapter when given a plugin_id,
  so every plugin log call is stamped with plugin_id automatically instead
  of only calls that explicitly passed extra={'plugin_id': ...}. This makes
  the "[Plugin: x]" prefix reliable in the journalctl-backed log stream.
- display_controller publishes the currently active mode/plugin to the
  shared cache whenever it changes, exposed via a new
  GET /api/v3/display/current-status endpoint.
- System Logs page: adds a "Now showing" banner backed by that endpoint, a
  plugin filter dropdown (populated from parsed log lines), a plugin badge
  per log entry, and fixes log parsing to handle the short-iso timestamp
  format journalctl actually returns (the old regex only matched syslog
  timestamps, so level/plugin extraction silently never ran).

Co-authored-by: Claude <noreply@anthropic.com>

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

src/logging_config.py

@@ -139,7 +139,25 @@ 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.
 
@@ -148,13 +166,13 @@ def get_logger(name: str, plugin_id: Optional[str] = None) -> logging.Logger:
         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
 

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)

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"""

web_interface/templates/v3/partials/logs.html

@@ -4,6 +4,17 @@
         <p class="mt-1 text-sm text-gray-600">View real-time logs from the LED matrix service for troubleshooting.</p>
     </div>
 
+    <!-- Currently displayed plugin -->
+    <div id="current-plugin-banner" class="hidden mb-4 flex items-center gap-2 text-sm bg-blue-50 border border-blue-200 text-blue-800 rounded-lg px-3 py-2">
+        <i class="fas fa-tv"></i>
+        <span>Now showing: <strong id="current-plugin-mode">-</strong>
+            <span id="current-plugin-id-wrap" class="hidden">(plugin: <code id="current-plugin-id" class="bg-blue-100 px-1 rounded"></code>)</span>
+        </span>
+        <button id="current-plugin-filter-btn" class="hidden ml-auto btn bg-blue-600 hover:bg-blue-700 text-white px-2 py-0.5 rounded text-xs">
+            Filter to this plugin
+        </button>
+    </div>
+
     <!-- Controls -->
     <div class="flex flex-wrap items-center justify-between gap-4 mb-6">
         <div class="flex items-center space-x-4">
@@ -27,6 +38,11 @@
                 <option value="INFO">Info & Above</option>
             </select>
 
+            <!-- Plugin Filter -->
+            <select id="log-plugin-filter" class="form-control text-sm">
+                <option value="">All Plugins</option>
+            </select>
+
             <!-- Search -->
             <div class="relative">
                 <input type="text" id="log-search" placeholder="Search logs..." class="form-control text-sm pl-8 pr-4 py-1 w-48">
@@ -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,20 +324,40 @@ 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;
+        let plugin = '';
+        let rest = null;
 
-        // 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];
+        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+(.*)$/);
 
-            // Find the message part (after service name and pid)
-            const messageMatch = line.match(/:\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', {
+                month: 'short',
+                day: '2-digit',
+                hour: '2-digit',
+                minute: '2-digit',
+                second: '2-digit',
+                hour12: false
+            });
+        }
+
+        if (rest !== null) {
+            // Find the message part (after hostname + service name/pid)
+            const messageMatch = rest.match(/:\s*(.+)$/);
             if (messageMatch) {
                 message = messageMatch[1];
 
@@ -313,23 +373,35 @@ function processLogs(logsText, append = false) {
                 }
 
                 // Clean up level prefix from message if it exists
-                message = message.replace(/^(ERROR|WARNING|WARN|INFO|DEBUG):\s*/i, '');
+                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: <id>]" 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;
             }
-        } else {
-            // If no timestamp, use current time
-            timestamp = new Date().toLocaleString('en-US', {
-                month: 'short',
-                day: '2-digit',
-                hour: '2-digit',
-                minute: '2-digit',
-                second: '2-digit',
-                hour12: false
-            });
         }
 
         const logEntry = {
             timestamp: timestamp,
             level: level,
+            plugin: plugin,
             message: message,
             raw: line,
             id: Date.now() + Math.random()
@@ -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 = '<option value="">All Plugins</option>' +
+        plugins.map(p => `<option value="${escapeHtml(p)}">${escapeHtml(p)}</option>`).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
+            ? `<span class="log-plugin flex-shrink-0 px-2 py-0.5 rounded text-xs font-semibold bg-purple-700 text-white" title="Plugin: ${escapeHtml(log.plugin)}">${escapeHtml(log.plugin)}</span>`
+            : '';
         logElement.innerHTML = `
             <div class="flex items-start gap-3 text-xs font-mono">
                 <span class="log-timestamp text-gray-400 flex-shrink-0 w-32">${escapeHtml(log.timestamp)}</span>
                 <span class="log-level flex-shrink-0 px-2 py-0.5 rounded text-xs font-semibold ${getLogLevelBadgeClass(log.level)}">${log.level}</span>
+                ${pluginBadge}
                 <span class="log-message flex-1 ${getLogLevelTextClass(log.level)} break-words">${escapeHtml(log.message)}</span>
             </div>
         `;
@@ -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;
+    }
 });
 </script>