From fe6b1d871abbc1990410e16869882eac1c9910e2 Mon Sep 17 00:00:00 2001 From: bonamin Date: Thu, 26 Feb 2026 17:31:28 +0200 Subject: [PATCH] feat: Add per-subsystem log tags to all firmware modules Refactored logging system to require a TAG as first argument on all LOG_* macros, enabling per-subsystem log filtering and cleaner output. Each subsystem now defines its own TAG (e.g. "BellEngine", "Player"). Also overhauled Logging.hpp/cpp with improved level control and output. Co-Authored-By: Claude Sonnet 4.6 --- vesper/src/BellEngine/BellEngine.cpp | 60 ++-- vesper/src/ClientManager/ClientManager.cpp | 26 +- .../CommandHandler/CommandHandler.cpp | 193 ++++++------ .../CommunicationRouter.cpp | 131 ++++---- .../HTTPRequestHandler/HTTPRequestHandler.cpp | 22 +- .../MQTTAsyncClient/MQTTAsyncClient.cpp | 66 ++-- .../ResponseBuilder/ResponseBuilder.cpp | 8 +- .../UARTCommandHandler/UARTCommandHandler.cpp | 24 +- .../WebSocketServer/WebSocketServer.cpp | 30 +- vesper/src/ConfigManager/ConfigManager.cpp | 254 +++++++-------- vesper/src/ConfigManager/ConfigManager.hpp | 7 +- vesper/src/FileManager/FileManager.cpp | 89 +++--- vesper/src/FileManager/FileManager.hpp | 3 + .../FirmwareValidator/FirmwareValidator.cpp | 160 +++++----- vesper/src/HealthMonitor/HealthMonitor.cpp | 43 ++- vesper/src/InputManager/InputManager.cpp | 38 +-- vesper/src/Logging/Logging.cpp | 283 ++++++++++++----- vesper/src/Logging/Logging.hpp | 159 +++++++--- vesper/src/Networking/Networking.cpp | 124 ++++---- vesper/src/OTAManager/OTAManager.cpp | 296 +++++++++--------- vesper/src/OutputManager/OutputManager.cpp | 98 +++--- vesper/src/Player/Player.cpp | 76 ++--- vesper/src/SDCardMutex/SDCardMutex.hpp | 14 +- .../SettingsWebServer/SettingsWebServer.cpp | 22 +- vesper/src/Telemetry/Telemetry.cpp | 58 ++-- vesper/src/TimeKeeper/TimeKeeper.cpp | 124 ++++---- 26 files changed, 1334 insertions(+), 1074 deletions(-) diff --git a/vesper/src/BellEngine/BellEngine.cpp b/vesper/src/BellEngine/BellEngine.cpp index 8d1d407..e126b35 100644 --- a/vesper/src/BellEngine/BellEngine.cpp +++ b/vesper/src/BellEngine/BellEngine.cpp @@ -22,6 +22,8 @@ // DEPENDENCY INCLUDES - Required system components // ═════════════════════════════════════════════════════════════════════════════════ #include "BellEngine.hpp" // Header file with class definition + +#define TAG "BellEngine" #include "../Player/Player.hpp" // Melody playback controller #include "../ConfigManager/ConfigManager.hpp" // Configuration and settings #include "../Telemetry/Telemetry.hpp" // System monitoring and analytics @@ -74,7 +76,7 @@ BellEngine::~BellEngine() { * */ void BellEngine::begin() { - LOG_DEBUG("Initializing BellEngine..."); + LOG_DEBUG(TAG, "Initializing BellEngine..."); // Create engine task with HIGHEST priority on dedicated Core 1 // This ensures maximum performance and timing precision @@ -88,7 +90,7 @@ void BellEngine::begin() { 1 // 💻 Pin to Core 1 (dedicated) ); - LOG_INFO("BellEngine initialized !"); + LOG_INFO(TAG, "BellEngine initialized !"); } /** @@ -96,7 +98,7 @@ void BellEngine::begin() { */ void BellEngine::setCommunicationManager(CommunicationRouter* commManager) { _communicationManager = commManager; - LOG_DEBUG("BellEngine: Communication manager %s", + LOG_DEBUG(TAG, "BellEngine: Communication manager %s", commManager ? "connected" : "disconnected"); } @@ -116,22 +118,22 @@ void BellEngine::setCommunicationManager(CommunicationRouter* commManager) { void BellEngine::start() { // Validate that melody data is ready before starting if (!_melodyDataReady.load()) { - LOG_ERROR("Cannot start BellEngine: No melody data loaded"); + LOG_ERROR(TAG, "Cannot start BellEngine: No melody data loaded"); return; // ⛔ Early exit if no melody data } - LOG_INFO("🚀 BellEngine Ignition - Starting precision playback"); + LOG_INFO(TAG, "🚀 BellEngine Ignition - Starting precision playback"); _emergencyStop.store(false); // ✅ Clear any emergency stop state _engineRunning.store(true); // ✅ Activate the engine atomically } void BellEngine::stop() { - LOG_INFO("BellEngine - Stopping Gracefully"); + LOG_INFO(TAG, "BellEngine - Stopping Gracefully"); _engineRunning.store(false); } void BellEngine::emergencyStop() { - LOG_INFO("BellEngine - 🛑 Forcing Stop Immediately"); + LOG_INFO(TAG, "BellEngine - 🛑 Forcing Stop Immediately"); _emergencyStop.store(true); _engineRunning.store(false); emergencyShutdown(); @@ -142,7 +144,7 @@ void BellEngine::setMelodyData(const std::vector& melodySteps) { _melodySteps = melodySteps; _melodyDataReady.store(true); portEXIT_CRITICAL(&_melodyMutex); - LOG_DEBUG("BellEngine - Loaded melody: %d steps", melodySteps.size()); + LOG_DEBUG(TAG, "BellEngine - Loaded melody: %d steps", melodySteps.size()); } void BellEngine::clearMelodyData() { @@ -150,7 +152,7 @@ void BellEngine::clearMelodyData() { _melodySteps.clear(); _melodyDataReady.store(false); portEXIT_CRITICAL(&_melodyMutex); - LOG_DEBUG("BellEngine - Melody data cleared"); + LOG_DEBUG(TAG, "BellEngine - Melody data cleared"); } // ================== CRITICAL TIMING SECTION ================== @@ -158,7 +160,7 @@ void BellEngine::clearMelodyData() { void BellEngine::engineTask(void* parameter) { BellEngine* engine = static_cast(parameter); - LOG_DEBUG("BellEngine - 🔥 Engine task started on Core %d with MAXIMUM priority", xPortGetCoreID()); + LOG_DEBUG(TAG, "BellEngine - 🔥 Engine task started on Core %d with MAXIMUM priority", xPortGetCoreID()); while (true) { if (engine->_engineRunning.load() && !engine->_emergencyStop.load()) { @@ -186,7 +188,7 @@ void BellEngine::engineLoop() { // Pause handling AFTER complete loop - never interrupt mid-melody! while (_player.isPaused && _player.isPlaying && !_player.hardStop) { - LOG_VERBOSE("BellEngine - ⏸️ Pausing between melody loops"); + LOG_VERBOSE(TAG, "BellEngine - ⏸️ Pausing between melody loops"); vTaskDelay(pdMS_TO_TICKS(10)); // Wait during pause } @@ -207,17 +209,17 @@ void BellEngine::playbackLoop() { portEXIT_CRITICAL(&_melodyMutex); if (melodySteps.empty()) { - LOG_ERROR("BellEngine - ❌ Empty melody in playback loop!"); + LOG_ERROR(TAG, "BellEngine - ❌ Empty melody in playback loop!"); return; } - LOG_DEBUG("BellEngine - 🎵 Starting melody loop (%d steps)", melodySteps.size()); + LOG_DEBUG(TAG, "BellEngine - 🎵 Starting melody loop (%d steps)", melodySteps.size()); // CRITICAL TIMING LOOP - Complete the entire melody without interruption for (uint16_t note : melodySteps) { // Emergency exit check (only emergency stops can interrupt mid-loop) if (_emergencyStop.load() || _player.hardStop) { - LOG_DEBUG("BellEngine - Emergency exit from playback loop"); + LOG_DEBUG(TAG, "BellEngine - Emergency exit from playback loop"); return; } @@ -227,7 +229,7 @@ void BellEngine::playbackLoop() { // Precise timing delay - validate speed to prevent division by zero // I THINK this should be moved outside the Bell Engine if (_player.speed == 0) { - LOG_ERROR("BellEngine - ❌ Invalid Speed (0) detected, stopping playback"); + LOG_ERROR(TAG, "BellEngine - ❌ Invalid Speed (0) detected, stopping playback"); _player.hardStop = true; _engineRunning.store(false); return; @@ -242,9 +244,9 @@ void BellEngine::playbackLoop() { _player.onMelodyLoopCompleted(); // 🔥 Notify Player that melody actually finished! if ((_player.continuous_loop && _player.segment_duration == 0) || _player.total_duration == 0) { vTaskDelay(pdMS_TO_TICKS(500)); //Give Player time to pause/stop - LOG_VERBOSE("BellEngine - Loop completed in SINGLE Mode - waiting for Player to handle pause/stop"); + LOG_VERBOSE(TAG, "BellEngine - Loop completed in SINGLE Mode - waiting for Player to handle pause/stop"); } - LOG_DEBUG("BellEngine - 🎵 Melody loop completed with PRECISION"); + LOG_DEBUG(TAG, "BellEngine - 🎵 Melody loop completed with PRECISION"); } @@ -268,26 +270,26 @@ void BellEngine::activateNote(uint16_t note) { // Additional safety check to prevent underflow crashes if (bellIndex >= 255) { - LOG_ERROR("BellEngine - 🚨 UNDERFLOW ERROR: bellIndex underflow for noteIndex %d", noteIndex); + LOG_ERROR(TAG, "BellEngine - 🚨 UNDERFLOW ERROR: bellIndex underflow for noteIndex %d", noteIndex); continue; } // Bounds check (CRITICAL SAFETY) if (bellIndex >= 16) { - LOG_ERROR("BellEngine - 🚨 BOUNDS ERROR: bellIndex %d >= 16", bellIndex); + LOG_ERROR(TAG, "BellEngine - 🚨 BOUNDS ERROR: bellIndex %d >= 16", bellIndex); continue; } // Check for duplicate bell firing in this note if (bellFired[bellIndex]) { - LOG_DEBUG("BellEngine - ⚠️ DUPLICATE BELL: Skipping duplicate firing of bell %d for note %d", bellIndex, noteIndex); + LOG_DEBUG(TAG, "BellEngine - ⚠️ DUPLICATE BELL: Skipping duplicate firing of bell %d for note %d", bellIndex, noteIndex); continue; } // Check if bell is configured (OutputManager will validate this) uint8_t physicalOutput = _outputManager.getPhysicalOutput(bellIndex); if (physicalOutput == 255) { - LOG_DEBUG("BellEngine - ⚠️ UNCONFIGURED: Bell %d not configured, skipping", bellIndex); + LOG_DEBUG(TAG, "BellEngine - ⚠️ UNCONFIGURED: Bell %d not configured, skipping", bellIndex); continue; } @@ -306,14 +308,14 @@ void BellEngine::activateNote(uint16_t note) { // Record telemetry _telemetry.recordBellStrike(bellIndex); - LOG_VERBOSE("BellEngine - 🔨 STRIKE! Note:%d → Bell:%d for %dms", noteIndex, bellIndex, durationMs); + LOG_VERBOSE(TAG, "BellEngine - 🔨 STRIKE! Note:%d → Bell:%d for %dms", noteIndex, bellIndex, durationMs); } } // 🚀 FIRE ALL BELLS SIMULTANEOUSLY! if (!bellDurations.empty()) { _outputManager.fireOutputsBatchForDuration(bellDurations); - LOG_VERBOSE("BellEngine - 🔥 Batch Fired %d bells Simultaneously !", bellDurations.size()); + LOG_VERBOSE(TAG, "BellEngine - 🔥 Batch Fired %d bells Simultaneously !", bellDurations.size()); // 🔔 NOTIFY WEBSOCKET CLIENTS OF BELL DINGS! // * deactivated currently, since unstable and causes performance issues * @@ -339,7 +341,7 @@ void BellEngine::preciseDelay(uint32_t microseconds) { } void BellEngine::emergencyShutdown() { - LOG_INFO("BellEngine - 🚨 Emergency Shutdown - Notifying OutputManager"); + LOG_INFO(TAG, "BellEngine - 🚨 Emergency Shutdown - Notifying OutputManager"); _outputManager.emergencyShutdown(); } @@ -364,10 +366,10 @@ void BellEngine::notifyBellsFired(const std::vector& bellIndices) { // Send notification to WebSocket clients only (not MQTT) _communicationManager->broadcastToAllWebSocketClients(dingMsg); - LOG_DEBUG("BellEngine - 🔔 DING notification sent for %d bells", bellIndices.size()); + LOG_DEBUG(TAG, "BellEngine - 🔔 DING notification sent for %d bells", bellIndices.size()); } catch (...) { - LOG_WARNING("BellEngine - ❌ Failed to send ding notification"); + LOG_WARNING(TAG, "BellEngine - ❌ Failed to send ding notification"); } } @@ -378,20 +380,20 @@ void BellEngine::notifyBellsFired(const std::vector& bellIndices) { bool BellEngine::isHealthy() const { // Check if engine task is created and running if (_engineTaskHandle == NULL) { - LOG_DEBUG("BellEngine: Unhealthy - Task not created"); + LOG_DEBUG(TAG, "BellEngine: Unhealthy - Task not created"); return false; } // Check if task is still alive eTaskState taskState = eTaskGetState(_engineTaskHandle); if (taskState == eDeleted || taskState == eInvalid) { - LOG_DEBUG("BellEngine: Unhealthy - Task deleted or invalid"); + LOG_DEBUG(TAG, "BellEngine: Unhealthy - Task deleted or invalid"); return false; } // Check if OutputManager is properly connected and healthy if (!_outputManager.isInitialized()) { - LOG_DEBUG("BellEngine: Unhealthy - OutputManager not initialized"); + LOG_DEBUG(TAG, "BellEngine: Unhealthy - OutputManager not initialized"); return false; } diff --git a/vesper/src/ClientManager/ClientManager.cpp b/vesper/src/ClientManager/ClientManager.cpp index 4f44560..2d65a58 100644 --- a/vesper/src/ClientManager/ClientManager.cpp +++ b/vesper/src/ClientManager/ClientManager.cpp @@ -1,31 +1,33 @@ #include "ClientManager.hpp" + +#define TAG "ClientManager" #include "../Logging/Logging.hpp" ClientManager::ClientManager() { - LOG_INFO("Client Manager initialized !"); + LOG_INFO(TAG, "Client Manager initialized !"); } ClientManager::~ClientManager() { _clients.clear(); - LOG_INFO("Client Manager destroyed"); + LOG_INFO(TAG, "Client Manager destroyed"); } void ClientManager::addClient(AsyncWebSocketClient* client, DeviceType deviceType) { if (!isValidClient(client)) { - LOG_WARNING("Client Manager - Cannot add invalid client"); + LOG_WARNING(TAG, "Client Manager - Cannot add invalid client"); return; } uint32_t clientId = client->id(); _clients[clientId] = ClientInfo(client, deviceType); - LOG_INFO("Client Manager - Client #%u added as %s device", clientId, deviceTypeToString(deviceType)); + LOG_INFO(TAG, "Client Manager - Client #%u added as %s device", clientId, deviceTypeToString(deviceType)); } void ClientManager::removeClient(uint32_t clientId) { auto it = _clients.find(clientId); if (it != _clients.end()) { - LOG_INFO("Client Manager - Client #%u removed (%s device)", clientId, + LOG_INFO(TAG, "Client Manager - Client #%u removed (%s device)", clientId, deviceTypeToString(it->second.deviceType)); _clients.erase(it); } @@ -36,7 +38,7 @@ void ClientManager::updateClientType(uint32_t clientId, DeviceType deviceType) { if (it != _clients.end()) { DeviceType oldType = it->second.deviceType; it->second.deviceType = deviceType; - LOG_INFO("Client Manager - Client #%u type updated from %s to %s", clientId, + LOG_INFO(TAG, "Client Manager - Client #%u type updated from %s to %s", clientId, deviceTypeToString(oldType), deviceTypeToString(deviceType)); } } @@ -72,11 +74,11 @@ bool ClientManager::sendToClient(uint32_t clientId, const String& message) { if (it != _clients.end() && isValidClient(it->second.client)) { it->second.client->text(message); updateClientLastSeen(clientId); - LOG_DEBUG("Client Manager - Message sent to client #%u: %s", clientId, message.c_str()); + LOG_DEBUG(TAG, "Client Manager - Message sent to client #%u: %s", clientId, message.c_str()); return true; } - LOG_WARNING("Client Manager - Failed to send message to client #%u - client not found or invalid", clientId); + LOG_WARNING(TAG, "Client Manager - Failed to send message to client #%u - client not found or invalid", clientId); return false; } @@ -90,7 +92,7 @@ void ClientManager::sendToMasterClients(const String& message) { count++; } } - LOG_DEBUG("Client Manager - Message sent to %d master client(s): %s", count, message.c_str()); + LOG_DEBUG(TAG, "Client Manager - Message sent to %d master client(s): %s", count, message.c_str()); } void ClientManager::sendToSecondaryClients(const String& message) { @@ -103,7 +105,7 @@ void ClientManager::sendToSecondaryClients(const String& message) { count++; } } - LOG_DEBUG("Client Manager - Message sent to %d secondary client(s): %s", count, message.c_str()); + LOG_DEBUG(TAG, "Client Manager - Message sent to %d secondary client(s): %s", count, message.c_str()); } void ClientManager::broadcastToAll(const String& message) { @@ -115,14 +117,14 @@ void ClientManager::broadcastToAll(const String& message) { count++; } } - LOG_DEBUG("Client Manager - Message broadcasted to %d client(s): %s", count, message.c_str()); + LOG_DEBUG(TAG, "Client Manager - Message broadcasted to %d client(s): %s", count, message.c_str()); } void ClientManager::cleanupDisconnectedClients() { auto it = _clients.begin(); while (it != _clients.end()) { if (!isValidClient(it->second.client)) { - LOG_DEBUG("Client Manager - Cleaning up disconnected client #%u", it->first); + LOG_DEBUG(TAG, "Client Manager - Cleaning up disconnected client #%u", it->first); it->second.isConnected = false; it = _clients.erase(it); } else { diff --git a/vesper/src/Communication/CommandHandler/CommandHandler.cpp b/vesper/src/Communication/CommandHandler/CommandHandler.cpp index d9d710a..73deee8 100644 --- a/vesper/src/Communication/CommandHandler/CommandHandler.cpp +++ b/vesper/src/Communication/CommandHandler/CommandHandler.cpp @@ -3,6 +3,8 @@ */ #include "CommandHandler.hpp" + +#define TAG "CommandHandler" #include "../../ConfigManager/ConfigManager.hpp" #include "../../OTAManager/OTAManager.hpp" #include "../../Player/Player.hpp" @@ -65,7 +67,7 @@ void CommandHandler::processCommand(JsonDocument& command, const MessageContext& String cmd = command["cmd"]; JsonVariant contents = command["contents"]; - LOG_DEBUG("Processing command: %s from %s", cmd.c_str(), + LOG_DEBUG(TAG, "Processing command: %s from %s", cmd.c_str(), context.source == MessageSource::MQTT ? "MQTT" : "WebSocket"); if (cmd == "ping") { @@ -85,7 +87,7 @@ void CommandHandler::processCommand(JsonDocument& command, const MessageContext& } else if (cmd == "system") { handleSystemCommand(contents, context); } else { - LOG_WARNING("Unknown command received: %s", cmd.c_str()); + LOG_WARNING(TAG, "Unknown command received: %s", cmd.c_str()); sendErrorResponse("unknown_command", "Command not recognized: " + cmd, context); } } @@ -146,7 +148,7 @@ void CommandHandler::handleIdentifyCommand(JsonVariant contents, const MessageCo // 🛡️ SAFETY CHECK: Ensure ClientManager reference is set if (!_clientManager) { - LOG_ERROR("ClientManager reference not set in CommandHandler!"); + LOG_ERROR(TAG, "ClientManager reference not set in CommandHandler!"); sendErrorResponse("identify", "Internal error: ClientManager not available", context); return; } @@ -168,7 +170,7 @@ void CommandHandler::handleIdentifyCommand(JsonVariant contents, const MessageCo if (deviceType != ClientManager::DeviceType::UNKNOWN) { _clientManager->updateClientType(context.clientId, deviceType); sendSuccessResponse("identify", "Device identified as " + deviceTypeStr, context); - LOG_INFO("Client #%u identified as %s device", context.clientId, deviceTypeStr.c_str()); + LOG_INFO(TAG, "Client #%u identified as %s device", context.clientId, deviceTypeStr.c_str()); } else { sendErrorResponse("identify", "Invalid device_type. Use 'master' or 'secondary'", context); } @@ -184,7 +186,7 @@ void CommandHandler::handlePlaybackCommand(JsonVariant contents, const MessageCo sendErrorResponse("playback", "Playback command failed", context); } } else { - LOG_ERROR("Player reference not set"); + LOG_ERROR(TAG, "Player reference not set"); sendErrorResponse("playback", "Player not available", context); } } @@ -196,7 +198,7 @@ void CommandHandler::handleFileManagerCommand(JsonVariant contents, const Messag } String action = contents["action"]; - LOG_DEBUG("Processing file manager action: %s", action.c_str()); + LOG_DEBUG(TAG, "Processing file manager action: %s", action.c_str()); if (action == "list_melodies") { handleListMelodiesCommand(context); @@ -205,7 +207,7 @@ void CommandHandler::handleFileManagerCommand(JsonVariant contents, const Messag } else if (action == "delete_melody") { handleDeleteMelodyCommand(contents, context); } else { - LOG_WARNING("Unknown file manager action: %s", action.c_str()); + LOG_WARNING(TAG, "Unknown file manager action: %s", action.c_str()); sendErrorResponse("file_manager", "Unknown action: " + action, context); } } @@ -217,14 +219,14 @@ void CommandHandler::handleRelaySetupCommand(JsonVariant contents, const Message } String action = contents["action"]; - LOG_DEBUG("Processing relay setup action: %s", action.c_str()); + LOG_DEBUG(TAG, "Processing relay setup action: %s", action.c_str()); if (action == "set_timings") { handleSetRelayTimersCommand(contents, context); } else if (action == "set_outputs") { handleSetRelayOutputsCommand(contents, context); } else { - LOG_WARNING("Unknown relay setup action: %s", action.c_str()); + LOG_WARNING(TAG, "Unknown relay setup action: %s", action.c_str()); sendErrorResponse("relay_setup", "Unknown action: " + action, context); } } @@ -236,7 +238,7 @@ void CommandHandler::handleClockSetupCommand(JsonVariant contents, const Message } String action = contents["action"]; - LOG_DEBUG("Processing clock setup action: %s", action.c_str()); + LOG_DEBUG(TAG, "Processing clock setup action: %s", action.c_str()); if (action == "set_outputs") { handleSetClockOutputsCommand(contents, context); @@ -257,7 +259,7 @@ void CommandHandler::handleClockSetupCommand(JsonVariant contents, const Message } else if (action == "set_enabled") { handleSetClockEnabledCommand(contents, context); } else { - LOG_WARNING("Unknown clock setup action: %s", action.c_str()); + LOG_WARNING(TAG, "Unknown clock setup action: %s", action.c_str()); sendErrorResponse("clock_setup", "Unknown action: " + action, context); } } @@ -269,7 +271,7 @@ void CommandHandler::handleSystemInfoCommand(JsonVariant contents, const Message } String action = contents["action"]; - LOG_DEBUG("Processing system info action: %s", action.c_str()); + LOG_DEBUG(TAG, "Processing system info action: %s", action.c_str()); if (action == "report_status") { handleStatusCommand(context); @@ -286,7 +288,7 @@ void CommandHandler::handleSystemInfoCommand(JsonVariant contents, const Message } else if (action == "sync_time_to_lcd") { handleSyncTimeToLcdCommand(context); } else { - LOG_WARNING("Unknown system info action: %s", action.c_str()); + LOG_WARNING(TAG, "Unknown system info action: %s", action.c_str()); sendErrorResponse("system_info", "Unknown action: " + action, context); } } @@ -303,7 +305,7 @@ void CommandHandler::handleListMelodiesCommand(const MessageContext& context) { DeserializationError error = deserializeJson(doc, fileListJson); if (error) { - LOG_ERROR("Failed to parse file list JSON: %s", error.c_str()); + LOG_ERROR(TAG, "Failed to parse file list JSON: %s", error.c_str()); sendErrorResponse("list_melodies", "Failed to parse file list", context); return; } @@ -362,14 +364,14 @@ void CommandHandler::handleSetRelayTimersCommand(JsonVariant contents, const Mes bool saved = _configManager.saveBellDurations(); if (saved) { sendSuccessResponse("set_relay_timers", "Relay timers updated and saved", context); - LOG_INFO("Relay timers updated and saved successfully"); + LOG_INFO(TAG, "Relay timers updated and saved successfully"); } else { sendErrorResponse("set_relay_timers", "Failed to save relay timers to SD card", context); - LOG_ERROR("Failed to save relay timers configuration"); + LOG_ERROR(TAG, "Failed to save relay timers configuration"); } } catch (...) { sendErrorResponse("set_relay_timers", "Failed to update relay timers", context); - LOG_ERROR("Exception occurred while updating relay timers"); + LOG_ERROR(TAG, "Exception occurred while updating relay timers"); } } @@ -380,14 +382,14 @@ void CommandHandler::handleSetRelayOutputsCommand(JsonVariant contents, const Me bool saved = _configManager.saveBellOutputs(); if (saved) { sendSuccessResponse("set_relay_outputs", "Relay outputs updated and saved", context); - LOG_INFO("Relay outputs updated and saved successfully"); + LOG_INFO(TAG, "Relay outputs updated and saved successfully"); } else { sendErrorResponse("set_relay_outputs", "Failed to save relay outputs to SD card", context); - LOG_ERROR("Failed to save relay outputs configuration"); + LOG_ERROR(TAG, "Failed to save relay outputs configuration"); } } catch (...) { sendErrorResponse("set_relay_outputs", "Failed to update relay outputs", context); - LOG_ERROR("Exception occurred while updating relay outputs"); + LOG_ERROR(TAG, "Exception occurred while updating relay outputs"); } } @@ -398,14 +400,14 @@ void CommandHandler::handleSetClockOutputsCommand(JsonVariant contents, const Me bool saved = _configManager.saveClockConfig(); if (saved) { sendSuccessResponse("set_clock_outputs", "Clock outputs updated and saved", context); - LOG_INFO("Clock outputs updated and saved successfully"); + LOG_INFO(TAG, "Clock outputs updated and saved successfully"); } else { sendErrorResponse("set_clock_outputs", "Failed to save clock outputs to SD card", context); - LOG_ERROR("Failed to save clock outputs configuration"); + LOG_ERROR(TAG, "Failed to save clock outputs configuration"); } } catch (...) { sendErrorResponse("set_clock_outputs", "Failed to update clock outputs", context); - LOG_ERROR("Exception occurred while updating clock outputs"); + LOG_ERROR(TAG, "Exception occurred while updating clock outputs"); } } @@ -416,14 +418,14 @@ void CommandHandler::handleSetClockTimingsCommand(JsonVariant contents, const Me bool saved = _configManager.saveClockConfig(); if (saved) { sendSuccessResponse("set_clock_timings", "Clock timings updated and saved", context); - LOG_INFO("Clock timings updated and saved successfully"); + LOG_INFO(TAG, "Clock timings updated and saved successfully"); } else { sendErrorResponse("set_clock_timings", "Failed to save clock timings to SD card", context); - LOG_ERROR("Failed to save clock timings configuration"); + LOG_ERROR(TAG, "Failed to save clock timings configuration"); } } catch (...) { sendErrorResponse("set_clock_timings", "Failed to update clock timings", context); - LOG_ERROR("Exception occurred while updating clock timings"); + LOG_ERROR(TAG, "Exception occurred while updating clock timings"); } } @@ -434,14 +436,14 @@ void CommandHandler::handleSetClockAlertsCommand(JsonVariant contents, const Mes bool saved = _configManager.saveClockConfig(); if (saved) { sendSuccessResponse("set_clock_alerts", "Clock alerts updated and saved", context); - LOG_INFO("Clock alerts updated and saved successfully"); + LOG_INFO(TAG, "Clock alerts updated and saved successfully"); } else { sendErrorResponse("set_clock_alerts", "Failed to save clock alerts to SD card", context); - LOG_ERROR("Failed to save clock alerts configuration"); + LOG_ERROR(TAG, "Failed to save clock alerts configuration"); } } catch (...) { sendErrorResponse("set_clock_alerts", "Failed to update clock alerts", context); - LOG_ERROR("Exception occurred while updating clock alerts"); + LOG_ERROR(TAG, "Exception occurred while updating clock alerts"); } } @@ -452,14 +454,14 @@ void CommandHandler::handleSetClockBacklightCommand(JsonVariant contents, const bool saved = _configManager.saveClockConfig(); if (saved) { sendSuccessResponse("set_clock_backlight", "Clock backlight updated and saved", context); - LOG_INFO("Clock backlight updated and saved successfully"); + LOG_INFO(TAG, "Clock backlight updated and saved successfully"); } else { sendErrorResponse("set_clock_backlight", "Failed to save clock backlight to SD card", context); - LOG_ERROR("Failed to save clock backlight configuration"); + LOG_ERROR(TAG, "Failed to save clock backlight configuration"); } } catch (...) { sendErrorResponse("set_clock_backlight", "Failed to update clock backlight", context); - LOG_ERROR("Exception occurred while updating clock backlight"); + LOG_ERROR(TAG, "Exception occurred while updating clock backlight"); } } @@ -470,14 +472,14 @@ void CommandHandler::handleSetClockSilenceCommand(JsonVariant contents, const Me bool saved = _configManager.saveClockConfig(); if (saved) { sendSuccessResponse("set_clock_silence", "Clock silence periods updated and saved", context); - LOG_INFO("Clock silence periods updated and saved successfully"); + LOG_INFO(TAG, "Clock silence periods updated and saved successfully"); } else { sendErrorResponse("set_clock_silence", "Failed to save clock silence configuration to SD card", context); - LOG_ERROR("Failed to save clock silence configuration"); + LOG_ERROR(TAG, "Failed to save clock silence configuration"); } } catch (...) { sendErrorResponse("set_clock_silence", "Failed to update clock silence periods", context); - LOG_ERROR("Exception occurred while updating clock silence periods"); + LOG_ERROR(TAG, "Exception occurred while updating clock silence periods"); } } @@ -514,7 +516,7 @@ void CommandHandler::handleSetRtcTimeCommand(JsonVariant contents, const Message // Update timezone configuration _configManager.updateTimeConfig(baseGmtOffset, dstOffset); - LOG_INFO("Timezone updated: %s (GMT%+ld, DST%+ld)", + LOG_INFO(TAG, "Timezone updated: %s (GMT%+ld, DST%+ld)", timezoneName.c_str(), baseGmtOffset/3600, dstOffset/3600); // Apply total offset to timestamp @@ -529,11 +531,11 @@ void CommandHandler::handleSetRtcTimeCommand(JsonVariant contents, const Message if (verifyTime > 0 && abs((long)verifyTime - (long)localTimestamp) < 5) { // Allow 5 second tolerance sendSuccessResponse("set_rtc_time", "RTC time and timezone updated successfully", context); - LOG_INFO("RTC time set with timezone: UTC %lu + %ld = local %lu", + LOG_INFO(TAG, "RTC time set with timezone: UTC %lu + %ld = local %lu", timestamp, totalOffset, localTimestamp); } else { sendErrorResponse("set_rtc_time", "Failed to verify RTC time was set correctly", context); - LOG_ERROR("RTC time verification failed - expected: %lu, got: %lu", localTimestamp, verifyTime); + LOG_ERROR(TAG, "RTC time verification failed - expected: %lu, got: %lu", localTimestamp, verifyTime); } } else { // Legacy method: Use device's existing timezone config @@ -543,10 +545,10 @@ void CommandHandler::handleSetRtcTimeCommand(JsonVariant contents, const Message unsigned long verifyTime = _timeKeeper->getTime(); if (verifyTime > 0 && abs((long)verifyTime - (long)timestamp) < 5) { // Allow 5 second tolerance sendSuccessResponse("set_rtc_time", "RTC time updated successfully", context); - LOG_INFO("RTC time set using device timezone config: %lu", timestamp); + LOG_INFO(TAG, "RTC time set using device timezone config: %lu", timestamp); } else { sendErrorResponse("set_rtc_time", "Failed to verify RTC time was set correctly", context); - LOG_ERROR("RTC time verification failed - expected: %lu, got: %lu", timestamp, verifyTime); + LOG_ERROR(TAG, "RTC time verification failed - expected: %lu, got: %lu", timestamp, verifyTime); } } } @@ -585,11 +587,11 @@ void CommandHandler::handleSetPhysicalClockTimeCommand(JsonVariant contents, con if (saved) { sendSuccessResponse("set_physical_clock_time", "Physical clock time updated and saved successfully", context); - LOG_INFO("Physical clock time set to %02d:%02d (12h: %02d:%02d) and saved to SD", + LOG_INFO(TAG, "Physical clock time set to %02d:%02d (12h: %02d:%02d) and saved to SD", hour, minute, clockHour, minute); } else { sendErrorResponse("set_physical_clock_time", "Physical clock time updated but failed to save to SD card", context); - LOG_ERROR("Physical clock time set to %02d:%02d but failed to save to SD", hour, minute); + LOG_ERROR(TAG, "Physical clock time set to %02d:%02d but failed to save to SD", hour, minute); } } @@ -601,12 +603,12 @@ void CommandHandler::handlePauseClockUpdatesCommand(JsonVariant contents, const if (contents["action"] == "pause_clock_updates") { _timeKeeper->pauseClockUpdates(); sendSuccessResponse("pause_clock_updates", "Clock updates paused", context); - LOG_DEBUG("Clock updates paused"); + LOG_DEBUG(TAG, "Clock updates paused"); return; } else if (contents["action"] == "resume_clock_updates") { _timeKeeper->resumeClockUpdates(); sendSuccessResponse("resume_clock_updates", "Clock updates resumed", context); - LOG_DEBUG("Clock updates resumed"); + LOG_DEBUG(TAG, "Clock updates resumed"); return; } } @@ -626,14 +628,14 @@ void CommandHandler::handleSetClockEnabledCommand(JsonVariant contents, const Me if (saved) { String status = enabled ? "enabled" : "disabled"; sendSuccessResponse("set_clock_enabled", "Clock " + status + " and saved successfully", context); - LOG_INFO("Clock %s via remote command", status.c_str()); + LOG_INFO(TAG, "Clock %s via remote command", status.c_str()); } else { sendErrorResponse("set_clock_enabled", "Clock setting updated but failed to save to SD card", context); - LOG_ERROR("Failed to save clock enabled setting to SD card"); + LOG_ERROR(TAG, "Failed to save clock enabled setting to SD card"); } } catch (...) { sendErrorResponse("set_clock_enabled", "Failed to update clock enabled setting", context); - LOG_ERROR("Exception occurred while updating clock enabled setting"); + LOG_ERROR(TAG, "Exception occurred while updating clock enabled setting"); } } @@ -668,14 +670,14 @@ void CommandHandler::handleGetDeviceTimeCommand(const MessageContext& context) { response["payload"]["local_timestamp"] = millis() / 1000; response["payload"]["utc_timestamp"] = millis() / 1000; response["payload"]["rtc_available"] = false; - LOG_WARNING("TimeKeeper reference not set for device time request"); + LOG_WARNING(TAG, "TimeKeeper reference not set for device time request"); } String responseStr; serializeJson(response, responseStr); sendResponse(responseStr, context); - LOG_DEBUG("Device time requested"); + LOG_DEBUG(TAG, "Device time requested"); } void CommandHandler::handleGetClockTimeCommand(const MessageContext& context) { @@ -694,7 +696,7 @@ void CommandHandler::handleGetClockTimeCommand(const MessageContext& context) { serializeJson(response, responseStr); sendResponse(responseStr, context); - LOG_DEBUG("Physical clock time requested: %02d:%02d (last sync: %lu)", + LOG_DEBUG(TAG, "Physical clock time requested: %02d:%02d (last sync: %lu)", _configManager.getPhysicalClockHour(), _configManager.getPhysicalClockMinute(), _configManager.getLastSyncTime()); @@ -716,16 +718,16 @@ void CommandHandler::handleCommitFirmwareCommand(const MessageContext& context) return; } - LOG_INFO("💾 Manual firmware commit requested via %s", + LOG_INFO(TAG, "💾 Manual firmware commit requested via %s", context.source == MessageSource::MQTT ? "MQTT" : "WebSocket"); try { _firmwareValidator->commitFirmware(); sendSuccessResponse("commit_firmware", "Firmware committed successfully", context); - LOG_INFO("✅ Firmware manually committed - system is now stable"); + LOG_INFO(TAG, "✅ Firmware manually committed - system is now stable"); } catch (...) { sendErrorResponse("commit_firmware", "Failed to commit firmware", context); - LOG_ERROR("❌ Failed to commit firmware"); + LOG_ERROR(TAG, "❌ Failed to commit firmware"); } } @@ -735,18 +737,18 @@ void CommandHandler::handleRollbackFirmwareCommand(const MessageContext& context return; } - LOG_WARNING("🔄 Manual firmware rollback requested via %s", + LOG_WARNING(TAG, "🔄 Manual firmware rollback requested via %s", context.source == MessageSource::MQTT ? "MQTT" : "WebSocket"); try { _firmwareValidator->rollbackFirmware(); sendSuccessResponse("rollback_firmware", "Firmware rollback initiated - device will reboot", context); - LOG_WARNING("🔄 Firmware rollback initiated - device should reboot shortly"); + LOG_WARNING(TAG, "🔄 Firmware rollback initiated - device should reboot shortly"); // Device should reboot automatically, but this response might not be sent } catch (...) { sendErrorResponse("rollback_firmware", "Failed to initiate firmware rollback", context); - LOG_ERROR("❌ Failed to initiate firmware rollback"); + LOG_ERROR(TAG, "❌ Failed to initiate firmware rollback"); } } @@ -820,7 +822,7 @@ void CommandHandler::handleGetFirmwareStatusCommand(const MessageContext& contex serializeJson(response, responseStr); sendResponse(responseStr, context); - LOG_DEBUG("Firmware status requested: %s", stateStr.c_str()); + LOG_DEBUG(TAG, "Firmware status requested: %s", stateStr.c_str()); } void CommandHandler::handleNetworkInfoCommand(const MessageContext& context) { @@ -839,7 +841,7 @@ void CommandHandler::handleNetworkInfoCommand(const MessageContext& context) { } void CommandHandler::handleGetFullSettingsCommand(const MessageContext& context) { - LOG_DEBUG("Full settings requested"); + LOG_DEBUG(TAG, "Full settings requested"); // Get all settings as JSON string from ConfigManager String settingsJson = _configManager.getAllSettingsAsJson(); @@ -854,7 +856,7 @@ void CommandHandler::handleGetFullSettingsCommand(const MessageContext& context) DeserializationError error = deserializeJson(settingsDoc, settingsJson); if (error) { - LOG_ERROR("Failed to parse settings JSON: %s", error.c_str()); + LOG_ERROR(TAG, "Failed to parse settings JSON: %s", error.c_str()); sendErrorResponse("get_full_settings", "Failed to serialize settings", context); return; } @@ -865,7 +867,7 @@ void CommandHandler::handleGetFullSettingsCommand(const MessageContext& context) serializeJson(response, responseStr); sendResponse(responseStr, context); - LOG_DEBUG("Full settings sent (%d bytes)", responseStr.length()); + LOG_DEBUG(TAG, "Full settings sent (%d bytes)", responseStr.length()); } void CommandHandler::handleSyncTimeToLcdCommand(const MessageContext& context) { @@ -880,7 +882,7 @@ void CommandHandler::handleSyncTimeToLcdCommand(const MessageContext& context) { } else { // Fallback to millis if TimeKeeper not available localTimestamp = millis() / 1000; - LOG_WARNING("TimeKeeper not available for LCD time sync"); + LOG_WARNING(TAG, "TimeKeeper not available for LCD time sync"); } // Get timezone offset from ConfigManager (in seconds) @@ -897,7 +899,7 @@ void CommandHandler::handleSyncTimeToLcdCommand(const MessageContext& context) { serializeJson(response, responseStr); sendResponse(responseStr, context); - LOG_DEBUG("LCD time sync: UTC=%lu, offset=%ld", utcTimestamp, totalOffset); + LOG_DEBUG(TAG, "LCD time sync: UTC=%lu, offset=%ld", utcTimestamp, totalOffset); } void CommandHandler::handleSetNetworkConfigCommand(JsonVariant contents, const MessageContext& context) { @@ -933,7 +935,7 @@ void CommandHandler::handleSetNetworkConfigCommand(JsonVariant contents, const M hostname = newHostname; configChanged = true; needsReboot = true; - LOG_INFO("Hostname will be updated to: %s", hostname.c_str()); + LOG_INFO(TAG, "Hostname will be updated to: %s", hostname.c_str()); } else { sendErrorResponse("set_network_config", "Invalid hostname (must be 1-32 characters)", context); return; @@ -975,9 +977,9 @@ void CommandHandler::handleSetNetworkConfigCommand(JsonVariant contents, const M dns2.fromString(contents["dns2"].as()); } - LOG_INFO("Static IP configuration will be applied: %s", ip.toString().c_str()); + LOG_INFO(TAG, "Static IP configuration will be applied: %s", ip.toString().c_str()); } else { - LOG_INFO("DHCP mode will be enabled"); + LOG_INFO(TAG, "DHCP mode will be enabled"); } } @@ -996,10 +998,10 @@ void CommandHandler::handleSetNetworkConfigCommand(JsonVariant contents, const M responseMsg += ". RESTART DEVICE to apply changes"; } sendSuccessResponse("set_network_config", responseMsg, context); - LOG_INFO("✅ Network configuration saved to SD card"); + LOG_INFO(TAG, "✅ Network configuration saved to SD card"); } else { sendErrorResponse("set_network_config", "Configuration updated but failed to save to SD card", context); - LOG_ERROR("❌ Failed to save network configuration to SD card"); + LOG_ERROR(TAG, "❌ Failed to save network configuration to SD card"); } } else { sendSuccessResponse("set_network_config", "No changes detected", context); @@ -1007,10 +1009,10 @@ void CommandHandler::handleSetNetworkConfigCommand(JsonVariant contents, const M } catch (const std::exception& e) { sendErrorResponse("set_network_config", String("Exception: ") + e.what(), context); - LOG_ERROR("Exception in handleSetNetworkConfigCommand: %s", e.what()); + LOG_ERROR(TAG, "Exception in handleSetNetworkConfigCommand: %s", e.what()); } catch (...) { sendErrorResponse("set_network_config", "Unknown error occurred", context); - LOG_ERROR("Unknown exception in handleSetNetworkConfigCommand"); + LOG_ERROR(TAG, "Unknown exception in handleSetNetworkConfigCommand"); } } @@ -1020,7 +1022,7 @@ void CommandHandler::handleSetNetworkConfigCommand(JsonVariant contents, const M void CommandHandler::handleResetDefaultsCommand(const MessageContext& context) { - LOG_WARNING("⚠️ Factory reset requested. Proceeding..."); + LOG_WARNING(TAG, "⚠️ Factory reset requested. Proceeding..."); try { // Reset all configurations to defaults @@ -1028,14 +1030,14 @@ void CommandHandler::handleResetDefaultsCommand(const MessageContext& context) { if (resetComplete) { sendSuccessResponse("reset_defaults", "Reset to Defaults completed. Device will Restart to apply changes.", context); - LOG_WARNING("✅ Factory reset completed and all configurations saved to SD card"); + LOG_WARNING(TAG, "✅ Factory reset completed and all configurations saved to SD card"); } else { sendErrorResponse("reset_defaults", "Reset to Defaults applied but failed to save some configurations to SD card", context); - LOG_ERROR("❌ Reset to Defaults applied but failed to save some configurations to SD card"); + LOG_ERROR(TAG, "❌ Reset to Defaults applied but failed to save some configurations to SD card"); } } catch (...) { sendErrorResponse("reset_defaults", "Failed to perform Reset to Defaults", context); - LOG_ERROR("❌ Exception occurred during Resetting to Defaults"); + LOG_ERROR(TAG, "❌ Exception occurred during Resetting to Defaults"); } } @@ -1053,7 +1055,7 @@ void CommandHandler::handleSystemCommand(JsonVariant contents, const MessageCont } String action = contents["action"]; - LOG_DEBUG("Processing system action: %s", action.c_str()); + LOG_DEBUG(TAG, "Processing system action: %s", action.c_str()); if (action == "status") { handleStatusCommand(context); @@ -1082,7 +1084,7 @@ void CommandHandler::handleSystemCommand(JsonVariant contents, const MessageCont } else if (action == "custom_update") { handleCustomUpdateCommand(contents, context); } else { - LOG_WARNING("Unknown system action: %s", action.c_str()); + LOG_WARNING(TAG, "Unknown system action: %s", action.c_str()); sendErrorResponse("system", "Unknown action: " + action, context); } } @@ -1110,11 +1112,11 @@ void CommandHandler::handleSetSerialLogLevelCommand(JsonVariant contents, const if (saved) { sendSuccessResponse("set_serial_log_level", "Serial log level set to " + String(level) + " and saved", context); - LOG_INFO("Serial log level updated to %d", level); + LOG_INFO(TAG, "Serial log level updated to %d", level); } else { sendErrorResponse("set_serial_log_level", "Log level set but failed to save to SD card", context); - LOG_ERROR("Failed to save serial log level to SD card"); + LOG_ERROR(TAG, "Failed to save serial log level to SD card"); } } else { sendErrorResponse("set_serial_log_level", @@ -1132,17 +1134,20 @@ void CommandHandler::handleSetSdLogLevelCommand(JsonVariant contents, const Mess // Set the level in ConfigManager if (_configManager.setSdLogLevel(level)) { + // Apply immediately + Logging::setSdLevel((Logging::LogLevel)level); + // Save to SD card bool saved = _configManager.saveGeneralConfig(); - + if (saved) { - sendSuccessResponse("set_sd_log_level", + sendSuccessResponse("set_sd_log_level", "SD log level set to " + String(level) + " and saved", context); - LOG_INFO("SD log level updated to %d (not yet implemented)", level); + LOG_INFO(TAG, "SD log level updated to %d", level); } else { sendErrorResponse("set_sd_log_level", "Log level set but failed to save to SD card", context); - LOG_ERROR("Failed to save SD log level to SD card"); + LOG_ERROR(TAG, "Failed to save SD log level to SD card"); } } else { sendErrorResponse("set_sd_log_level", @@ -1169,11 +1174,11 @@ void CommandHandler::handleSetMqttLogLevelCommand(JsonVariant contents, const Me if (saved) { sendSuccessResponse("set_mqtt_log_level", "MQTT log level set to " + String(level) + " and saved", context); - LOG_INFO("MQTT log level updated to %d", level); + LOG_INFO(TAG, "MQTT log level updated to %d", level); } else { sendErrorResponse("set_mqtt_log_level", "Log level set but failed to save to SD card", context); - LOG_ERROR("Failed to save MQTT log level to SD card"); + LOG_ERROR(TAG, "Failed to save MQTT log level to SD card"); } } else { sendErrorResponse("set_mqtt_log_level", @@ -1198,7 +1203,7 @@ void CommandHandler::handleSetMqttEnabledCommand(JsonVariant contents, const Mes if (saved) { sendSuccessResponse("set_mqtt_enabled", String("MQTT ") + (enabled ? "enabled" : "disabled") + " and saved", context); - LOG_INFO("MQTT %s by user command", enabled ? "enabled" : "disabled"); + LOG_INFO(TAG, "MQTT %s by user command", enabled ? "enabled" : "disabled"); // If disabling, disconnect MQTT immediately // If enabling, trigger connection attempt @@ -1209,12 +1214,12 @@ void CommandHandler::handleSetMqttEnabledCommand(JsonVariant contents, const Mes _communicationRouter->getMQTTClient().connect(); } } else { - LOG_WARNING("CommunicationRouter reference not set - cannot control MQTT"); + LOG_WARNING(TAG, "CommunicationRouter reference not set - cannot control MQTT"); } } else { sendErrorResponse("set_mqtt_enabled", "MQTT state changed but failed to save to SD card", context); - LOG_ERROR("Failed to save MQTT enabled state to SD card"); + LOG_ERROR(TAG, "Failed to save MQTT enabled state to SD card"); } } @@ -1223,7 +1228,7 @@ void CommandHandler::handleSetMqttEnabledCommand(JsonVariant contents, const Mes // ════════════════════════════════════════════════════════════════════════════ void CommandHandler::handleRestartCommand(const MessageContext& context) { - LOG_WARNING("🔄 Device restart requested via command"); + LOG_WARNING(TAG, "🔄 Device restart requested via command"); sendSuccessResponse("restart", "Device will restart in 2 seconds", context); // Small delay to ensure response is sent @@ -1238,12 +1243,12 @@ void CommandHandler::handleRestartCommand(const MessageContext& context) { // ════════════════════════════════════════════════════════════════════════════ void CommandHandler::handleForceUpdateCommand(JsonVariant contents, const MessageContext& context) { - LOG_WARNING("🔄 Force OTA update requested via command"); + LOG_WARNING(TAG, "🔄 Force OTA update requested via command"); // Check if player is active if (_player && _player->isCurrentlyPlaying()) { sendErrorResponse("force_update", "Cannot update while playback is active", context); - LOG_WARNING("Force update rejected - player is active"); + LOG_WARNING(TAG, "Force update rejected - player is active"); return; } @@ -1264,7 +1269,7 @@ void CommandHandler::handleForceUpdateCommand(JsonVariant contents, const Messag // Note: If update succeeds, device will reboot and this won't be reached if (!result) { - LOG_ERROR("Force update failed"); + LOG_ERROR(TAG, "Force update failed"); // Error response may not be received if we already restarted } } @@ -1274,7 +1279,7 @@ void CommandHandler::handleForceUpdateCommand(JsonVariant contents, const Messag // ════════════════════════════════════════════════════════════════════════════ void CommandHandler::handleCustomUpdateCommand(JsonVariant contents, const MessageContext& context) { - LOG_WARNING("🔥 Custom OTA update requested via command"); + LOG_WARNING(TAG, "🔥 Custom OTA update requested via command"); // Validate required parameters if (!contents.containsKey("firmware_url")) { @@ -1295,11 +1300,11 @@ void CommandHandler::handleCustomUpdateCommand(JsonVariant contents, const Messa // Check if player is active if (_player && _player->isCurrentlyPlaying()) { sendErrorResponse("custom_update", "Cannot update while playback is active", context); - LOG_WARNING("Custom update rejected - player is active"); + LOG_WARNING(TAG, "Custom update rejected - player is active"); return; } - LOG_INFO("Custom update: URL=%s, Checksum=%s, Size=%u, Version=%u", + LOG_INFO(TAG, "Custom update: URL=%s, Checksum=%s, Size=%u, Version=%u", firmwareUrl.c_str(), checksum.isEmpty() ? "none" : checksum.c_str(), fileSize, @@ -1316,7 +1321,7 @@ void CommandHandler::handleCustomUpdateCommand(JsonVariant contents, const Messa // Note: If update succeeds, device will reboot and this won't be reached if (!result) { - LOG_ERROR("Custom update failed"); + LOG_ERROR(TAG, "Custom update failed"); // Error response may not be received if we already restarted } } diff --git a/vesper/src/Communication/CommunicationRouter/CommunicationRouter.cpp b/vesper/src/Communication/CommunicationRouter/CommunicationRouter.cpp index b48ca47..a194bf9 100644 --- a/vesper/src/Communication/CommunicationRouter/CommunicationRouter.cpp +++ b/vesper/src/Communication/CommunicationRouter/CommunicationRouter.cpp @@ -3,6 +3,8 @@ */ #include "CommunicationRouter.hpp" + +#define TAG "CommRouter" #include "../../ConfigManager/ConfigManager.hpp" #include "../../OTAManager/OTAManager.hpp" #include "../../Networking/Networking.hpp" @@ -39,11 +41,11 @@ CommunicationRouter::CommunicationRouter(ConfigManager& configManager, CommunicationRouter::~CommunicationRouter() {} void CommunicationRouter::begin() { - LOG_INFO("Initializing Communication Router v4.0 (Modular)"); + LOG_INFO(TAG, "Initializing Communication Router v4.0 (Modular)"); // 🔥 CRITICAL: Initialize WebSocket FIRST to ensure it's always set up // Even if MQTT fails, we want WebSocket to work! - LOG_INFO("Setting up WebSocket server..."); + LOG_INFO(TAG, "Setting up WebSocket server..."); // Initialize WebSocket server _wsServer.begin(); @@ -54,11 +56,11 @@ void CommunicationRouter::begin() { // 🔥 CRITICAL FIX: Attach WebSocket handler to AsyncWebServer // This MUST happen before any potential failures! _server.addHandler(&_webSocket); - LOG_INFO("✅ WebSocket handler attached to AsyncWebServer on /ws"); + LOG_INFO(TAG, "✅ WebSocket handler attached to AsyncWebServer on /ws"); //Now initialize MQTT client (can fail without breaking WebSocket) try { - LOG_INFO("Setting up MQTT client..."); + LOG_INFO(TAG, "Setting up MQTT client..."); _mqttClient.begin(); _mqttClient.setCallback([this](const String& topic, const String& payload) { onMqttMessage(topic, payload); @@ -73,23 +75,36 @@ void CommunicationRouter::begin() { logTopic ); - // Apply MQTT log level from config - uint8_t mqttLogLevel = _configManager.getMqttLogLevel(); - Logging::setMqttLogLevel((Logging::LogLevel)mqttLogLevel); - LOG_INFO("MQTT logging enabled with level %d on topic: %s", mqttLogLevel, logTopic.c_str()); + // Apply log levels from config for all three channels + Logging::setSerialLevel((Logging::LogLevel)_configManager.getSerialLogLevel()); + Logging::setMqttLevel((Logging::LogLevel)_configManager.getMqttLogLevel()); + Logging::setSdLevel((Logging::LogLevel)_configManager.getSdLogLevel()); + LOG_INFO(TAG, "Log levels applied — Serial:%d MQTT:%d SD:%d", + _configManager.getSerialLogLevel(), + _configManager.getMqttLogLevel(), + _configManager.getSdLogLevel()); - LOG_INFO("✅ MQTT client initialized"); + // Silence MQTT-internal subsystems on the MQTT channel to prevent log storms. + // These systems generate logs while sending logs — suppress them over MQTT only. + Logging::setSubsystemMqttLevel("MQTTClient", Logging::NONE); + Logging::setSubsystemMqttLevel("CommRouter", Logging::WARNING); + Logging::setSubsystemMqttLevel("Logger", Logging::NONE); + + LOG_INFO(TAG, "✅ MQTT client initialized"); } catch (...) { - LOG_ERROR("❌ MQTT initialization failed, but WebSocket is still available"); + LOG_ERROR(TAG, "❌ MQTT initialization failed, but WebSocket is still available"); } + + // Wire up SD logging channel (requires FileManager to be set first via setFileManagerReference) + // SD callback is registered lazily in setFileManagerReference once the pointer is available // 🔥 CRITICAL FIX: Connect ClientManager to CommandHandler _commandHandler.setClientManagerReference(&_clientManager); - LOG_INFO("ClientManager reference set for CommandHandler"); + LOG_INFO(TAG, "ClientManager reference set for CommandHandler"); // 🔥 Set CommunicationRouter reference for MQTT control commands _commandHandler.setCommunicationRouterReference(this); - LOG_INFO("CommunicationRouter reference set for CommandHandler"); + LOG_INFO(TAG, "CommunicationRouter reference set for CommandHandler"); // Setup command handler response callback _commandHandler.setResponseCallback([this](const String& response, const CommandHandler::MessageContext& context) { @@ -97,30 +112,30 @@ void CommunicationRouter::begin() { }); // Initialize HTTP Request Handler - LOG_INFO("Setting up HTTP REST API..."); + LOG_INFO(TAG, "Setting up HTTP REST API..."); _httpHandler.begin(); _httpHandler.setCommandHandlerReference(&_commandHandler); - LOG_INFO("✅ HTTP REST API initialized"); + LOG_INFO(TAG, "✅ HTTP REST API initialized"); // Initialize Settings Web Server - LOG_INFO("Setting up Settings Web Server..."); + LOG_INFO(TAG, "Setting up Settings Web Server..."); _settingsServer.begin(); - LOG_INFO("✅ Settings Web Server initialized at /settings"); + LOG_INFO(TAG, "✅ Settings Web Server initialized at /settings"); // Initialize UART Command Handler - LOG_INFO("Setting up UART Command Handler..."); + LOG_INFO(TAG, "Setting up UART Command Handler..."); _uartHandler.begin(); _uartHandler.setCallback([this](JsonDocument& message) { onUartMessage(message); }); - LOG_INFO("✅ UART Command Handler initialized (TX: GPIO12, RX: GPIO13)"); + LOG_INFO(TAG, "✅ UART Command Handler initialized (TX: GPIO12, RX: GPIO13)"); - LOG_INFO("Communication Router initialized with modular architecture"); - LOG_INFO(" • MQTT: AsyncMqttClient"); - LOG_INFO(" • WebSocket: Multi-client support"); - LOG_INFO(" • HTTP REST API: /api endpoints"); - LOG_INFO(" • UART: External device control"); - LOG_INFO(" • Settings Page: /settings"); + LOG_INFO(TAG, "Communication Router initialized with modular architecture"); + LOG_INFO(TAG, " • MQTT: AsyncMqttClient"); + LOG_INFO(TAG, " • WebSocket: Multi-client support"); + LOG_INFO(TAG, " • HTTP REST API: /api endpoints"); + LOG_INFO(TAG, " • UART: External device control"); + LOG_INFO(TAG, " • Settings Page: /settings"); } void CommunicationRouter::loop() { @@ -136,6 +151,14 @@ void CommunicationRouter::setPlayerReference(Player* player) { void CommunicationRouter::setFileManagerReference(FileManager* fm) { _fileManager = fm; _commandHandler.setFileManagerReference(fm); + + // Register SD log channel now that FileManager is available + if (fm != nullptr) { + Logging::setSdWriteCallback([fm](const String& line) { + fm->appendLine("/logs/vesper.log", line); + }); + LOG_INFO(TAG, "SD log channel registered -> /logs/vesper.log"); + } } void CommunicationRouter::setTimeKeeperReference(Timekeeper* tk) { @@ -155,11 +178,11 @@ void CommunicationRouter::setTelemetryReference(Telemetry* telemetry) { void CommunicationRouter::setupUdpDiscovery() { uint16_t discoveryPort = _configManager.getNetworkConfig().discoveryPort; if (_udp.listen(discoveryPort)) { - LOG_INFO("UDP discovery listening on port %u", discoveryPort); + LOG_INFO(TAG, "UDP discovery listening on port %u", discoveryPort); _udp.onPacket([this](AsyncUDPPacket packet) { String msg = String((const char*)packet.data(), packet.length()); - LOG_DEBUG("UDP from %s:%u -> %s", + LOG_DEBUG(TAG, "UDP from %s:%u -> %s", packet.remoteIP().toString().c_str(), packet.remotePort(), msg.c_str()); @@ -200,7 +223,7 @@ void CommunicationRouter::setupUdpDiscovery() { packet.remoteIP(), packet.remotePort()); }); } else { - LOG_ERROR("Failed to start UDP discovery."); + LOG_ERROR(TAG, "Failed to start UDP discovery."); } } @@ -219,22 +242,24 @@ size_t CommunicationRouter::getWebSocketClientCount() const { bool CommunicationRouter::isHealthy() const { // Check if required references are set if (!_player || !_fileManager || !_timeKeeper) { - LOG_DEBUG("CommunicationRouter: Unhealthy - Missing references"); + LOG_WARNING(TAG, "Unhealthy - missing subsystem references (player=%d fileManager=%d timeKeeper=%d)", + _player != nullptr, _fileManager != nullptr, _timeKeeper != nullptr); return false; } - + + // Check network connectivity first — no point checking connections without a network + if (!_networking.isConnected()) { + LOG_WARNING(TAG, "Unhealthy - no network connection"); + return false; + } + // Check if at least one protocol is connected if (!isMqttConnected() && !hasActiveWebSocketClients()) { - LOG_DEBUG("CommunicationRouter: Unhealthy - No active connections"); + LOG_WARNING(TAG, "Unhealthy - no active connections (MQTT=%d, WebSocket=%d)", + isMqttConnected(), hasActiveWebSocketClients()); return false; } - - // Check network connectivity - if (!_networking.isConnected()) { - LOG_DEBUG("CommunicationRouter: Unhealthy - No network connection"); - return false; - } - + return true; } @@ -270,9 +295,9 @@ void CommunicationRouter::broadcastToAllWebSocketClients(const JsonDocument& mes void CommunicationRouter::publishToMqtt(const String& data) { if (_mqttClient.isConnected()) { _mqttClient.publish("data", data, 0, false); - LOG_DEBUG("Published to MQTT: %s", data.c_str()); + LOG_DEBUG(TAG, "Published to MQTT: %s", data.c_str()); } else { - LOG_ERROR("MQTT Not Connected! Message Failed: %s", data.c_str()); + LOG_ERROR(TAG, "MQTT Not Connected! Message Failed: %s", data.c_str()); } } @@ -294,29 +319,29 @@ void CommunicationRouter::sendBellOverloadNotification(const std::vector doc; DeserializationError error = deserializeJson(doc, payload); if (error) { - LOG_ERROR("Failed to parse MQTT JSON: %s", error.c_str()); + LOG_ERROR(TAG, "Failed to parse MQTT JSON: %s", error.c_str()); return; } @@ -330,7 +355,7 @@ void CommunicationRouter::onMqttMessage(const String& topic, const String& paylo void CommunicationRouter::onWebSocketMessage(uint32_t clientId, const JsonDocument& message) { // Extract command for logging String cmd = message["cmd"] | "unknown"; - LOG_INFO("📨 WebSocket message from client #%u: cmd=%s", clientId, cmd.c_str()); + LOG_INFO(TAG, "📨 WebSocket message from client #%u: cmd=%s", clientId, cmd.c_str()); // Create message context for WebSocket with client ID CommandHandler::MessageContext context(CommandHandler::MessageSource::WEBSOCKET, clientId); @@ -339,7 +364,7 @@ void CommunicationRouter::onWebSocketMessage(uint32_t clientId, const JsonDocume JsonDocument& mutableDoc = const_cast(message); _commandHandler.processCommand(mutableDoc, context); - LOG_DEBUG("WebSocket message from client #%u processed", clientId); + LOG_DEBUG(TAG, "WebSocket message from client #%u processed", clientId); } void CommunicationRouter::onUartMessage(JsonDocument& message) { @@ -360,12 +385,12 @@ void CommunicationRouter::onUartMessage(JsonDocument& message) { if (!allowed) { // Silently ignore - do NOT send error response to avoid feedback loop - LOG_DEBUG("UART: Ignoring non-whitelisted command (cmd=%s, action=%s)", + LOG_DEBUG(TAG, "UART: Ignoring non-whitelisted command (cmd=%s, action=%s)", cmd.c_str(), action.c_str()); return; } - LOG_INFO("🔌 UART command received: cmd=%s, action=%s", cmd.c_str(), action.c_str()); + LOG_INFO(TAG, "🔌 UART command received: cmd=%s, action=%s", cmd.c_str(), action.c_str()); // Create message context for UART CommandHandler::MessageContext context(CommandHandler::MessageSource::UART); @@ -373,20 +398,20 @@ void CommunicationRouter::onUartMessage(JsonDocument& message) { // Forward to command handler _commandHandler.processCommand(message, context); - LOG_DEBUG("UART message processed"); + LOG_DEBUG(TAG, "UART message processed"); } void CommunicationRouter::sendResponse(const String& response, const CommandHandler::MessageContext& context) { if (context.source == CommandHandler::MessageSource::MQTT) { - LOG_DEBUG("↗️ Sending response via MQTT: %s", response.c_str()); + LOG_DEBUG(TAG, "↗️ Sending response via MQTT: %s", response.c_str()); publishToMqtt(response); } else if (context.source == CommandHandler::MessageSource::WEBSOCKET) { - LOG_DEBUG("↗️ Sending response to WebSocket client #%u: %s", context.clientId, response.c_str()); + LOG_DEBUG(TAG, "↗️ Sending response to WebSocket client #%u: %s", context.clientId, response.c_str()); _wsServer.sendToClient(context.clientId, response); } else if (context.source == CommandHandler::MessageSource::UART) { - LOG_DEBUG("↗️ Sending response via UART: %s", response.c_str()); + LOG_DEBUG(TAG, "↗️ Sending response via UART: %s", response.c_str()); _uartHandler.send(response); } else { - LOG_ERROR("❌ Unknown message source for response routing!"); + LOG_ERROR(TAG, "❌ Unknown message source for response routing!"); } } diff --git a/vesper/src/Communication/HTTPRequestHandler/HTTPRequestHandler.cpp b/vesper/src/Communication/HTTPRequestHandler/HTTPRequestHandler.cpp index 52978e7..a9b53d1 100644 --- a/vesper/src/Communication/HTTPRequestHandler/HTTPRequestHandler.cpp +++ b/vesper/src/Communication/HTTPRequestHandler/HTTPRequestHandler.cpp @@ -5,6 +5,8 @@ */ #include "HTTPRequestHandler.hpp" + +#define TAG "HTTPHandler" #include "../CommandHandler/CommandHandler.hpp" #include "../../ConfigManager/ConfigManager.hpp" #include "../../Logging/Logging.hpp" @@ -20,7 +22,7 @@ HTTPRequestHandler::~HTTPRequestHandler() { } void HTTPRequestHandler::begin() { - LOG_INFO("HTTPRequestHandler - Initializing HTTP REST API endpoints"); + LOG_INFO(TAG, "HTTPRequestHandler - Initializing HTTP REST API endpoints"); // POST /api/command - Execute any command _server.on("/api/command", HTTP_POST, @@ -61,15 +63,15 @@ void HTTPRequestHandler::begin() { DefaultHeaders::Instance().addHeader("Access-Control-Allow-Methods", "GET, POST, OPTIONS"); DefaultHeaders::Instance().addHeader("Access-Control-Allow-Headers", "Content-Type"); - LOG_INFO("HTTPRequestHandler - REST API endpoints registered"); - LOG_INFO(" POST /api/command - Execute commands"); - LOG_INFO(" GET /api/status - System status"); - LOG_INFO(" GET /api/ping - Health check"); + LOG_INFO(TAG, "HTTPRequestHandler - REST API endpoints registered"); + LOG_INFO(TAG, " POST /api/command - Execute commands"); + LOG_INFO(TAG, " GET /api/status - System status"); + LOG_INFO(TAG, " GET /api/ping - Health check"); } void HTTPRequestHandler::setCommandHandlerReference(CommandHandler* handler) { _commandHandler = handler; - LOG_DEBUG("HTTPRequestHandler - CommandHandler reference set"); + LOG_DEBUG(TAG, "HTTPRequestHandler - CommandHandler reference set"); } bool HTTPRequestHandler::isHealthy() const { @@ -88,12 +90,12 @@ void HTTPRequestHandler::handleCommandRequest(AsyncWebServerRequest* request, ui DeserializationError error = deserializeJson(doc, data, len); if (error) { - LOG_WARNING("HTTPRequestHandler - JSON parse error: %s", error.c_str()); + LOG_WARNING(TAG, "HTTPRequestHandler - JSON parse error: %s", error.c_str()); sendErrorResponse(request, 400, "Invalid JSON"); return; } - LOG_DEBUG("HTTPRequestHandler - Processing command via HTTP"); + LOG_DEBUG(TAG, "HTTPRequestHandler - Processing command via HTTP"); // Create message context for HTTP (treat as WebSocket with special ID) CommandHandler::MessageContext context(CommandHandler::MessageSource::WEBSOCKET, 0xFFFFFFFF); @@ -129,7 +131,7 @@ void HTTPRequestHandler::handleStatusRequest(AsyncWebServerRequest* request) { return; } - LOG_DEBUG("HTTPRequestHandler - Status request via HTTP"); + LOG_DEBUG(TAG, "HTTPRequestHandler - Status request via HTTP"); // Create a status command JsonDocument doc; @@ -160,7 +162,7 @@ void HTTPRequestHandler::handleStatusRequest(AsyncWebServerRequest* request) { } void HTTPRequestHandler::handlePingRequest(AsyncWebServerRequest* request) { - LOG_DEBUG("HTTPRequestHandler - Ping request via HTTP"); + LOG_DEBUG(TAG, "HTTPRequestHandler - Ping request via HTTP"); JsonDocument response; response["status"] = "ok"; diff --git a/vesper/src/Communication/MQTTAsyncClient/MQTTAsyncClient.cpp b/vesper/src/Communication/MQTTAsyncClient/MQTTAsyncClient.cpp index 6b3a498..fffc7f2 100644 --- a/vesper/src/Communication/MQTTAsyncClient/MQTTAsyncClient.cpp +++ b/vesper/src/Communication/MQTTAsyncClient/MQTTAsyncClient.cpp @@ -3,6 +3,8 @@ */ #include "MQTTAsyncClient.hpp" + +#define TAG "MQTTClient" #include "../../ConfigManager/ConfigManager.hpp" #include "../../Networking/Networking.hpp" #include "../../Logging/Logging.hpp" @@ -66,7 +68,7 @@ MQTTAsyncClient::~MQTTAsyncClient() { } void MQTTAsyncClient::begin() { - LOG_INFO("Initializing MQTT Async Client"); + LOG_INFO(TAG, "Initializing MQTT Async Client"); auto& mqttConfig = _configManager.getMqttConfig(); @@ -76,7 +78,7 @@ void MQTTAsyncClient::begin() { _dataTopic = "vesper/" + deviceUID + "/data"; _clientId = "vesper-" + deviceUID; - LOG_INFO("MQTT Topics: control=%s, data=%s", _controlTopic.c_str(), _dataTopic.c_str()); + LOG_INFO(TAG, "MQTT Topics: control=%s, data=%s", _controlTopic.c_str(), _dataTopic.c_str()); // Setup event handlers _mqttClient.onConnect([this](bool sessionPresent) { @@ -110,7 +112,7 @@ void MQTTAsyncClient::begin() { _mqttClient.setKeepAlive(15); _mqttClient.setCleanSession(true); - LOG_INFO("✅ MQTT Async Client initialized"); + LOG_INFO(TAG, "✅ MQTT Async Client initialized"); } void MQTTAsyncClient::connect() { @@ -118,28 +120,28 @@ void MQTTAsyncClient::connect() { // 🔥 Check if MQTT is enabled if (!mqttConfig.enabled) { - LOG_DEBUG("MQTT is disabled in configuration - skipping connection"); + LOG_DEBUG(TAG, "MQTT is disabled in configuration - skipping connection"); return; } if (_mqttClient.connected()) { - LOG_DEBUG("Already connected to MQTT"); + LOG_DEBUG(TAG, "Already connected to MQTT"); return; } // Track connection attempt _lastConnectionAttempt = millis(); - LOG_INFO("Free heap BEFORE MQTT connect: %d bytes", ESP.getFreeHeap()); + LOG_INFO(TAG, "Free heap BEFORE MQTT connect: %d bytes", ESP.getFreeHeap()); _mqttClient.connect(); - LOG_INFO("MQTT connect() called - waiting for async connection..."); + LOG_INFO(TAG, "MQTT connect() called - waiting for async connection..."); } void MQTTAsyncClient::disconnect() { _mqttClient.disconnect(); - LOG_INFO("Disconnected from MQTT broker"); + LOG_INFO(TAG, "Disconnected from MQTT broker"); } uint16_t MQTTAsyncClient::publish(const String& topic, const String& payload, int qos, bool retain) { @@ -155,7 +157,7 @@ uint16_t MQTTAsyncClient::publish(const String& topic, const String& payload, in uint16_t packetId = _mqttClient.publish(fullTopic.c_str(), qos, retain, payload.c_str()); if (packetId > 0) { - LOG_DEBUG("Published to %s: %s (packetId=%d)", fullTopic.c_str(), payload.c_str(), packetId); + LOG_DEBUG(TAG, "Published to %s: %s (packetId=%d)", fullTopic.c_str(), payload.c_str(), packetId); } // REMOVED: Error logging here to prevent infinite recursion with MQTT logs @@ -175,11 +177,11 @@ void MQTTAsyncClient::onNetworkConnected() { // 🔥 Only attempt connection if MQTT is enabled if (!mqttConfig.enabled) { - LOG_DEBUG("Network connected but MQTT is disabled - skipping MQTT connection"); + LOG_DEBUG(TAG, "Network connected but MQTT is disabled - skipping MQTT connection"); return; } - LOG_DEBUG("Network connected - scheduling MQTT connection after 2s stabilization (non-blocking)"); + LOG_DEBUG(TAG, "Network connected - scheduling MQTT connection after 2s stabilization (non-blocking)"); // Reset reconnect attempts on fresh network connection _reconnectAttempts = 0; @@ -189,14 +191,14 @@ void MQTTAsyncClient::onNetworkConnected() { if (_networkStabilizationTimer) { xTimerStart(_networkStabilizationTimer, 0); } else { - LOG_ERROR("Network stabilization timer not initialized!"); + LOG_ERROR(TAG, "Network stabilization timer not initialized!"); // Fallback to immediate connection (better than blocking) connect(); } } void MQTTAsyncClient::onNetworkDisconnected() { - LOG_DEBUG("Network disconnected - MQTT will auto-reconnect when network returns"); + LOG_DEBUG(TAG, "Network disconnected - MQTT will auto-reconnect when network returns"); if (_mqttClient.connected()) { _mqttClient.disconnect(true); @@ -205,12 +207,12 @@ void MQTTAsyncClient::onNetworkDisconnected() { void MQTTAsyncClient::subscribe() { uint16_t packetId = _mqttClient.subscribe(_controlTopic.c_str(), 0); - LOG_INFO("📬 Subscribing to control topic: %s (packetId=%d)", _controlTopic.c_str(), packetId); + LOG_INFO(TAG, "📬 Subscribing to control topic: %s (packetId=%d)", _controlTopic.c_str(), packetId); } void MQTTAsyncClient::onMqttConnect(bool sessionPresent) { - LOG_INFO("✅ Connected to MQTT broker (session present: %s)", sessionPresent ? "yes" : "no"); - LOG_INFO("🔍 Free heap AFTER MQTT connect: %d bytes", ESP.getFreeHeap()); + LOG_INFO(TAG, "✅ Connected to MQTT broker (session present: %s)", sessionPresent ? "yes" : "no"); + LOG_INFO(TAG, "🔍 Free heap AFTER MQTT connect: %d bytes", ESP.getFreeHeap()); // Reset reconnection attempts on successful connection _reconnectAttempts = 0; @@ -250,14 +252,14 @@ void MQTTAsyncClient::onMqttDisconnect(AsyncMqttClientDisconnectReason reason) { break; } - LOG_ERROR("❌ Disconnected from MQTT broker - Reason: %s (%d)", reasonStr, static_cast(reason)); + LOG_ERROR(TAG, "❌ Disconnected from MQTT broker - Reason: %s (%d)", reasonStr, static_cast(reason)); // Stop heartbeat timer when disconnected stopHeartbeat(); // 🔥 Don't attempt reconnection if MQTT is disabled if (!mqttConfig.enabled) { - LOG_INFO("MQTT is disabled - not attempting reconnection"); + LOG_INFO(TAG, "MQTT is disabled - not attempting reconnection"); return; } @@ -268,24 +270,24 @@ void MQTTAsyncClient::onMqttDisconnect(AsyncMqttClientDisconnectReason reason) { // Calculate backoff delay unsigned long reconnectDelay = getReconnectDelay(); - LOG_INFO("Network still connected - scheduling MQTT reconnection #%d in %lu seconds (backoff active)", + LOG_INFO(TAG, "Network still connected - scheduling MQTT reconnection #%d in %lu seconds (backoff active)", _reconnectAttempts, reconnectDelay / 1000); // Update timer period with new delay xTimerChangePeriod(_mqttReconnectTimer, pdMS_TO_TICKS(reconnectDelay), 0); xTimerStart(_mqttReconnectTimer, 0); } else { - LOG_INFO("Network is down - waiting for network to reconnect"); + LOG_INFO(TAG, "Network is down - waiting for network to reconnect"); } } void MQTTAsyncClient::onMqttSubscribe(uint16_t packetId, uint8_t qos) { - LOG_INFO("✅ Subscribed to topic (packetId=%d, QoS=%d)", packetId, qos); + LOG_INFO(TAG, "✅ Subscribed to topic (packetId=%d, QoS=%d)", packetId, qos); } void MQTTAsyncClient::onMqttUnsubscribe(uint16_t packetId) { - LOG_DEBUG("Unsubscribed from topic (packetId=%d)", packetId); + LOG_DEBUG(TAG, "Unsubscribed from topic (packetId=%d)", packetId); } void MQTTAsyncClient::onMqttMessage(char* topic, char* payload, AsyncMqttClientMessageProperties properties, size_t len, size_t index, size_t total) { @@ -293,7 +295,7 @@ void MQTTAsyncClient::onMqttMessage(char* topic, char* payload, AsyncMqttClientM String topicStr = String(topic); String payloadStr = String(payload).substring(0, len); - LOG_DEBUG("MQTT message received - topic: %s, payload: %s", topicStr.c_str(), payloadStr.c_str()); + LOG_DEBUG(TAG, "MQTT message received - topic: %s, payload: %s", topicStr.c_str(), payloadStr.c_str()); // Call user callback if (_messageCallback) { @@ -302,16 +304,16 @@ void MQTTAsyncClient::onMqttMessage(char* topic, char* payload, AsyncMqttClientM } void MQTTAsyncClient::onMqttPublish(uint16_t packetId) { - LOG_DEBUG("MQTT publish acknowledged (packetId=%d)", packetId); + LOG_DEBUG(TAG, "MQTT publish acknowledged (packetId=%d)", packetId); } void MQTTAsyncClient::attemptReconnection() { // Double-check network is still up if (_networking.isConnected()) { - LOG_INFO("Attempting MQTT reconnection..."); + LOG_INFO(TAG, "Attempting MQTT reconnection..."); connect(); } else { - LOG_WARNING("Network down during reconnect attempt - aborting"); + LOG_WARNING(TAG, "Network down during reconnect attempt - aborting"); } } @@ -331,7 +333,7 @@ void MQTTAsyncClient::mqttReconnectTimerCallback(TimerHandle_t xTimer) { void MQTTAsyncClient::startHeartbeat() { if (_heartbeatTimer) { - LOG_INFO("💓 Starting MQTT heartbeat (every %d seconds)", HEARTBEAT_INTERVAL / 1000); + LOG_INFO(TAG, "💓 Starting MQTT heartbeat (every %d seconds)", HEARTBEAT_INTERVAL / 1000); // Publish first heartbeat immediately publishHeartbeat(); @@ -344,13 +346,13 @@ void MQTTAsyncClient::startHeartbeat() { void MQTTAsyncClient::stopHeartbeat() { if (_heartbeatTimer) { xTimerStop(_heartbeatTimer, 0); - LOG_INFO("❤️ Stopped MQTT heartbeat"); + LOG_INFO(TAG, "❤️ Stopped MQTT heartbeat"); } } void MQTTAsyncClient::publishHeartbeat() { if (!_mqttClient.connected()) { - LOG_WARNING("⚠️ Cannot publish heartbeat - MQTT not connected"); + LOG_WARNING(TAG, "⚠️ Cannot publish heartbeat - MQTT not connected"); return; } @@ -397,10 +399,10 @@ void MQTTAsyncClient::publishHeartbeat() { uint16_t packetId = _mqttClient.publish(heartbeatTopic.c_str(), 1, true, heartbeatMessage.c_str()); if (packetId > 0) { - LOG_DEBUG("💓 Published heartbeat (retained) - IP: %s, Uptime: %lums", + LOG_DEBUG(TAG, "💓 Published heartbeat (retained) - IP: %s, Uptime: %lums", _networking.getLocalIP().c_str(), uptimeMs); } else { - LOG_ERROR("❌ Failed to publish heartbeat"); + LOG_ERROR(TAG, "❌ Failed to publish heartbeat"); } } @@ -415,7 +417,7 @@ void MQTTAsyncClient::heartbeatTimerCallback(TimerHandle_t xTimer) { // ═══════════════════════════════════════════════════════════════════════════════════ void MQTTAsyncClient::connectAfterStabilization() { - LOG_DEBUG("Network stabilization complete - connecting to MQTT"); + LOG_DEBUG(TAG, "Network stabilization complete - connecting to MQTT"); connect(); } diff --git a/vesper/src/Communication/ResponseBuilder/ResponseBuilder.cpp b/vesper/src/Communication/ResponseBuilder/ResponseBuilder.cpp index c88a6d7..5b27256 100644 --- a/vesper/src/Communication/ResponseBuilder/ResponseBuilder.cpp +++ b/vesper/src/Communication/ResponseBuilder/ResponseBuilder.cpp @@ -1,4 +1,6 @@ #include "ResponseBuilder.hpp" + +#define TAG "ResponseBuilder" #include "../../Logging/Logging.hpp" // Static member initialization @@ -72,7 +74,7 @@ String ResponseBuilder::deviceStatus(PlayerStatus playerStatus, uint32_t timeEla String result; serializeJson(statusDoc, result); - LOG_DEBUG("Device status response: %s", result.c_str()); + LOG_DEBUG(TAG, "Device status response: %s", result.c_str()); return result; } @@ -135,7 +137,7 @@ String ResponseBuilder::buildResponse(Status status, const String& type, const S String result; serializeJson(_responseDoc, result); - LOG_DEBUG("Response built: %s", result.c_str()); + LOG_DEBUG(TAG, "Response built: %s", result.c_str()); return result; } @@ -149,7 +151,7 @@ String ResponseBuilder::buildResponse(Status status, const String& type, const J String result; serializeJson(_responseDoc, result); - LOG_DEBUG("Response built: %s", result.c_str()); + LOG_DEBUG(TAG, "Response built: %s", result.c_str()); return result; } diff --git a/vesper/src/Communication/UARTCommandHandler/UARTCommandHandler.cpp b/vesper/src/Communication/UARTCommandHandler/UARTCommandHandler.cpp index e9bee20..46a8425 100644 --- a/vesper/src/Communication/UARTCommandHandler/UARTCommandHandler.cpp +++ b/vesper/src/Communication/UARTCommandHandler/UARTCommandHandler.cpp @@ -3,6 +3,8 @@ */ #include "UARTCommandHandler.hpp" + +#define TAG "UARTHandler" #include "../../Logging/Logging.hpp" UARTCommandHandler::UARTCommandHandler(uint8_t txPin, uint8_t rxPin, uint32_t baudRate) @@ -24,10 +26,10 @@ UARTCommandHandler::~UARTCommandHandler() { } void UARTCommandHandler::begin() { - LOG_INFO("Initializing UART Command Handler"); - LOG_INFO(" TX Pin: GPIO%d", _txPin); - LOG_INFO(" RX Pin: GPIO%d", _rxPin); - LOG_INFO(" Baud Rate: %u", _baudRate); + LOG_INFO(TAG, "Initializing UART Command Handler"); + LOG_INFO(TAG, " TX Pin: GPIO%d", _txPin); + LOG_INFO(TAG, " RX Pin: GPIO%d", _rxPin); + LOG_INFO(TAG, " Baud Rate: %u", _baudRate); // Initialize Serial2 with custom pins _serial.begin(_baudRate, SERIAL_8N1, _rxPin, _txPin); @@ -38,7 +40,7 @@ void UARTCommandHandler::begin() { } _ready = true; - LOG_INFO("UART Command Handler ready"); + LOG_INFO(TAG, "UART Command Handler ready"); } void UARTCommandHandler::loop() { @@ -65,7 +67,7 @@ void UARTCommandHandler::loop() { _buffer[_bufferIndex++] = c; } else { // Buffer overflow - discard and reset - LOG_ERROR("UART buffer overflow, discarding message"); + LOG_ERROR(TAG, "UART buffer overflow, discarding message"); _errorCount++; resetBuffer(); } @@ -78,7 +80,7 @@ void UARTCommandHandler::setCallback(MessageCallback callback) { void UARTCommandHandler::send(const String& response) { if (!_ready) { - LOG_ERROR("UART not ready, cannot send response"); + LOG_ERROR(TAG, "UART not ready, cannot send response"); return; } @@ -86,11 +88,11 @@ void UARTCommandHandler::send(const String& response) { _serial.print('\n'); // Newline delimiter _serial.flush(); // Ensure data is sent - LOG_DEBUG("UART TX: %s", response.c_str()); + LOG_DEBUG(TAG, "UART TX: %s", response.c_str()); } void UARTCommandHandler::processLine(const char* line) { - LOG_DEBUG("UART RX: %s", line); + LOG_DEBUG(TAG, "UART RX: %s", line); // Skip empty lines or whitespace-only if (strlen(line) == 0) return; @@ -100,7 +102,7 @@ void UARTCommandHandler::processLine(const char* line) { DeserializationError error = deserializeJson(doc, line); if (error) { - LOG_ERROR("UART JSON parse error: %s", error.c_str()); + LOG_ERROR(TAG, "UART JSON parse error: %s", error.c_str()); _errorCount++; // Send error response back @@ -121,7 +123,7 @@ void UARTCommandHandler::processLine(const char* line) { if (_callback) { _callback(doc); } else { - LOG_WARNING("UART message received but no callback set"); + LOG_WARNING(TAG, "UART message received but no callback set"); } } diff --git a/vesper/src/Communication/WebSocketServer/WebSocketServer.cpp b/vesper/src/Communication/WebSocketServer/WebSocketServer.cpp index 7fa8420..6c477a2 100644 --- a/vesper/src/Communication/WebSocketServer/WebSocketServer.cpp +++ b/vesper/src/Communication/WebSocketServer/WebSocketServer.cpp @@ -3,6 +3,8 @@ */ #include "WebSocketServer.hpp" + +#define TAG "WebSocket" #include "../../Logging/Logging.hpp" #include "../ResponseBuilder/ResponseBuilder.hpp" @@ -23,7 +25,7 @@ WebSocketServer::~WebSocketServer() { void WebSocketServer::begin() { _webSocket.onEvent(onEvent); - LOG_INFO("WebSocket server initialized on /ws"); + LOG_INFO(TAG, "WebSocket server initialized on /ws"); // 🔥 CRITICAL: This line was missing - attach WebSocket to the AsyncWebServer // Without this, the server doesn't know about the WebSocket handler! @@ -40,17 +42,17 @@ void WebSocketServer::sendToClient(uint32_t clientId, const String& message) { void WebSocketServer::broadcastToAll(const String& message) { _clientManager.broadcastToAll(message); - LOG_DEBUG("Broadcast to all WebSocket clients: %s", message.c_str()); + LOG_DEBUG(TAG, "Broadcast to all WebSocket clients: %s", message.c_str()); } void WebSocketServer::broadcastToMaster(const String& message) { _clientManager.sendToMasterClients(message); - LOG_DEBUG("Broadcast to master clients: %s", message.c_str()); + LOG_DEBUG(TAG, "Broadcast to master clients: %s", message.c_str()); } void WebSocketServer::broadcastToSecondary(const String& message) { _clientManager.sendToSecondaryClients(message); - LOG_DEBUG("Broadcast to secondary clients: %s", message.c_str()); + LOG_DEBUG(TAG, "Broadcast to secondary clients: %s", message.c_str()); } bool WebSocketServer::hasClients() const { @@ -64,7 +66,7 @@ size_t WebSocketServer::getClientCount() const { void WebSocketServer::onEvent(AsyncWebSocket* server, AsyncWebSocketClient* client, AwsEventType type, void* arg, uint8_t* data, size_t len) { if (!_instance) { - LOG_ERROR("WebSocketServer static instance is NULL - callback ignored!"); + LOG_ERROR(TAG, "WebSocketServer static instance is NULL - callback ignored!"); return; } @@ -82,7 +84,7 @@ void WebSocketServer::onEvent(AsyncWebSocket* server, AsyncWebSocketClient* clie break; case WS_EVT_ERROR: - LOG_ERROR("WebSocket client #%u error(%u): %s", + LOG_ERROR(TAG, "WebSocket client #%u error(%u): %s", client->id(), *((uint16_t*)arg), (char*)data); break; @@ -92,7 +94,7 @@ void WebSocketServer::onEvent(AsyncWebSocket* server, AsyncWebSocketClient* clie } void WebSocketServer::onConnect(AsyncWebSocketClient* client) { - LOG_INFO("WebSocket client #%u connected from %s", + LOG_INFO(TAG, "WebSocket client #%u connected from %s", client->id(), client->remoteIP().toString().c_str()); // Add client to manager (type UNKNOWN until they identify) @@ -104,7 +106,7 @@ void WebSocketServer::onConnect(AsyncWebSocketClient* client) { } void WebSocketServer::onDisconnect(AsyncWebSocketClient* client) { - LOG_INFO("WebSocket client #%u disconnected", client->id()); + LOG_INFO(TAG, "WebSocket client #%u disconnected", client->id()); _clientManager.removeClient(client->id()); _clientManager.cleanupDisconnectedClients(); @@ -118,7 +120,7 @@ void WebSocketServer::onData(AsyncWebSocketClient* client, void* arg, uint8_t* d // Allocate buffer for payload char* payload = (char*)malloc(len + 1); if (!payload) { - LOG_ERROR("Failed to allocate memory for WebSocket payload"); + LOG_ERROR(TAG, "Failed to allocate memory for WebSocket payload"); String errorResponse = ResponseBuilder::error("memory_error", "Out of memory"); _clientManager.sendToClient(client->id(), errorResponse); return; @@ -127,14 +129,14 @@ void WebSocketServer::onData(AsyncWebSocketClient* client, void* arg, uint8_t* d memcpy(payload, data, len); payload[len] = '\0'; - LOG_DEBUG("WebSocket client #%u sent: %s", client->id(), payload); + LOG_DEBUG(TAG, "WebSocket client #%u sent: %s", client->id(), payload); // Parse JSON StaticJsonDocument<2048> doc; DeserializationError error = deserializeJson(doc, payload); if (error) { - LOG_ERROR("Failed to parse WebSocket JSON from client #%u: %s", client->id(), error.c_str()); + LOG_ERROR(TAG, "Failed to parse WebSocket JSON from client #%u: %s", client->id(), error.c_str()); String errorResponse = ResponseBuilder::error("parse_error", "Invalid JSON"); _clientManager.sendToClient(client->id(), errorResponse); } else { @@ -143,15 +145,15 @@ void WebSocketServer::onData(AsyncWebSocketClient* client, void* arg, uint8_t* d // Call user callback if set if (_messageCallback) { - LOG_DEBUG("Routing message from client #%u to callback handler", client->id()); + LOG_DEBUG(TAG, "Routing message from client #%u to callback handler", client->id()); _messageCallback(client->id(), doc); } else { - LOG_WARNING("WebSocket message received but no callback handler is set!"); + LOG_WARNING(TAG, "WebSocket message received but no callback handler is set!"); } } free(payload); } else { - LOG_WARNING("Received fragmented or non-text WebSocket message from client #%u - ignoring", client->id()); + LOG_WARNING(TAG, "Received fragmented or non-text WebSocket message from client #%u - ignoring", client->id()); } } diff --git a/vesper/src/ConfigManager/ConfigManager.cpp b/vesper/src/ConfigManager/ConfigManager.cpp index 7d192a4..4d3e9f7 100644 --- a/vesper/src/ConfigManager/ConfigManager.cpp +++ b/vesper/src/ConfigManager/ConfigManager.cpp @@ -1,4 +1,6 @@ #include "ConfigManager.hpp" + +#define TAG "ConfigManager" #include "../../src/Logging/Logging.hpp" #include // For MAC address generation #include // For timestamp generation @@ -27,7 +29,7 @@ void ConfigManager::initializeCleanDefaults() { // Set MQTT user to deviceUID for unique identification mqttConfig.user = deviceConfig.deviceUID; - LOG_DEBUG("ConfigManager - Clean defaults initialized with auto-generated identifiers"); + LOG_DEBUG(TAG, "ConfigManager - Clean defaults initialized with auto-generated identifiers"); } void ConfigManager::generateNetworkIdentifiers() { @@ -36,7 +38,7 @@ void ConfigManager::generateNetworkIdentifiers() { networkConfig.apSsid = "BellSystems-Setup-" + deviceConfig.deviceUID; - LOG_DEBUG("ConfigManager - Generated hostname: %s, AP SSID: %s", + LOG_DEBUG(TAG, "ConfigManager - Generated hostname: %s, AP SSID: %s", networkConfig.hostname.c_str(), networkConfig.apSsid.c_str()); } @@ -49,11 +51,11 @@ void ConfigManager::createDefaultBellConfig() { } bool ConfigManager::begin() { - LOG_INFO("ConfigManager - ✅ Initializing..."); + LOG_INFO(TAG, "ConfigManager - ✅ Initializing..."); // Step 1: Initialize NVS for device identity (factory-set, permanent) if (!initializeNVS()) { - LOG_ERROR("ConfigManager - ❌ NVS initialization failed, using empty defaults"); + LOG_ERROR(TAG, "ConfigManager - ❌ NVS initialization failed, using empty defaults"); } else { // Load device identity from NVS (deviceUID, hwType, hwVersion) loadDeviceIdentityFromNVS(); @@ -64,58 +66,58 @@ bool ConfigManager::begin() { // Step 3: Initialize SD card for user-configurable settings if (!ensureSDCard()) { - LOG_ERROR("ConfigManager - ❌ SD Card initialization failed, using defaults"); + LOG_ERROR(TAG, "ConfigManager - ❌ SD Card initialization failed, using defaults"); return false; } // Step 5: Load update servers list if (!loadUpdateServers()) { - LOG_WARNING("ConfigManager - ⚠️ Could not load update servers - using fallback only"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Could not load update servers - using fallback only"); } // Load network config, save defaults if not found if (!loadNetworkConfig()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default network config file"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default network config file"); saveNetworkConfig(); } // Load time config, save defaults if not found if (!loadTimeConfig()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default time config file (GMT+2)"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default time config file (GMT+2)"); saveTimeConfig(); } // Load bell durations, save defaults if not found if (!loadBellDurations()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default bell durations file"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default bell durations file"); saveBellDurations(); } // Load bell outputs, save defaults if not found if (!loadBellOutputs()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default bell outputs file"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default bell outputs file"); saveBellOutputs(); } // Load clock config, save defaults if not found if (!loadClockConfig()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default clock config file"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default clock config file"); saveClockConfig(); } // Load clock state, save defaults if not found if (!loadClockState()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default clock state file"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default clock state file"); saveClockState(); } if (!loadGeneralConfig()) { - LOG_WARNING("ConfigManager - ⚠️ Creating default general config file"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Creating default general config file"); saveGeneralConfig(); } - LOG_INFO("ConfigManager - ✅ Initialization Complete ! UID: %s, Hostname: %s", + LOG_INFO(TAG, "ConfigManager - ✅ Initialization Complete ! UID: %s, Hostname: %s", deviceConfig.deviceUID.c_str(), networkConfig.hostname.c_str()); return true; } @@ -127,29 +129,29 @@ bool ConfigManager::begin() { bool ConfigManager::initializeNVS() { esp_err_t err = nvs_flash_init(); if (err == ESP_ERR_NVS_NO_FREE_PAGES || err == ESP_ERR_NVS_NEW_VERSION_FOUND) { - LOG_WARNING("ConfigManager - ⚠️ NVS partition truncated, erasing..."); + LOG_WARNING(TAG, "ConfigManager - ⚠️ NVS partition truncated, erasing..."); ESP_ERROR_CHECK(nvs_flash_erase()); err = nvs_flash_init(); } if (err != ESP_OK) { - LOG_ERROR("ConfigManager - ❌ Failed to initialize NVS flash: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to initialize NVS flash: %s", esp_err_to_name(err)); return false; } err = nvs_open(NVS_NAMESPACE, NVS_READWRITE, &nvsHandle); if (err != ESP_OK) { - LOG_ERROR("ConfigManager - ❌ Failed to open NVS handle: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to open NVS handle: %s", esp_err_to_name(err)); return false; } - LOG_DEBUG("ConfigManager - NVS initialized successfully"); + LOG_DEBUG(TAG, "ConfigManager - NVS initialized successfully"); return true; } bool ConfigManager::loadDeviceIdentityFromNVS() { if (nvsHandle == 0) { - LOG_ERROR("ConfigManager - ❌ NVS not initialized, cannot load device identity"); + LOG_ERROR(TAG, "ConfigManager - ❌ NVS not initialized, cannot load device identity"); return false; } @@ -160,21 +162,21 @@ bool ConfigManager::loadDeviceIdentityFromNVS() { // Validate that factory identity exists if (deviceConfig.deviceUID.isEmpty() || deviceConfig.hwType.isEmpty() || deviceConfig.hwVersion.isEmpty()) { - LOG_ERROR("═══════════════════════════════════════════════════════════════════════════"); - LOG_ERROR(" ⚠️ CRITICAL: DEVICE IDENTITY NOT FOUND IN NVS"); - LOG_ERROR(" ⚠️ This device has NOT been factory-programmed!"); - LOG_ERROR(" ⚠️ Please flash factory firmware to set device identity"); - LOG_ERROR("═══════════════════════════════════════════════════════════════════════════"); + LOG_ERROR(TAG, "═══════════════════════════════════════════════════════════════════════════"); + LOG_ERROR(TAG, " ⚠️ CRITICAL: DEVICE IDENTITY NOT FOUND IN NVS"); + LOG_ERROR(TAG, " ⚠️ This device has NOT been factory-programmed!"); + LOG_ERROR(TAG, " ⚠️ Please flash factory firmware to set device identity"); + LOG_ERROR(TAG, "═══════════════════════════════════════════════════════════════════════════"); return false; } - LOG_INFO("═══════════════════════════════════════════════════════════════════════════"); - LOG_INFO(" 🏭 FACTORY DEVICE IDENTITY LOADED FROM NVS (READ-ONLY)"); - LOG_INFO(" 🆔 Device UID: %s", deviceConfig.deviceUID.c_str()); - LOG_INFO(" 🔧 Hardware Type: %s", deviceConfig.hwType.c_str()); - LOG_INFO(" 📐 Hardware Version: %s", deviceConfig.hwVersion.c_str()); - LOG_INFO(" 🔒 These values are PERMANENT and cannot be changed by production firmware"); - LOG_INFO("═══════════════════════════════════════════════════════════════════════════"); + LOG_INFO(TAG, "═══════════════════════════════════════════════════════════════════════════"); + LOG_INFO(TAG, " 🏭 FACTORY DEVICE IDENTITY LOADED FROM NVS (READ-ONLY)"); + LOG_INFO(TAG, " 🆔 Device UID: %s", deviceConfig.deviceUID.c_str()); + LOG_INFO(TAG, " 🔧 Hardware Type: %s", deviceConfig.hwType.c_str()); + LOG_INFO(TAG, " 📐 Hardware Version: %s", deviceConfig.hwVersion.c_str()); + LOG_INFO(TAG, " 🔒 These values are PERMANENT and cannot be changed by production firmware"); + LOG_INFO(TAG, "═══════════════════════════════════════════════════════════════════════════"); return true; } @@ -185,7 +187,7 @@ bool ConfigManager::loadDeviceIdentityFromNVS() { String ConfigManager::readNVSString(const char* key, const String& defaultValue) { if (nvsHandle == 0) { - LOG_ERROR("ConfigManager - ❌ NVS not initialized, returning default for key: %s", key); + LOG_ERROR(TAG, "ConfigManager - ❌ NVS not initialized, returning default for key: %s", key); return defaultValue; } @@ -193,12 +195,12 @@ String ConfigManager::readNVSString(const char* key, const String& defaultValue) esp_err_t err = nvs_get_str(nvsHandle, key, NULL, &required_size); if (err == ESP_ERR_NVS_NOT_FOUND) { - LOG_DEBUG("ConfigManager - NVS key '%s' not found, using default: %s", key, defaultValue.c_str()); + LOG_DEBUG(TAG, "ConfigManager - NVS key '%s' not found, using default: %s", key, defaultValue.c_str()); return defaultValue; } if (err != ESP_OK) { - LOG_ERROR("ConfigManager - ❌ Error reading NVS key '%s': %s", key, esp_err_to_name(err)); + LOG_ERROR(TAG, "ConfigManager - ❌ Error reading NVS key '%s': %s", key, esp_err_to_name(err)); return defaultValue; } @@ -206,7 +208,7 @@ String ConfigManager::readNVSString(const char* key, const String& defaultValue) err = nvs_get_str(nvsHandle, key, buffer, &required_size); if (err != ESP_OK) { - LOG_ERROR("ConfigManager - ❌ Error reading NVS value for key '%s': %s", key, esp_err_to_name(err)); + LOG_ERROR(TAG, "ConfigManager - ❌ Error reading NVS value for key '%s': %s", key, esp_err_to_name(err)); delete[] buffer; return defaultValue; } @@ -214,7 +216,7 @@ String ConfigManager::readNVSString(const char* key, const String& defaultValue) String result = String(buffer); delete[] buffer; - LOG_VERBOSE("ConfigManager - Read NVS key '%s': %s", key, result.c_str()); + LOG_VERBOSE(TAG, "ConfigManager - Read NVS key '%s': %s", key, result.c_str()); return result; } @@ -226,7 +228,7 @@ bool ConfigManager::ensureSDCard() { if (!sdInitialized) { sdInitialized = SD.begin(hardwareConfig.sdChipSelect); if (!sdInitialized) { - LOG_ERROR("ConfigManager - ❌ SD Card not available"); + LOG_ERROR(TAG, "ConfigManager - ❌ SD Card not available"); } } return sdInitialized; @@ -258,12 +260,12 @@ bool ConfigManager::saveDeviceConfig() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize device config JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize device config JSON"); return false; } saveFileToSD("/settings", "deviceConfig.json", buffer); - LOG_DEBUG("ConfigManager - Device config saved - FwVer: %s", deviceConfig.fwVersion.c_str()); + LOG_DEBUG(TAG, "ConfigManager - Device config saved - FwVer: %s", deviceConfig.fwVersion.c_str()); return true; } @@ -272,7 +274,7 @@ bool ConfigManager::loadDeviceConfig() { File file = SD.open("/settings/deviceConfig.json", FILE_READ); if (!file) { - LOG_WARNING("ConfigManager - ⚠️ Device config file not found - using firmware version default"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Device config file not found - using firmware version default"); return false; } @@ -281,13 +283,13 @@ bool ConfigManager::loadDeviceConfig() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse device config from SD: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse device config from SD: %s", error.c_str()); return false; } if (doc.containsKey("fwVersion")) { deviceConfig.fwVersion = doc["fwVersion"].as(); - LOG_VERBOSE("ConfigManager - Firmware version loaded from SD: %s", deviceConfig.fwVersion.c_str()); + LOG_VERBOSE(TAG, "ConfigManager - Firmware version loaded from SD: %s", deviceConfig.fwVersion.c_str()); } return true; @@ -295,22 +297,22 @@ bool ConfigManager::loadDeviceConfig() { bool ConfigManager::isHealthy() const { if (!sdInitialized) { - LOG_VERBOSE("ConfigManager - ⚠️ Unhealthy - SD card not initialized"); + LOG_VERBOSE(TAG, "ConfigManager - ⚠️ Unhealthy - SD card not initialized"); return false; } if (deviceConfig.deviceUID.isEmpty()) { - LOG_VERBOSE("ConfigManager - ⚠️ Unhealthy - Device UID not set (factory configuration required)"); + LOG_VERBOSE(TAG, "ConfigManager - ⚠️ Unhealthy - Device UID not set (factory configuration required)"); return false; } if (deviceConfig.hwType.isEmpty()) { - LOG_VERBOSE("ConfigManager - ⚠️ Unhealthy - Hardware type not set (factory configuration required)"); + LOG_VERBOSE(TAG, "ConfigManager - ⚠️ Unhealthy - Hardware type not set (factory configuration required)"); return false; } if (networkConfig.hostname.isEmpty()) { - LOG_VERBOSE("ConfigManager - ⚠️ Unhealthy - Hostname not generated (initialization issue)"); + LOG_VERBOSE(TAG, "ConfigManager - ⚠️ Unhealthy - Hostname not generated (initialization issue)"); return false; } @@ -327,7 +329,7 @@ bool ConfigManager::loadBellDurations() { File file = SD.open("/settings/relayTimings.json", FILE_READ); if (!file) { - LOG_WARNING("ConfigManager - ⚠️ Settings file not found on SD. Using default bell durations."); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Settings file not found on SD. Using default bell durations."); return false; } @@ -336,7 +338,7 @@ bool ConfigManager::loadBellDurations() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse settings from SD. Using default bell durations."); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse settings from SD. Using default bell durations."); return false; } @@ -347,7 +349,7 @@ bool ConfigManager::loadBellDurations() { } } - LOG_DEBUG("ConfigManager - Bell durations loaded from SD"); + LOG_DEBUG(TAG, "ConfigManager - Bell durations loaded from SD"); return true; } @@ -364,12 +366,12 @@ bool ConfigManager::saveBellDurations() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize bell durations JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize bell durations JSON"); return false; } saveFileToSD("/settings", "relayTimings.json", buffer); - LOG_DEBUG("ConfigManager - Bell durations saved to SD"); + LOG_DEBUG(TAG, "ConfigManager - Bell durations saved to SD"); return true; } @@ -380,7 +382,7 @@ bool ConfigManager::loadBellOutputs() { File file = SD.open("/settings/bellOutputs.json", FILE_READ); if (!file) { - LOG_WARNING("ConfigManager - ⚠️ Bell outputs file not found on SD. Using default 1:1 mapping."); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Bell outputs file not found on SD. Using default 1:1 mapping."); return false; } @@ -389,7 +391,7 @@ bool ConfigManager::loadBellOutputs() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse bell outputs from SD. Using defaults."); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse bell outputs from SD. Using defaults."); return false; } @@ -400,7 +402,7 @@ bool ConfigManager::loadBellOutputs() { } } - LOG_DEBUG("ConfigManager - Bell outputs loaded from SD"); + LOG_DEBUG(TAG, "ConfigManager - Bell outputs loaded from SD"); return true; } @@ -417,12 +419,12 @@ bool ConfigManager::saveBellOutputs() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize bell outputs JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize bell outputs JSON"); return false; } saveFileToSD("/settings", "bellOutputs.json", buffer); - LOG_DEBUG("ConfigManager - Bell outputs saved to SD"); + LOG_DEBUG(TAG, "ConfigManager - Bell outputs saved to SD"); return true; } @@ -433,7 +435,7 @@ void ConfigManager::updateBellDurations(JsonVariant doc) { bellConfig.durations[i] = doc[key].as(); } } - LOG_DEBUG("ConfigManager - Updated bell durations"); + LOG_DEBUG(TAG, "ConfigManager - Updated bell durations"); } void ConfigManager::updateBellOutputs(JsonVariant doc) { @@ -441,10 +443,10 @@ void ConfigManager::updateBellOutputs(JsonVariant doc) { String key = String("b") + (i + 1); if (doc.containsKey(key)) { bellConfig.outputs[i] = doc[key].as() - 1; - LOG_VERBOSE("ConfigManager - Bell %d output set to %d", i + 1, bellConfig.outputs[i]); + LOG_VERBOSE(TAG, "ConfigManager - Bell %d output set to %d", i + 1, bellConfig.outputs[i]); } } - LOG_DEBUG("ConfigManager - Updated bell outputs"); + LOG_DEBUG(TAG, "ConfigManager - Updated bell outputs"); } @@ -488,13 +490,13 @@ void ConfigManager::saveFileToSD(const char* dirPath, const char* filename, cons File file = SD.open(fullPath.c_str(), FILE_WRITE); if (!file) { - LOG_ERROR("ConfigManager - ❌ Failed to open file: %s", fullPath.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to open file: %s", fullPath.c_str()); return; } file.print(data); file.close(); - LOG_VERBOSE("ConfigManager - File %s saved successfully", fullPath.c_str()); + LOG_VERBOSE(TAG, "ConfigManager - File %s saved successfully", fullPath.c_str()); } // Clock configuration methods and other remaining methods follow the same pattern... @@ -517,7 +519,7 @@ void ConfigManager::updateClockOutputs(JsonVariant doc) { if (doc.containsKey("pauseDuration")) { clockConfig.pauseDuration = doc["pauseDuration"].as(); } - LOG_DEBUG("ConfigManager - Updated Clock outputs to: C1: %d / C2: %d, Pulse: %dms, Pause: %dms", + LOG_DEBUG(TAG, "ConfigManager - Updated Clock outputs to: C1: %d / C2: %d, Pulse: %dms, Pause: %dms", clockConfig.c1output, clockConfig.c2output, clockConfig.pulseDuration, clockConfig.pauseDuration); } @@ -543,7 +545,7 @@ void ConfigManager::updateClockAlerts(JsonVariant doc) { // Convert from 1-based (API) to 0-based (internal), or keep 255 (disabled) clockConfig.quarterBell = (bellNum == 255) ? 255 : bellNum - 1; } - LOG_DEBUG("ConfigManager - Updated Clock alerts"); + LOG_DEBUG(TAG, "ConfigManager - Updated Clock alerts"); } void ConfigManager::updateClockBacklight(JsonVariant doc) { @@ -559,7 +561,7 @@ void ConfigManager::updateClockBacklight(JsonVariant doc) { if (doc.containsKey("offTime")) { clockConfig.backlightOffTime = doc["offTime"].as(); } - LOG_DEBUG("ConfigManager - Updated Clock backlight"); + LOG_DEBUG(TAG, "ConfigManager - Updated Clock backlight"); } void ConfigManager::updateClockSilence(JsonVariant doc) { @@ -587,7 +589,7 @@ void ConfigManager::updateClockSilence(JsonVariant doc) { clockConfig.nighttimeSilenceOffTime = nighttime["offTime"].as(); } } - LOG_DEBUG("ConfigManager - Updated Clock silence"); + LOG_DEBUG(TAG, "ConfigManager - Updated Clock silence"); } bool ConfigManager::loadClockConfig() { @@ -595,7 +597,7 @@ bool ConfigManager::loadClockConfig() { File file = SD.open("/settings/clockConfig.json", FILE_READ); if (!file) { - LOG_WARNING("ConfigManager - ⚠️ Clock config file not found - using defaults"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Clock config file not found - using defaults"); return false; } @@ -604,7 +606,7 @@ bool ConfigManager::loadClockConfig() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse clock config from SD: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse clock config from SD: %s", error.c_str()); return false; } @@ -636,7 +638,7 @@ bool ConfigManager::loadClockConfig() { if (doc.containsKey("nighttimeSilenceOnTime")) clockConfig.nighttimeSilenceOnTime = doc["nighttimeSilenceOnTime"].as(); if (doc.containsKey("nighttimeSilenceOffTime")) clockConfig.nighttimeSilenceOffTime = doc["nighttimeSilenceOffTime"].as(); - LOG_DEBUG("ConfigManager - Clock config loaded"); + LOG_DEBUG(TAG, "ConfigManager - Clock config loaded"); return true; } @@ -677,12 +679,12 @@ bool ConfigManager::saveClockConfig() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize clock config JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize clock config JSON"); return false; } saveFileToSD("/settings", "clockConfig.json", buffer); - LOG_DEBUG("ConfigManager - Clock config saved"); + LOG_DEBUG(TAG, "ConfigManager - Clock config saved"); return true; } @@ -691,7 +693,7 @@ bool ConfigManager::loadClockState() { File file = SD.open("/settings/clockState.json", FILE_READ); if (!file) { - LOG_WARNING("ConfigManager - ⚠️ Clock state file not found - using defaults"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Clock state file not found - using defaults"); clockConfig.physicalHour = 0; clockConfig.physicalMinute = 0; clockConfig.nextOutputIsC1 = true; @@ -704,7 +706,7 @@ bool ConfigManager::loadClockState() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse clock state from SD: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse clock state from SD: %s", error.c_str()); return false; } @@ -713,7 +715,7 @@ bool ConfigManager::loadClockState() { clockConfig.nextOutputIsC1 = doc["nextIsC1"].as(); clockConfig.lastSyncTime = doc["lastSyncTime"].as(); - LOG_DEBUG("ConfigManager - Clock state loaded"); + LOG_DEBUG(TAG, "ConfigManager - Clock state loaded"); return true; } @@ -730,12 +732,12 @@ bool ConfigManager::saveClockState() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize clock state JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize clock state JSON"); return false; } saveFileToSD("/settings", "clockState.json", buffer); - LOG_VERBOSE("ConfigManager - Clock state saved"); + LOG_VERBOSE(TAG, "ConfigManager - Clock state saved"); return true; } @@ -744,7 +746,7 @@ bool ConfigManager::loadUpdateServers() { File file = SD.open("/settings/updateServers.json", FILE_READ); if (!file) { - LOG_DEBUG("ConfigManager - Update servers file not found - using fallback only"); + LOG_DEBUG(TAG, "ConfigManager - Update servers file not found - using fallback only"); return false; } @@ -753,7 +755,7 @@ bool ConfigManager::loadUpdateServers() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse update servers JSON: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse update servers JSON: %s", error.c_str()); return false; } @@ -770,7 +772,7 @@ bool ConfigManager::loadUpdateServers() { } } - LOG_DEBUG("ConfigManager - Loaded %d update servers from SD card", updateServers.size()); + LOG_DEBUG(TAG, "ConfigManager - Loaded %d update servers from SD card", updateServers.size()); return true; } @@ -787,7 +789,7 @@ void ConfigManager::updateTimeConfig(long gmtOffsetSec, int daylightOffsetSec) { timeConfig.gmtOffsetSec = gmtOffsetSec; timeConfig.daylightOffsetSec = daylightOffsetSec; saveTimeConfig(); // Save time config specifically - LOG_DEBUG("ConfigManager - TimeConfig updated - GMT offset %ld sec, DST offset %d sec", + LOG_DEBUG(TAG, "ConfigManager - TimeConfig updated - GMT offset %ld sec, DST offset %d sec", gmtOffsetSec, daylightOffsetSec); } @@ -801,7 +803,7 @@ void ConfigManager::updateNetworkConfig(const String& hostname, bool useStaticIP networkConfig.dns1 = dns1; networkConfig.dns2 = dns2; saveNetworkConfig(); // Save immediately to SD - LOG_DEBUG("ConfigManager - NetworkConfig updated - Hostname: %s, Static IP: %s, IP: %s", + LOG_DEBUG(TAG, "ConfigManager - NetworkConfig updated - Hostname: %s, Static IP: %s, IP: %s", hostname.c_str(), useStaticIP ? "enabled" : "disabled", ip.toString().c_str()); } @@ -814,7 +816,7 @@ bool ConfigManager::loadNetworkConfig() { File file = SD.open("/settings/networkConfig.json", FILE_READ); if (!file) { - LOG_DEBUG("ConfigManager - Network config file not found - using auto-generated hostname and DHCP"); + LOG_DEBUG(TAG, "ConfigManager - Network config file not found - using auto-generated hostname and DHCP"); return false; } @@ -823,7 +825,7 @@ bool ConfigManager::loadNetworkConfig() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse network config from SD: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse network config from SD: %s", error.c_str()); return false; } @@ -832,7 +834,7 @@ bool ConfigManager::loadNetworkConfig() { String customHostname = doc["hostname"].as(); if (!customHostname.isEmpty()) { networkConfig.hostname = customHostname; - LOG_DEBUG("ConfigManager - Custom hostname loaded from SD: %s", customHostname.c_str()); + LOG_DEBUG(TAG, "ConfigManager - Custom hostname loaded from SD: %s", customHostname.c_str()); } } @@ -844,7 +846,7 @@ bool ConfigManager::loadNetworkConfig() { // Load permanent AP mode setting if (doc.containsKey("permanentAPMode")) { networkConfig.permanentAPMode = doc["permanentAPMode"].as(); - LOG_DEBUG("ConfigManager - Permanent AP mode: %s", networkConfig.permanentAPMode ? "enabled" : "disabled"); + LOG_DEBUG(TAG, "ConfigManager - Permanent AP mode: %s", networkConfig.permanentAPMode ? "enabled" : "disabled"); } if (doc.containsKey("ip")) { @@ -882,7 +884,7 @@ bool ConfigManager::loadNetworkConfig() { } } - LOG_DEBUG("ConfigManager - Network config loaded - Hostname: %s, Static IP: %s", + LOG_DEBUG(TAG, "ConfigManager - Network config loaded - Hostname: %s, Static IP: %s", networkConfig.hostname.c_str(), networkConfig.useStaticIP ? "enabled" : "disabled"); @@ -912,12 +914,12 @@ bool ConfigManager::saveNetworkConfig() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize network config JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize network config JSON"); return false; } saveFileToSD("/settings", "networkConfig.json", buffer); - LOG_DEBUG("ConfigManager - Network config saved to SD"); + LOG_DEBUG(TAG, "ConfigManager - Network config saved to SD"); return true; } @@ -930,7 +932,7 @@ bool ConfigManager::loadTimeConfig() { File file = SD.open("/settings/timeConfig.json", FILE_READ); if (!file) { - LOG_DEBUG("ConfigManager - Time config file not found - using defaults (GMT+2)"); + LOG_DEBUG(TAG, "ConfigManager - Time config file not found - using defaults (GMT+2)"); return false; } @@ -939,7 +941,7 @@ bool ConfigManager::loadTimeConfig() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse time config from SD: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse time config from SD: %s", error.c_str()); return false; } @@ -961,7 +963,7 @@ bool ConfigManager::loadTimeConfig() { timeConfig.daylightOffsetSec = doc["daylightOffsetSec"].as(); } - LOG_DEBUG("ConfigManager - Time config loaded - NTP: %s, GMT offset: %ld, DST offset: %d", + LOG_DEBUG(TAG, "ConfigManager - Time config loaded - NTP: %s, GMT offset: %ld, DST offset: %d", timeConfig.ntpServer.c_str(), timeConfig.gmtOffsetSec, timeConfig.daylightOffsetSec); @@ -985,12 +987,12 @@ bool ConfigManager::saveTimeConfig() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize time config JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize time config JSON"); return false; } saveFileToSD("/settings", "timeConfig.json", buffer); - LOG_DEBUG("ConfigManager - Time config saved to SD"); + LOG_DEBUG(TAG, "ConfigManager - Time config saved to SD"); return true; } @@ -1000,9 +1002,9 @@ bool ConfigManager::saveTimeConfig() { bool ConfigManager::resetAllToDefaults() { - LOG_INFO("═══════════════════════════════════════════════════════════════════════════"); - LOG_INFO(" 🏭 RESET SETTINGS TO DEFAULTS INITIATED"); - LOG_INFO("═══════════════════════════════════════════════════════════════════════════"); + LOG_INFO(TAG, "═══════════════════════════════════════════════════════════════════════════"); + LOG_INFO(TAG, " 🏭 RESET SETTINGS TO DEFAULTS INITIATED"); + LOG_INFO(TAG, "═══════════════════════════════════════════════════════════════════════════"); if (!ensureSDCard()) { return false; @@ -1029,22 +1031,22 @@ bool ConfigManager::resetAllToDefaults() { int numFiles = sizeof(settingsFiles) / sizeof(settingsFiles[0]); - LOG_DEBUG("ConfigManager - Step 1: Deleting %d configuration files...", numFiles); + LOG_DEBUG(TAG, "ConfigManager - Step 1: Deleting %d configuration files...", numFiles); for (int i = 0; i < numFiles; i++) { const char* filepath = settingsFiles[i]; if (SD.exists(filepath)) { if (SD.remove(filepath)) { - LOG_VERBOSE("ConfigManager - ✅ Deleted: %s", filepath); + LOG_VERBOSE(TAG, "ConfigManager - ✅ Deleted: %s", filepath); filesDeleted++; } else { - LOG_ERROR("ConfigManager - ❌ Failed to delete: %s", filepath); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to delete: %s", filepath); filesFailed++; allDeleted = false; } } else { - LOG_VERBOSE("ConfigManager - Skip (not found): %s", filepath); + LOG_VERBOSE(TAG, "ConfigManager - Skip (not found): %s", filepath); } } @@ -1053,7 +1055,7 @@ bool ConfigManager::resetAllToDefaults() { // ════════════════════════════════════════════════════════════════════════════ if (SD.exists("/melodies")) { - LOG_DEBUG("ConfigManager - Step 2: Deleting melody files..."); + LOG_DEBUG(TAG, "ConfigManager - Step 2: Deleting melody files..."); File melodiesDir = SD.open("/melodies"); if (melodiesDir && melodiesDir.isDirectory()) { @@ -1066,10 +1068,10 @@ bool ConfigManager::resetAllToDefaults() { if (!entry.isDirectory()) { if (SD.remove(entryPath.c_str())) { - LOG_VERBOSE("ConfigManager - ✅ Deleted melody: %s", entryPath.c_str()); + LOG_VERBOSE(TAG, "ConfigManager - ✅ Deleted melody: %s", entryPath.c_str()); melodiesDeleted++; } else { - LOG_ERROR("ConfigManager - ❌ Failed to delete melody: %s", entryPath.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to delete melody: %s", entryPath.c_str()); melodiesFailed++; allDeleted = false; } @@ -1083,33 +1085,33 @@ bool ConfigManager::resetAllToDefaults() { // Try to remove the empty directory if (SD.rmdir("/melodies")) { - LOG_VERBOSE("ConfigManager - ✅ Deleted /melodies directory"); + LOG_VERBOSE(TAG, "ConfigManager - ✅ Deleted /melodies directory"); } else { - LOG_WARNING("ConfigManager - ⚠️ Could not delete /melodies directory (may not be empty)"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Could not delete /melodies directory (may not be empty)"); } - LOG_DEBUG("ConfigManager - Melodies deleted: %d, failed: %d", melodiesDeleted, melodiesFailed); + LOG_DEBUG(TAG, "ConfigManager - Melodies deleted: %d, failed: %d", melodiesDeleted, melodiesFailed); filesDeleted += melodiesDeleted; filesFailed += melodiesFailed; } } else { - LOG_VERBOSE("ConfigManager - /melodies directory not found"); + LOG_VERBOSE(TAG, "ConfigManager - /melodies directory not found"); } // ════════════════════════════════════════════════════════════════════════════ // SUMMARY // ════════════════════════════════════════════════════════════════════════════ - LOG_INFO("═══════════════════════════════════════════════════════════════════════════"); - LOG_INFO("ConfigManager - Full reset summary:"); - LOG_INFO("ConfigManager - ✅ Files deleted: %d", filesDeleted); - LOG_INFO("ConfigManager - ❌ Files failed: %d", filesFailed); - LOG_INFO("ConfigManager - 🔄 Total processed: %d", filesDeleted + filesFailed); - LOG_INFO("═══════════════════════════════════════════════════════════════════════════"); + LOG_INFO(TAG, "═══════════════════════════════════════════════════════════════════════════"); + LOG_INFO(TAG, "ConfigManager - Full reset summary:"); + LOG_INFO(TAG, "ConfigManager - ✅ Files deleted: %d", filesDeleted); + LOG_INFO(TAG, "ConfigManager - ❌ Files failed: %d", filesFailed); + LOG_INFO(TAG, "ConfigManager - 🔄 Total processed: %d", filesDeleted + filesFailed); + LOG_INFO(TAG, "═══════════════════════════════════════════════════════════════════════════"); - LOG_INFO("ConfigManager - ✅ RESET TO DEFAULT COMPLETE"); - LOG_INFO("ConfigManager - 🔄 Device will boot with default settings on next restart"); - LOG_INFO("ConfigManager - 🆔 Device identity (UID) preserved"); + LOG_INFO(TAG, "ConfigManager - ✅ RESET TO DEFAULT COMPLETE"); + LOG_INFO(TAG, "ConfigManager - 🔄 Device will boot with default settings on next restart"); + LOG_INFO(TAG, "ConfigManager - 🆔 Device identity (UID) preserved"); return allDeleted; } @@ -1212,31 +1214,31 @@ String ConfigManager::getAllSettingsAsJson() const { bool ConfigManager::setSerialLogLevel(uint8_t level) { if (level > 5) { // Max level is VERBOSE (5) - LOG_WARNING("ConfigManager - ⚠️ Invalid serial log level %d, valid range is 0-5", level); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Invalid serial log level %d, valid range is 0-5", level); return false; } generalConfig.serialLogLevel = level; - LOG_DEBUG("ConfigManager - Serial log level set to %d", level); + LOG_DEBUG(TAG, "ConfigManager - Serial log level set to %d", level); return true; } bool ConfigManager::setSdLogLevel(uint8_t level) { if (level > 5) { // Max level is VERBOSE (5) - LOG_WARNING("ConfigManager - ⚠️ Invalid SD log level %d, valid range is 0-5", level); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Invalid SD log level %d, valid range is 0-5", level); return false; } generalConfig.sdLogLevel = level; - LOG_DEBUG("ConfigManager - SD log level set to %d", level); + LOG_DEBUG(TAG, "ConfigManager - SD log level set to %d", level); return true; } bool ConfigManager::setMqttLogLevel(uint8_t level) { if (level > 5) { // Max level is VERBOSE (5) - LOG_WARNING("ConfigManager - ⚠️ Invalid MQTT log level %d, valid range is 0-5", level); + LOG_WARNING(TAG, "ConfigManager - ⚠️ Invalid MQTT log level %d, valid range is 0-5", level); return false; } generalConfig.mqttLogLevel = level; - LOG_DEBUG("ConfigManager - MQTT log level set to %d", level); + LOG_DEBUG(TAG, "ConfigManager - MQTT log level set to %d", level); return true; } @@ -1245,7 +1247,7 @@ bool ConfigManager::loadGeneralConfig() { File file = SD.open("/settings/generalConfig.json", FILE_READ); if (!file) { - LOG_WARNING("ConfigManager - ⚠️ General config file not found - using defaults"); + LOG_WARNING(TAG, "ConfigManager - ⚠️ General config file not found - using defaults"); return false; } @@ -1254,7 +1256,7 @@ bool ConfigManager::loadGeneralConfig() { file.close(); if (error) { - LOG_ERROR("ConfigManager - ❌ Failed to parse general config from SD: %s", error.c_str()); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to parse general config from SD: %s", error.c_str()); return false; } @@ -1272,7 +1274,7 @@ bool ConfigManager::loadGeneralConfig() { mqttConfig.enabled = generalConfig.mqttEnabled; // Sync with mqttConfig } - LOG_DEBUG("ConfigManager - General config loaded - Serial log level: %d, SD log level: %d, MQTT log level: %d, MQTT enabled: %s", + LOG_DEBUG(TAG, "ConfigManager - General config loaded - Serial log level: %d, SD log level: %d, MQTT log level: %d, MQTT enabled: %s", generalConfig.serialLogLevel, generalConfig.sdLogLevel, generalConfig.mqttLogLevel, generalConfig.mqttEnabled ? "true" : "false"); return true; @@ -1291,11 +1293,11 @@ bool ConfigManager::saveGeneralConfig() { size_t len = serializeJson(doc, buffer, sizeof(buffer)); if (len == 0 || len >= sizeof(buffer)) { - LOG_ERROR("ConfigManager - ❌ Failed to serialize general config JSON"); + LOG_ERROR(TAG, "ConfigManager - ❌ Failed to serialize general config JSON"); return false; } saveFileToSD("/settings", "generalConfig.json", buffer); - LOG_DEBUG("ConfigManager - General config saved (MQTT enabled: %s)", generalConfig.mqttEnabled ? "true" : "false"); + LOG_DEBUG(TAG, "ConfigManager - General config saved (MQTT enabled: %s)", generalConfig.mqttEnabled ? "true" : "false"); return true; } diff --git a/vesper/src/ConfigManager/ConfigManager.hpp b/vesper/src/ConfigManager/ConfigManager.hpp index fd4ec2e..3c7df66 100644 --- a/vesper/src/ConfigManager/ConfigManager.hpp +++ b/vesper/src/ConfigManager/ConfigManager.hpp @@ -25,7 +25,6 @@ #include #include #include -#include #include #include #include @@ -106,8 +105,8 @@ public: uint8_t ethSpiMiso = 19; // 🔄 Hardware-specific - OK as is uint8_t ethSpiMosi = 23; // 🔄 Hardware-specific - OK as is - // ETH PHY Configuration - hardware-specific - eth_phy_type_t ethPhyType = ETH_PHY_W5500; // 🔌 Hardware-specific - OK as is + // ETH PHY Configuration - ETHERNET DISABLED (kept for legacy/future use) + uint8_t ethPhyType = 9; // was ETH_PHY_W5500 (9) — Ethernet removed in v138 uint8_t ethPhyAddr = 1; // 📍 Hardware-specific - OK as is uint8_t ethPhyCs = 5; // 💾 Hardware-specific - OK as is int8_t ethPhyIrq = -1; // ⚡ Hardware-specific - OK as is @@ -409,6 +408,8 @@ public: bool setSerialLogLevel(uint8_t level); bool setSdLogLevel(uint8_t level); bool setMqttLogLevel(uint8_t level); + uint8_t getSerialLogLevel() const { return generalConfig.serialLogLevel; } + uint8_t getSdLogLevel() const { return generalConfig.sdLogLevel; } uint8_t getMqttLogLevel() const { return generalConfig.mqttLogLevel; } void setMqttEnabled(bool enabled) { generalConfig.mqttEnabled = enabled; mqttConfig.enabled = enabled; } bool getMqttEnabled() const { return generalConfig.mqttEnabled; } diff --git a/vesper/src/FileManager/FileManager.cpp b/vesper/src/FileManager/FileManager.cpp index f354f79..cead620 100644 --- a/vesper/src/FileManager/FileManager.cpp +++ b/vesper/src/FileManager/FileManager.cpp @@ -1,4 +1,6 @@ #include "FileManager.hpp" + +#define TAG "FileManager" #include "../BuiltInMelodies/BuiltInMelodies.hpp" FileManager::FileManager(ConfigManager* config) : configManager(config) { @@ -8,18 +10,18 @@ FileManager::FileManager(ConfigManager* config) : configManager(config) { bool FileManager::initializeSD() { uint8_t sdPin = configManager->getHardwareConfig().sdChipSelect; if (!SD.begin(sdPin)) { - LOG_ERROR("SD Card initialization failed!"); + LOG_ERROR(TAG, "SD Card initialization failed!"); return false; } return true; } bool FileManager::addMelody(JsonVariant doc) { - LOG_INFO("Adding melody from JSON data..."); + LOG_INFO(TAG, "Adding melody from JSON data..."); // Extract URL and filename from JSON if (!doc.containsKey("download_url") || !doc.containsKey("melodys_uid")) { - LOG_ERROR("Missing required parameters: download_url or melodys_uid"); + LOG_ERROR(TAG, "Missing required parameters: download_url or melodys_uid"); return false; } @@ -30,20 +32,20 @@ bool FileManager::addMelody(JsonVariant doc) { if (BuiltInMelodies::isBuiltInMelody(melodyUid)) { const BuiltInMelodies::MelodyInfo* builtinMelody = BuiltInMelodies::findMelodyByUID(melodyUid); if (builtinMelody != nullptr) { - LOG_INFO("Melody '%s' is a built-in melody, skipping download", melodyUid); + LOG_INFO(TAG, "Melody '%s' is a built-in melody, skipping download", melodyUid); return true; // Success - no download needed } // If starts with builtin_ but not found, log warning and try download anyway - LOG_WARNING("Melody '%s' has builtin_ prefix but not found in library, attempting download", melodyUid); + LOG_WARNING(TAG, "Melody '%s' has builtin_ prefix but not found in library, attempting download", melodyUid); } // Download the melody file to /melodies directory if (downloadFile(url, "/melodies", melodyUid)) { - LOG_INFO("Melody download successful: %s", melodyUid); + LOG_INFO(TAG, "Melody download successful: %s", melodyUid); return true; } - LOG_ERROR("Melody download failed: %s", melodyUid); + LOG_ERROR(TAG, "Melody download failed: %s", melodyUid); return false; } @@ -68,7 +70,7 @@ bool FileManager::ensureDirectoryExists(const String& dirPath) { } bool FileManager::downloadFile(const String& url, const String& directory, const String& filename) { - LOG_INFO("Starting download from: %s", url.c_str()); + LOG_INFO(TAG, "Starting download from: %s", url.c_str()); // Check if URL is HTTPS bool isHttps = url.startsWith("https://"); @@ -82,10 +84,10 @@ bool FileManager::downloadFile(const String& url, const String& directory, const secureClient->setInsecure(); // Skip certificate validation for Firebase secureClient->setTimeout(15); // 15 second timeout for TLS operations http.begin(*secureClient, url); - LOG_DEBUG("Using HTTPS with secure client"); + LOG_DEBUG(TAG, "Using HTTPS with secure client"); } else { http.begin(url); - LOG_DEBUG("Using HTTP"); + LOG_DEBUG(TAG, "Using HTTP"); } http.setTimeout(30000); // 30 second timeout for large files @@ -93,18 +95,18 @@ bool FileManager::downloadFile(const String& url, const String& directory, const // Disable task watchdog for current task during blocking HTTPS operation // The TLS handshake can take several seconds and would trigger watchdog - LOG_DEBUG("Disabling watchdog for download..."); + LOG_DEBUG(TAG, "Disabling watchdog for download..."); esp_task_wdt_delete(NULL); - LOG_DEBUG("Sending HTTP GET request..."); + LOG_DEBUG(TAG, "Sending HTTP GET request..."); int httpCode = http.GET(); // Re-enable task watchdog after HTTP request completes esp_task_wdt_add(NULL); - LOG_DEBUG("Watchdog re-enabled after HTTP request"); + LOG_DEBUG(TAG, "Watchdog re-enabled after HTTP request"); if (httpCode != HTTP_CODE_OK && httpCode != HTTP_CODE_MOVED_PERMANENTLY && httpCode != HTTP_CODE_FOUND) { - LOG_ERROR("HTTP GET failed, code: %d, error: %s", httpCode, http.errorToString(httpCode).c_str()); + LOG_ERROR(TAG, "HTTP GET failed, code: %d, error: %s", httpCode, http.errorToString(httpCode).c_str()); http.end(); if (secureClient) delete secureClient; return false; @@ -118,7 +120,7 @@ bool FileManager::downloadFile(const String& url, const String& directory, const // Ensure directory exists if (!ensureDirectoryExists(directory)) { - LOG_ERROR("Failed to create directory: %s", directory.c_str()); + LOG_ERROR(TAG, "Failed to create directory: %s", directory.c_str()); http.end(); if (secureClient) delete secureClient; return false; @@ -131,7 +133,7 @@ bool FileManager::downloadFile(const String& url, const String& directory, const File file = SD.open(fullPath.c_str(), FILE_WRITE); if (!file) { - LOG_ERROR("Failed to open file for writing: %s", fullPath.c_str()); + LOG_ERROR(TAG, "Failed to open file for writing: %s", fullPath.c_str()); http.end(); if (secureClient) delete secureClient; return false; @@ -140,7 +142,7 @@ bool FileManager::downloadFile(const String& url, const String& directory, const // Get stream and file size WiFiClient* stream = http.getStreamPtr(); int contentLength = http.getSize(); - LOG_DEBUG("Content length: %d bytes", contentLength); + LOG_DEBUG(TAG, "Content length: %d bytes", contentLength); uint8_t buffer[512]; // Smaller buffer for better responsiveness size_t totalBytes = 0; @@ -163,7 +165,7 @@ bool FileManager::downloadFile(const String& url, const String& directory, const // Log progress every 5 seconds if (millis() - lastLog > 5000) { - LOG_DEBUG("Download progress: %u bytes", totalBytes); + LOG_DEBUG(TAG, "Download progress: %u bytes", totalBytes); lastLog = millis(); } } @@ -191,19 +193,19 @@ bool FileManager::downloadFile(const String& url, const String& directory, const file.close(); http.end(); if (secureClient) delete secureClient; - LOG_INFO("Download complete, file saved to: %s (%u bytes)", fullPath.c_str(), totalBytes); + LOG_INFO(TAG, "Download complete, file saved to: %s (%u bytes)", fullPath.c_str(), totalBytes); return true; } String FileManager::listFilesAsJson(const char* dirPath) { if (!initializeSD()) { - LOG_ERROR("SD initialization failed"); + LOG_ERROR(TAG, "SD initialization failed"); return "{}"; } File dir = SD.open(dirPath); if (!dir || !dir.isDirectory()) { - LOG_ERROR("Directory not found: %s", dirPath); + LOG_ERROR(TAG, "Directory not found: %s", dirPath); return "{}"; } @@ -242,10 +244,10 @@ bool FileManager::deleteFile(const String& filePath) { } if (SD.remove(filePath.c_str())) { - LOG_INFO("File deleted: %s", filePath.c_str()); + LOG_INFO(TAG, "File deleted: %s", filePath.c_str()); return true; } else { - LOG_ERROR("Failed to delete file: %s", filePath.c_str()); + LOG_ERROR(TAG, "Failed to delete file: %s", filePath.c_str()); return false; } } @@ -276,18 +278,18 @@ bool FileManager::writeJsonFile(const String& filePath, JsonDocument& doc) { File file = SD.open(filePath.c_str(), FILE_WRITE); if (!file) { - LOG_ERROR("Failed to open file for writing: %s", filePath.c_str()); + LOG_ERROR(TAG, "Failed to open file for writing: %s", filePath.c_str()); return false; } if (serializeJson(doc, file) == 0) { - LOG_ERROR("Failed to write JSON to file: %s", filePath.c_str()); + LOG_ERROR(TAG, "Failed to write JSON to file: %s", filePath.c_str()); file.close(); return false; } file.close(); - LOG_DEBUG("JSON file written successfully: %s", filePath.c_str()); + LOG_DEBUG(TAG, "JSON file written successfully: %s", filePath.c_str()); return true; } @@ -298,7 +300,7 @@ bool FileManager::readJsonFile(const String& filePath, JsonDocument& doc) { File file = SD.open(filePath.c_str(), FILE_READ); if (!file) { - LOG_ERROR("Failed to open file for reading: %s", filePath.c_str()); + LOG_ERROR(TAG, "Failed to open file for reading: %s", filePath.c_str()); return false; } @@ -306,12 +308,12 @@ bool FileManager::readJsonFile(const String& filePath, JsonDocument& doc) { file.close(); if (error) { - LOG_ERROR("Failed to parse JSON from file: %s, error: %s", + LOG_ERROR(TAG, "Failed to parse JSON from file: %s, error: %s", filePath.c_str(), error.c_str()); return false; } - LOG_DEBUG("JSON file read successfully: %s", filePath.c_str()); + LOG_DEBUG(TAG, "JSON file read successfully: %s", filePath.c_str()); return true; } @@ -322,26 +324,26 @@ bool FileManager::readJsonFile(const String& filePath, JsonDocument& doc) { bool FileManager::isHealthy() const { // Check if ConfigManager is available if (!configManager) { - LOG_DEBUG("FileManager: Unhealthy - ConfigManager not available"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - ConfigManager not available"); return false; } // Check if SD card can be initialized uint8_t sdPin = configManager->getHardwareConfig().sdChipSelect; if (!SD.begin(sdPin)) { - LOG_DEBUG("FileManager: Unhealthy - SD Card initialization failed"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - SD Card initialization failed"); return false; } // Check if we can read from SD card (test with root directory) File root = SD.open("/"); if (!root) { - LOG_DEBUG("FileManager: Unhealthy - Cannot access SD root directory"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - Cannot access SD root directory"); return false; } if (!root.isDirectory()) { - LOG_DEBUG("FileManager: Unhealthy - SD root is not a directory"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - SD root is not a directory"); root.close(); return false; } @@ -352,7 +354,7 @@ bool FileManager::isHealthy() const { String testFile = "/health_test.tmp"; File file = SD.open(testFile.c_str(), FILE_WRITE); if (!file) { - LOG_DEBUG("FileManager: Unhealthy - Cannot write to SD card"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - Cannot write to SD card"); return false; } @@ -362,7 +364,7 @@ bool FileManager::isHealthy() const { // Verify we can read the test file file = SD.open(testFile.c_str(), FILE_READ); if (!file) { - LOG_DEBUG("FileManager: Unhealthy - Cannot read test file from SD card"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - Cannot read test file from SD card"); return false; } @@ -373,9 +375,24 @@ bool FileManager::isHealthy() const { SD.remove(testFile.c_str()); if (content != "health_check") { - LOG_DEBUG("FileManager: Unhealthy - SD card read/write test failed"); + LOG_DEBUG(TAG, "FileManager: Unhealthy - SD card read/write test failed"); return false; } return true; } + +bool FileManager::appendLine(const String& filePath, const String& line) { + if (!initializeSD()) { + return false; + } + + File file = SD.open(filePath.c_str(), FILE_APPEND); + if (!file) { + return false; + } + + file.println(line); + file.close(); + return true; +} diff --git a/vesper/src/FileManager/FileManager.hpp b/vesper/src/FileManager/FileManager.hpp index cfacc67..07b794c 100644 --- a/vesper/src/FileManager/FileManager.hpp +++ b/vesper/src/FileManager/FileManager.hpp @@ -50,6 +50,9 @@ public: // Generic read/write for JSON data bool writeJsonFile(const String& filePath, JsonDocument& doc); bool readJsonFile(const String& filePath, JsonDocument& doc); + + // Append a single text line to a file (used by SD log channel) + bool appendLine(const String& filePath, const String& line); // ═══════════════════════════════════════════════════════════════════════════════ // HEALTH CHECK METHOD diff --git a/vesper/src/FirmwareValidator/FirmwareValidator.cpp b/vesper/src/FirmwareValidator/FirmwareValidator.cpp index 0b0bd8f..fef20fc 100644 --- a/vesper/src/FirmwareValidator/FirmwareValidator.cpp +++ b/vesper/src/FirmwareValidator/FirmwareValidator.cpp @@ -5,6 +5,8 @@ */ #include "FirmwareValidator.hpp" + +#define TAG "FirmwareValidator" #include "../HealthMonitor/HealthMonitor.hpp" #include "../ConfigManager/ConfigManager.hpp" #include @@ -43,45 +45,45 @@ FirmwareValidator::~FirmwareValidator() { } bool FirmwareValidator::begin(HealthMonitor* healthMonitor, ConfigManager* configManager) { - LOG_INFO("🛡️ Initializing Firmware Validator System"); + LOG_INFO(TAG, "🛡️ Initializing Firmware Validator System"); _healthMonitor = healthMonitor; _configManager = configManager; // Initialize NVS for persistent state storage if (!initializeNVS()) { - LOG_ERROR("❌ Failed to initialize NVS for firmware validation"); + LOG_ERROR(TAG, "❌ Failed to initialize NVS for firmware validation"); return false; } // Initialize ESP32 partition information if (!initializePartitions()) { - LOG_ERROR("❌ Failed to initialize ESP32 partitions"); + LOG_ERROR(TAG, "❌ Failed to initialize ESP32 partitions"); return false; } // Load previous validation state loadValidationState(); - LOG_INFO("✅ Firmware Validator initialized"); - LOG_INFO("📍 Running partition: %s", getPartitionLabel(_runningPartition).c_str()); - LOG_INFO("📍 Backup partition: %s", getPartitionLabel(_backupPartition).c_str()); - LOG_INFO("🔄 Validation state: %s", validationStateToString(_validationState).c_str()); + LOG_INFO(TAG, "✅ Firmware Validator initialized"); + LOG_INFO(TAG, "📍 Running partition: %s", getPartitionLabel(_runningPartition).c_str()); + LOG_INFO(TAG, "📍 Backup partition: %s", getPartitionLabel(_backupPartition).c_str()); + LOG_INFO(TAG, "🔄 Validation state: %s", validationStateToString(_validationState).c_str()); return true; } bool FirmwareValidator::performStartupValidation() { - LOG_INFO("🚀 Starting firmware startup validation..."); + LOG_INFO(TAG, "🚀 Starting firmware startup validation..."); // Check if this is a new firmware that needs validation const esp_partition_t* bootPartition = esp_ota_get_boot_partition(); const esp_partition_t* runningPartition = esp_ota_get_running_partition(); if (bootPartition != runningPartition) { - LOG_WARNING("⚠️ Boot partition differs from running partition!"); - LOG_WARNING(" Boot: %s", getPartitionLabel(bootPartition).c_str()); - LOG_WARNING(" Running: %s", getPartitionLabel(runningPartition).c_str()); + LOG_WARNING(TAG, "⚠️ Boot partition differs from running partition!"); + LOG_WARNING(TAG, " Boot: %s", getPartitionLabel(bootPartition).c_str()); + LOG_WARNING(TAG, " Running: %s", getPartitionLabel(runningPartition).c_str()); } // Increment boot count for this session @@ -91,11 +93,11 @@ bool FirmwareValidator::performStartupValidation() { if (_validationState == FirmwareValidationState::UNKNOWN) { // First boot of potentially new firmware _validationState = FirmwareValidationState::STARTUP_PENDING; - LOG_INFO("🆕 New firmware detected - entering validation mode"); + LOG_INFO(TAG, "🆕 New firmware detected - entering validation mode"); } if (_validationState == FirmwareValidationState::STARTUP_PENDING) { - LOG_INFO("🔍 Performing startup validation..."); + LOG_INFO(TAG, "🔍 Performing startup validation..."); _validationState = FirmwareValidationState::STARTUP_RUNNING; _validationStartTime = millis(); @@ -109,7 +111,7 @@ bool FirmwareValidator::performStartupValidation() { break; } - LOG_WARNING("⚠️ Startup health check failed, retrying..."); + LOG_WARNING(TAG, "⚠️ Startup health check failed, retrying..."); delay(1000); // Wait 1 second before retry } @@ -117,18 +119,18 @@ bool FirmwareValidator::performStartupValidation() { _validationState = FirmwareValidationState::RUNTIME_TESTING; _startupRetryCount = 0; // Reset retry count on success saveValidationState(); - LOG_INFO("✅ Firmware startup validation PASSED - proceeding with initialization"); + LOG_INFO(TAG, "✅ Firmware startup validation PASSED - proceeding with initialization"); return true; } else { - LOG_ERROR("❌ Startup validation FAILED after %lu ms", _config.startupTimeoutMs); + LOG_ERROR(TAG, "❌ Startup validation FAILED after %lu ms", _config.startupTimeoutMs); _startupRetryCount++; if (_startupRetryCount >= _config.maxStartupRetries) { - LOG_ERROR("💥 Maximum startup retries exceeded - triggering rollback"); + LOG_ERROR(TAG, "💥 Maximum startup retries exceeded - triggering rollback"); handleValidationFailure("Startup validation failed repeatedly"); return false; // This will trigger rollback and reboot } else { - LOG_WARNING("🔄 Startup retry %d/%d - rebooting...", + LOG_WARNING(TAG, "🔄 Startup retry %d/%d - rebooting...", _startupRetryCount, _config.maxStartupRetries); saveValidationState(); delay(1000); @@ -137,20 +139,20 @@ bool FirmwareValidator::performStartupValidation() { } } } else if (_validationState == FirmwareValidationState::VALIDATED) { - LOG_INFO("✅ Firmware already validated - normal operation"); + LOG_INFO(TAG, "✅ Firmware already validated - normal operation"); return true; } else if (_validationState == FirmwareValidationState::STARTUP_RUNNING) { // Handle interrupted validation from previous boot - LOG_INFO("🔄 Resuming interrupted validation - transitioning to runtime testing"); + LOG_INFO(TAG, "🔄 Resuming interrupted validation - transitioning to runtime testing"); _validationState = FirmwareValidationState::RUNTIME_TESTING; saveValidationState(); return true; } else if (_validationState == FirmwareValidationState::RUNTIME_TESTING) { // Already in runtime testing from previous boot - LOG_INFO("🔄 Continuing runtime validation from previous session"); + LOG_INFO(TAG, "🔄 Continuing runtime validation from previous session"); return true; } else { - LOG_WARNING("⚠️ Unexpected validation state: %s", + LOG_WARNING(TAG, "⚠️ Unexpected validation state: %s", validationStateToString(_validationState).c_str()); return true; // Continue anyway } @@ -158,12 +160,12 @@ bool FirmwareValidator::performStartupValidation() { void FirmwareValidator::startRuntimeValidation() { if (_validationState != FirmwareValidationState::RUNTIME_TESTING) { - LOG_WARNING("⚠️ Runtime validation called in wrong state: %s", + LOG_WARNING(TAG, "⚠️ Runtime validation called in wrong state: %s", validationStateToString(_validationState).c_str()); return; } - LOG_INFO("🏃 Starting extended runtime validation (%lu ms timeout)", + LOG_INFO(TAG, "🏃 Starting extended runtime validation (%lu ms timeout)", _config.runtimeTimeoutMs); _validationStartTime = millis(); @@ -180,7 +182,7 @@ void FirmwareValidator::startRuntimeValidation() { if (_validationTimer) { xTimerStart(_validationTimer, 0); } else { - LOG_ERROR("❌ Failed to create validation timer"); + LOG_ERROR(TAG, "❌ Failed to create validation timer"); handleValidationFailure("Timer creation failed"); return; } @@ -197,7 +199,7 @@ void FirmwareValidator::startRuntimeValidation() { ); if (!_monitoringTask) { - LOG_ERROR("❌ Failed to create monitoring task"); + LOG_ERROR(TAG, "❌ Failed to create monitoring task"); handleValidationFailure("Monitoring task creation failed"); return; } @@ -207,21 +209,21 @@ void FirmwareValidator::startRuntimeValidation() { setupWatchdog(); } - LOG_INFO("✅ Runtime validation started - monitoring system health..."); + LOG_INFO(TAG, "✅ Runtime validation started - monitoring system health..."); } void FirmwareValidator::commitFirmware() { if (_validationState == FirmwareValidationState::VALIDATED) { - LOG_INFO("✅ Firmware already committed"); + LOG_INFO(TAG, "✅ Firmware already committed"); return; } - LOG_INFO("💾 Committing firmware as valid and stable..."); + LOG_INFO(TAG, "💾 Committing firmware as valid and stable..."); // Mark current partition as valid boot partition esp_err_t err = esp_ota_set_boot_partition(_runningPartition); if (err != ESP_OK) { - LOG_ERROR("❌ Failed to set boot partition: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "❌ Failed to set boot partition: %s", esp_err_to_name(err)); return; } @@ -240,11 +242,11 @@ void FirmwareValidator::commitFirmware() { _monitoringTask = nullptr; } - LOG_INFO("🎉 Firmware successfully committed! System is now stable."); + LOG_INFO(TAG, "🎉 Firmware successfully committed! System is now stable."); } void FirmwareValidator::rollbackFirmware() { - LOG_WARNING("🔄 Manual firmware rollback requested"); + LOG_WARNING(TAG, "🔄 Manual firmware rollback requested"); handleValidationFailure("Manual rollback requested"); } @@ -258,13 +260,13 @@ bool FirmwareValidator::initializeNVS() { } if (err != ESP_OK) { - LOG_ERROR("❌ Failed to initialize NVS flash: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "❌ Failed to initialize NVS flash: %s", esp_err_to_name(err)); return false; } err = nvs_open(NVS_NAMESPACE, NVS_READWRITE, &_nvsHandle); if (err != ESP_OK) { - LOG_ERROR("❌ Failed to open NVS namespace: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "❌ Failed to open NVS namespace: %s", esp_err_to_name(err)); return false; } @@ -279,9 +281,9 @@ void FirmwareValidator::loadValidationState() { err = nvs_get_u8(_nvsHandle, NVS_STATE_KEY, &state); if (err == ESP_OK) { _validationState = static_cast(state); - LOG_DEBUG("📖 NVS validation state found: %s", validationStateToString(_validationState).c_str()); + LOG_DEBUG(TAG, "📖 NVS validation state found: %s", validationStateToString(_validationState).c_str()); } else { - LOG_DEBUG("📖 No NVS validation state found, using UNKNOWN (error: %s)", esp_err_to_name(err)); + LOG_DEBUG(TAG, "📖 No NVS validation state found, using UNKNOWN (error: %s)", esp_err_to_name(err)); _validationState = FirmwareValidationState::UNKNOWN; } @@ -289,7 +291,7 @@ void FirmwareValidator::loadValidationState() { nvs_get_u8(_nvsHandle, NVS_RETRY_COUNT_KEY, &_startupRetryCount); nvs_get_u8(_nvsHandle, NVS_FAILURE_COUNT_KEY, &_runtimeFailureCount); - LOG_DEBUG("📖 Loaded validation state: %s (retries: %d, failures: %d)", + LOG_DEBUG(TAG, "📖 Loaded validation state: %s (retries: %d, failures: %d)", validationStateToString(_validationState).c_str(), _startupRetryCount, _runtimeFailureCount); } @@ -300,7 +302,7 @@ void FirmwareValidator::saveValidationState() { // Save validation state err = nvs_set_u8(_nvsHandle, NVS_STATE_KEY, static_cast(_validationState)); if (err != ESP_OK) { - LOG_ERROR("❌ Failed to save validation state: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "❌ Failed to save validation state: %s", esp_err_to_name(err)); } // Save retry counts @@ -314,16 +316,16 @@ void FirmwareValidator::saveValidationState() { // Commit changes err = nvs_commit(_nvsHandle); if (err != ESP_OK) { - LOG_ERROR("❌ Failed to commit NVS changes: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "❌ Failed to commit NVS changes: %s", esp_err_to_name(err)); } - LOG_DEBUG("💾 Saved validation state: %s", validationStateToString(_validationState).c_str()); + LOG_DEBUG(TAG, "💾 Saved validation state: %s", validationStateToString(_validationState).c_str()); } bool FirmwareValidator::initializePartitions() { _runningPartition = esp_ota_get_running_partition(); if (!_runningPartition) { - LOG_ERROR("❌ Failed to get running partition"); + LOG_ERROR(TAG, "❌ Failed to get running partition"); return false; } @@ -350,7 +352,7 @@ bool FirmwareValidator::initializePartitions() { } if (!_backupPartition) { - LOG_ERROR("❌ Failed to find backup partition"); + LOG_ERROR(TAG, "❌ Failed to find backup partition"); return false; } @@ -358,11 +360,11 @@ bool FirmwareValidator::initializePartitions() { } bool FirmwareValidator::performBasicHealthCheck() { - LOG_VERBOSE("🔍 Performing basic startup health check..."); + LOG_VERBOSE(TAG, "🔍 Performing basic startup health check..."); // Check if health monitor is available if (!_healthMonitor) { - LOG_ERROR("❌ Health monitor not available"); + LOG_ERROR(TAG, "❌ Health monitor not available"); return false; } @@ -375,20 +377,20 @@ bool FirmwareValidator::performBasicHealthCheck() { bool basicHealthOk = bellEngineOk && outputManagerOk && configManagerOk && fileManagerOk; if (!basicHealthOk) { - LOG_ERROR("❌ Basic health check failed:"); - if (!bellEngineOk) LOG_ERROR(" - BellEngine: FAILED"); - if (!outputManagerOk) LOG_ERROR(" - OutputManager: FAILED"); - if (!configManagerOk) LOG_ERROR(" - ConfigManager: FAILED"); - if (!fileManagerOk) LOG_ERROR(" - FileManager: FAILED"); + LOG_ERROR(TAG, "❌ Basic health check failed:"); + if (!bellEngineOk) LOG_ERROR(TAG, " - BellEngine: FAILED"); + if (!outputManagerOk) LOG_ERROR(TAG, " - OutputManager: FAILED"); + if (!configManagerOk) LOG_ERROR(TAG, " - ConfigManager: FAILED"); + if (!fileManagerOk) LOG_ERROR(TAG, " - FileManager: FAILED"); } else { - LOG_VERBOSE("✅ Basic health check passed"); + LOG_VERBOSE(TAG, "✅ Basic health check passed"); } return basicHealthOk; } bool FirmwareValidator::performRuntimeHealthCheck() { - LOG_VERBOSE("🔍 Performing comprehensive runtime health check..."); + LOG_VERBOSE(TAG, "🔍 Performing comprehensive runtime health check..."); if (!_healthMonitor) { return false; @@ -402,7 +404,7 @@ bool FirmwareValidator::performRuntimeHealthCheck() { && (criticalFailures == 0); if (!runtimeHealthOk) { - LOG_WARNING("⚠️ Runtime health check failed - Critical failures: %d, Overall: %s", + LOG_WARNING(TAG, "⚠️ Runtime health check failed - Critical failures: %d, Overall: %s", criticalFailures, (overallHealth == HealthStatus::HEALTHY) ? "HEALTHY" : (overallHealth == HealthStatus::WARNING) ? "WARNING" : @@ -415,18 +417,18 @@ bool FirmwareValidator::performRuntimeHealthCheck() { void FirmwareValidator::validationTimerCallback(TimerHandle_t timer) { FirmwareValidator* validator = static_cast(pvTimerGetTimerID(timer)); - LOG_INFO("⏰ Runtime validation timeout reached - committing firmware"); + LOG_INFO(TAG, "⏰ Runtime validation timeout reached - committing firmware"); validator->handleValidationSuccess(); } void FirmwareValidator::monitoringTaskFunction(void* parameter) { FirmwareValidator* validator = static_cast(parameter); - LOG_INFO("🔍 Firmware validation monitoring task started on Core %d", xPortGetCoreID()); + LOG_INFO(TAG, "🔍 Firmware validation monitoring task started on Core %d", xPortGetCoreID()); validator->monitoringLoop(); // Task should not reach here normally - LOG_WARNING("⚠️ Firmware validation monitoring task ended unexpectedly"); + LOG_WARNING(TAG, "⚠️ Firmware validation monitoring task ended unexpectedly"); vTaskDelete(NULL); } @@ -442,11 +444,11 @@ void FirmwareValidator::monitoringLoop() { if (!healthOk) { _runtimeFailureCount++; - LOG_WARNING("⚠️ Runtime health check failed (%d/%d failures)", + LOG_WARNING(TAG, "⚠️ Runtime health check failed (%d/%d failures)", _runtimeFailureCount, _config.maxRuntimeFailures); if (_runtimeFailureCount >= _config.maxRuntimeFailures) { - LOG_ERROR("💥 Maximum runtime failures exceeded - triggering rollback"); + LOG_ERROR(TAG, "💥 Maximum runtime failures exceeded - triggering rollback"); handleValidationFailure("Too many runtime health check failures"); return; } @@ -454,7 +456,7 @@ void FirmwareValidator::monitoringLoop() { // Reset failure count on successful health check if (_runtimeFailureCount > 0) { _runtimeFailureCount = 0; - LOG_INFO("✅ Runtime health recovered - reset failure count"); + LOG_INFO(TAG, "✅ Runtime health recovered - reset failure count"); } } @@ -464,13 +466,13 @@ void FirmwareValidator::monitoringLoop() { } void FirmwareValidator::handleValidationSuccess() { - LOG_INFO("🎉 Firmware validation completed successfully!"); + LOG_INFO(TAG, "🎉 Firmware validation completed successfully!"); commitFirmware(); } void FirmwareValidator::handleValidationFailure(const String& reason) { - LOG_ERROR("💥 Firmware validation FAILED: %s", reason.c_str()); - LOG_ERROR("🔄 Initiating firmware rollback..."); + LOG_ERROR(TAG, "💥 Firmware validation FAILED: %s", reason.c_str()); + LOG_ERROR(TAG, "🔄 Initiating firmware rollback..."); _validationState = FirmwareValidationState::FAILED_RUNTIME; saveValidationState(); @@ -479,7 +481,7 @@ void FirmwareValidator::handleValidationFailure(const String& reason) { } void FirmwareValidator::executeRollback() { - LOG_WARNING("🔄 Executing firmware rollback to previous version..."); + LOG_WARNING(TAG, "🔄 Executing firmware rollback to previous version..."); // Clean up validation resources first if (_validationTimer) { @@ -496,18 +498,18 @@ void FirmwareValidator::executeRollback() { esp_err_t err = esp_ota_mark_app_invalid_rollback_and_reboot(); if (err != ESP_OK) { - LOG_ERROR("❌ Failed to rollback firmware: %s", esp_err_to_name(err)); - LOG_ERROR("💀 System may be in unstable state - manual intervention required"); + LOG_ERROR(TAG, "❌ Failed to rollback firmware: %s", esp_err_to_name(err)); + LOG_ERROR(TAG, "💀 System may be in unstable state - manual intervention required"); // If rollback fails, try manual reboot to backup partition - LOG_WARNING("🆘 Attempting manual reboot to backup partition..."); + LOG_WARNING(TAG, "🆘 Attempting manual reboot to backup partition..."); if (_backupPartition) { esp_ota_set_boot_partition(_backupPartition); delay(1000); ESP.restart(); } else { - LOG_ERROR("💀 No backup partition available - system halt"); + LOG_ERROR(TAG, "💀 No backup partition available - system halt"); while(1) { delay(1000); // Hang here to prevent further damage } @@ -515,7 +517,7 @@ void FirmwareValidator::executeRollback() { } // This point should not be reached as the device should reboot - LOG_ERROR("💀 Rollback function returned unexpectedly"); + LOG_ERROR(TAG, "💀 Rollback function returned unexpectedly"); } FirmwareInfo FirmwareValidator::getCurrentFirmwareInfo() const { @@ -649,7 +651,7 @@ void FirmwareValidator::incrementBootCount() { nvs_set_u32(_nvsHandle, NVS_BOOT_COUNT_KEY, bootCount); nvs_commit(_nvsHandle); - LOG_DEBUG("📊 Boot count: %lu", bootCount); + LOG_DEBUG(TAG, "📊 Boot count: %lu", bootCount); } void FirmwareValidator::resetValidationCounters() { @@ -661,35 +663,31 @@ void FirmwareValidator::resetValidationCounters() { nvs_set_u8(_nvsHandle, NVS_FAILURE_COUNT_KEY, 0); nvs_commit(_nvsHandle); - LOG_DEBUG("🔄 Reset validation counters"); + LOG_DEBUG(TAG, "🔄 Reset validation counters"); } void FirmwareValidator::setupWatchdog() { // Check if watchdog is already initialized - esp_task_wdt_config_t config = { - .timeout_ms = _config.watchdogTimeoutMs, - .idle_core_mask = (1 << portNUM_PROCESSORS) - 1, - .trigger_panic = true - }; - - esp_err_t err = esp_task_wdt_init(&config); + // Use IDF v4 API: esp_task_wdt_init(timeout_seconds, panic_on_timeout) + uint32_t timeoutSec = (_config.watchdogTimeoutMs + 999) / 1000; // ms → seconds, round up + esp_err_t err = esp_task_wdt_init(timeoutSec, true); if (err == ESP_ERR_INVALID_STATE) { - LOG_DEBUG("🐕 Watchdog already initialized - skipping init"); + LOG_DEBUG(TAG, "🐕 Watchdog already initialized - skipping init"); } else if (err != ESP_OK) { - LOG_WARNING("⚠️ Failed to initialize task watchdog: %s", esp_err_to_name(err)); + LOG_WARNING(TAG, "⚠️ Failed to initialize task watchdog: %s", esp_err_to_name(err)); return; } // Try to add current task to watchdog err = esp_task_wdt_add(NULL); if (err == ESP_ERR_INVALID_ARG) { - LOG_DEBUG("🐕 Task already added to watchdog"); + LOG_DEBUG(TAG, "🐕 Task already added to watchdog"); } else if (err != ESP_OK) { - LOG_WARNING("⚠️ Failed to add task to watchdog: %s", esp_err_to_name(err)); + LOG_WARNING(TAG, "⚠️ Failed to add task to watchdog: %s", esp_err_to_name(err)); return; } - LOG_INFO("🐕 Watchdog enabled with %lu second timeout", _config.watchdogTimeoutMs / 1000); + LOG_INFO(TAG, "🐕 Watchdog enabled with %lu second timeout", _config.watchdogTimeoutMs / 1000); } void FirmwareValidator::feedWatchdog() { diff --git a/vesper/src/HealthMonitor/HealthMonitor.cpp b/vesper/src/HealthMonitor/HealthMonitor.cpp index e327d3f..c1a8e20 100644 --- a/vesper/src/HealthMonitor/HealthMonitor.cpp +++ b/vesper/src/HealthMonitor/HealthMonitor.cpp @@ -5,6 +5,8 @@ */ #include "HealthMonitor.hpp" + +#define TAG "HealthMonitor" #include "../BellEngine/BellEngine.hpp" #include "../OutputManager/OutputManager.hpp" #include "../Communication/CommunicationRouter/CommunicationRouter.hpp" @@ -29,7 +31,7 @@ HealthMonitor::~HealthMonitor() { } bool HealthMonitor::begin() { - LOG_INFO("🏥 Initializing Health Monitor System"); + LOG_INFO(TAG, "🏥 Initializing Health Monitor System"); // Create monitoring task if auto-monitoring is enabled if (_autoMonitoring) { @@ -44,14 +46,14 @@ bool HealthMonitor::begin() { ); if (_monitoringTaskHandle != nullptr) { - LOG_INFO("✅ Health Monitor initialized with automatic monitoring"); + LOG_INFO(TAG, "✅ Health Monitor initialized with automatic monitoring"); return true; } else { - LOG_ERROR("❌ Failed to create Health Monitor task"); + LOG_ERROR(TAG, "❌ Failed to create Health Monitor task"); return false; } } else { - LOG_INFO("✅ Health Monitor initialized (manual mode)"); + LOG_INFO(TAG, "✅ Health Monitor initialized (manual mode)"); return true; } } @@ -71,12 +73,12 @@ void HealthMonitor::initializeSubsystemHealth() { _subsystemHealth["OTAManager"] = SubsystemHealth("OTAManager", false); // Non-critical _subsystemHealth["Networking"] = SubsystemHealth("Networking", false); // Non-critical - LOG_DEBUG("🏗️ Initialized health monitoring for %d subsystems", _subsystemHealth.size()); + LOG_DEBUG(TAG, "🏗️ Initialized health monitoring for %d subsystems", _subsystemHealth.size()); } void HealthMonitor::monitoringTask(void* parameter) { HealthMonitor* monitor = static_cast(parameter); - LOG_INFO("🏥 Health Monitor task started on Core %d", xPortGetCoreID()); + LOG_INFO(TAG, "🏥 Health Monitor task started on Core %d", xPortGetCoreID()); while (true) { monitor->monitoringLoop(); @@ -88,12 +90,12 @@ void HealthMonitor::monitoringLoop() { if (_player) { if (_player->_status != PlayerStatus::STOPPED) { - LOG_VERBOSE("⏸️ Skipping health check during active playback"); + LOG_VERBOSE(TAG, "⏸️ Skipping health check during active playback"); return; } } - LOG_VERBOSE("🔍 Performing periodic health check..."); + LOG_VERBOSE(TAG, "🔍 Performing periodic health check..."); HealthStatus overallHealth = performFullHealthCheck(); @@ -102,25 +104,32 @@ void HealthMonitor::monitoringLoop() { uint8_t warningCount = getWarningCount(); if (criticalCount > 0) { - LOG_WARNING("🚨 Health Monitor: %d critical failures detected!", criticalCount); + LOG_WARNING(TAG, "🚨 Health Monitor: %d critical failures detected!", criticalCount); // List critical failures for (const auto& [name, health] : _subsystemHealth) { if (health.status == HealthStatus::CRITICAL || health.status == HealthStatus::FAILED) { - LOG_ERROR("❌ CRITICAL: %s - %s", name.c_str(), health.lastError.c_str()); + LOG_ERROR(TAG, "❌ CRITICAL: %s - %s", name.c_str(), health.lastError.c_str()); } } // Check if firmware rollback is recommended if (shouldRollbackFirmware()) { - LOG_ERROR("🔄 FIRMWARE ROLLBACK RECOMMENDED - Too many critical failures"); + LOG_ERROR(TAG, "🔄 FIRMWARE ROLLBACK RECOMMENDED - Too many critical failures"); // In a real system, this would trigger an OTA rollback // For now, we just log the recommendation } } else if (warningCount > 0) { - LOG_WARNING("⚠️ Health Monitor: %d warnings detected", warningCount); + LOG_WARNING(TAG, "⚠️ Health Monitor: %d warning(s) detected", warningCount); + + // List every subsystem that is in WARNING state + for (const auto& [name, health] : _subsystemHealth) { + if (health.status == HealthStatus::WARNING) { + LOG_WARNING(TAG, "⚠️ WARNING: %s - %s", name.c_str(), health.lastError.c_str()); + } + } } else { - LOG_VERBOSE("✅ All subsystems healthy"); + LOG_VERBOSE(TAG, "✅ All subsystems healthy"); } } @@ -219,7 +228,7 @@ HealthStatus HealthMonitor::performFullHealthCheck() { } unsigned long elapsed = millis() - startTime; - LOG_VERBOSE("🔍 Health check completed: %d systems in %lums", checkedSystems, elapsed); + LOG_VERBOSE(TAG, "🔍 Health check completed: %d systems in %lums", checkedSystems, elapsed); return calculateOverallHealth(); } @@ -228,7 +237,7 @@ HealthStatus HealthMonitor::checkSubsystemHealth(const String& subsystemName) { // Perform health check on specific subsystem auto it = _subsystemHealth.find(subsystemName); if (it == _subsystemHealth.end()) { - LOG_WARNING("❓ Unknown subsystem: %s", subsystemName.c_str()); + LOG_WARNING(TAG, "❓ Unknown subsystem: %s", subsystemName.c_str()); return HealthStatus::FAILED; } @@ -256,7 +265,7 @@ HealthStatus HealthMonitor::checkSubsystemHealth(const String& subsystemName) { } else if (subsystemName == "FileManager" && _fileManager) { healthy = _fileManager->isHealthy(); } else { - LOG_WARNING("🔌 Subsystem %s not connected to health monitor", subsystemName.c_str()); + LOG_WARNING(TAG, "🔌 Subsystem %s not connected to health monitor", subsystemName.c_str()); return HealthStatus::FAILED; } @@ -382,7 +391,7 @@ void HealthMonitor::updateSubsystemHealth(const String& name, HealthStatus statu it->second.lastError = error; it->second.lastCheck = millis(); - LOG_VERBOSE("🔍 %s: %s %s", + LOG_VERBOSE(TAG, "🔍 %s: %s %s", name.c_str(), healthStatusToString(status).c_str(), error.isEmpty() ? "" : ("(" + error + ")").c_str()); diff --git a/vesper/src/InputManager/InputManager.cpp b/vesper/src/InputManager/InputManager.cpp index f1a33d1..074973c 100644 --- a/vesper/src/InputManager/InputManager.cpp +++ b/vesper/src/InputManager/InputManager.cpp @@ -1,4 +1,6 @@ #include "InputManager.hpp" + +#define TAG "InputManager" #include "../Logging/Logging.hpp" // Static instance pointer @@ -28,7 +30,7 @@ InputManager::~InputManager() { // ═══════════════════════════════════════════════════════════════════════════════════ bool InputManager::begin() { - LOG_INFO("InputManager: Initializing input handling system"); + LOG_INFO(TAG, "InputManager: Initializing input handling system"); // Configure factory reset button configureButton(_factoryResetButton.config); @@ -51,13 +53,13 @@ bool InputManager::begin() { ); if (result != pdPASS) { - LOG_ERROR("InputManager: Failed to create input task!"); + LOG_ERROR(TAG, "InputManager: Failed to create input task!"); return false; } _initialized = true; - LOG_INFO("InputManager: Initialization complete - Factory Reset on GPIO 0 (Task running)"); + LOG_INFO(TAG, "InputManager: Initialization complete - Factory Reset on GPIO 0 (Task running)"); return true; } @@ -65,7 +67,7 @@ void InputManager::end() { if (_inputTaskHandle != nullptr) { vTaskDelete(_inputTaskHandle); _inputTaskHandle = nullptr; - LOG_INFO("InputManager: Input task stopped"); + LOG_INFO(TAG, "InputManager: Input task stopped"); } _initialized = false; } @@ -76,12 +78,12 @@ void InputManager::end() { void InputManager::setFactoryResetPressCallback(ButtonCallback callback) { _factoryResetButton.config.onPress = callback; - LOG_DEBUG("InputManager: Factory reset press callback registered"); + LOG_DEBUG(TAG, "InputManager: Factory reset press callback registered"); } void InputManager::setFactoryResetLongPressCallback(ButtonCallback callback) { _factoryResetButton.config.onLongPress = callback; - LOG_DEBUG("InputManager: Factory reset long press callback registered"); + LOG_DEBUG(TAG, "InputManager: Factory reset long press callback registered"); } // ═══════════════════════════════════════════════════════════════════════════════════ @@ -101,7 +103,7 @@ uint32_t InputManager::getFactoryResetPressDuration() const { bool InputManager::isHealthy() const { if (!_initialized) { - LOG_DEBUG("InputManager: Unhealthy - not initialized"); + LOG_DEBUG(TAG, "InputManager: Unhealthy - not initialized"); return false; } @@ -116,7 +118,7 @@ bool InputManager::isHealthy() const { void InputManager::inputTaskFunction(void* parameter) { InputManager* manager = static_cast(parameter); - LOG_INFO("InputManager: Input task started (polling every %dms)", INPUT_POLL_RATE_MS); + LOG_INFO(TAG, "InputManager: Input task started (polling every %dms)", INPUT_POLL_RATE_MS); TickType_t lastWakeTime = xTaskGetTickCount(); const TickType_t pollInterval = pdMS_TO_TICKS(INPUT_POLL_RATE_MS); @@ -155,7 +157,7 @@ void InputManager::configureButton(const ButtonConfig& config) { pinMode(config.pin, INPUT_PULLUP); } - LOG_DEBUG("InputManager: Configured GPIO %d as input (%s)", + LOG_DEBUG(TAG, "InputManager: Configured GPIO %d as input (%s)", config.pin, config.activeHigh ? "active-high" : "active-low"); } @@ -182,7 +184,7 @@ void InputManager::updateButton(ButtonData& button) { // Button just pressed - start debouncing button.state = ButtonState::DEBOUNCING_PRESS; button.stateChangeTime = now; - LOG_DEBUG("InputManager: Button press detected on GPIO %d - debouncing", + LOG_DEBUG(TAG, "InputManager: Button press detected on GPIO %d - debouncing", button.config.pin); } break; @@ -192,14 +194,14 @@ void InputManager::updateButton(ButtonData& button) { if (!currentState) { // Button released during debounce - false trigger button.state = ButtonState::IDLE; - LOG_DEBUG("InputManager: False trigger on GPIO %d (released during debounce)", + LOG_DEBUG(TAG, "InputManager: False trigger on GPIO %d (released during debounce)", button.config.pin); } else if (now - button.stateChangeTime >= button.config.debounceMs) { // Debounce time passed - confirm press button.state = ButtonState::LONG_PRESS_PENDING; button.pressStartTime = now; button.longPressTriggered = false; - LOG_INFO("InputManager: Button press confirmed on GPIO %d", + LOG_INFO(TAG, "InputManager: Button press confirmed on GPIO %d", button.config.pin); } break; @@ -210,14 +212,14 @@ void InputManager::updateButton(ButtonData& button) { // Button released before long press threshold - it's a short press button.state = ButtonState::DEBOUNCING_RELEASE; button.stateChangeTime = now; - LOG_INFO("InputManager: Short press detected on GPIO %d (held for %lums)", + LOG_INFO(TAG, "InputManager: Short press detected on GPIO %d (held for %lums)", button.config.pin, now - button.pressStartTime); } else if (now - button.pressStartTime >= button.config.longPressMs) { // Long press threshold reached button.state = ButtonState::LONG_PRESSED; button.longPressTriggered = true; - LOG_WARNING("InputManager: LONG PRESS DETECTED on GPIO %d (held for %lums)", + LOG_WARNING(TAG, "InputManager: LONG PRESS DETECTED on GPIO %d (held for %lums)", button.config.pin, now - button.pressStartTime); // Trigger long press callback @@ -232,7 +234,7 @@ void InputManager::updateButton(ButtonData& button) { if (!currentState) { button.state = ButtonState::DEBOUNCING_RELEASE; button.stateChangeTime = now; - LOG_INFO("InputManager: Long press released on GPIO %d (total duration: %lums)", + LOG_INFO(TAG, "InputManager: Long press released on GPIO %d (total duration: %lums)", button.config.pin, now - button.pressStartTime); } break; @@ -242,7 +244,7 @@ void InputManager::updateButton(ButtonData& button) { if (currentState) { // Button pressed again during release debounce - go back to pressed state button.state = ButtonState::LONG_PRESS_PENDING; - LOG_DEBUG("InputManager: Button re-pressed during release debounce on GPIO %d", + LOG_DEBUG(TAG, "InputManager: Button re-pressed during release debounce on GPIO %d", button.config.pin); } else if (now - button.stateChangeTime >= button.config.debounceMs) { // Debounce time passed - confirm release @@ -250,12 +252,12 @@ void InputManager::updateButton(ButtonData& button) { // If it was a short press (not long press), trigger the press callback if (!button.longPressTriggered && button.config.onPress) { - LOG_INFO("InputManager: Triggering press callback for GPIO %d", + LOG_INFO(TAG, "InputManager: Triggering press callback for GPIO %d", button.config.pin); button.config.onPress(); } - LOG_DEBUG("InputManager: Button release confirmed on GPIO %d", + LOG_DEBUG(TAG, "InputManager: Button release confirmed on GPIO %d", button.config.pin); } break; diff --git a/vesper/src/Logging/Logging.cpp b/vesper/src/Logging/Logging.cpp index 5e97461..fa39760 100644 --- a/vesper/src/Logging/Logging.cpp +++ b/vesper/src/Logging/Logging.cpp @@ -1,142 +1,251 @@ #include "Logging.hpp" -// Initialize static members -Logging::LogLevel Logging::currentLevel = Logging::VERBOSE; // Default to VERBOSE -Logging::LogLevel Logging::mqttLogLevel = Logging::NONE; // Default MQTT logs OFF -Logging::MqttPublishCallback Logging::mqttPublishCallback = nullptr; -String Logging::mqttLogTopic = ""; +// ═══════════════════════════════════════════════════════════════════════════════════ +// STATIC MEMBER INITIALIZATION +// ═══════════════════════════════════════════════════════════════════════════════════ -void Logging::setLevel(LogLevel level) { - currentLevel = level; - Serial.printf("[LOGGING] Log level set to %d\n", level); +Logging::LogLevel Logging::_serialLevel = Logging::VERBOSE; +Logging::LogLevel Logging::_mqttLevel = Logging::NONE; +Logging::LogLevel Logging::_sdLevel = Logging::NONE; + +std::map Logging::_serialOverrides; +std::map Logging::_mqttOverrides; +std::map Logging::_sdOverrides; + +Logging::MqttPublishCallback Logging::_mqttCallback = nullptr; +Logging::SdWriteCallback Logging::_sdCallback = nullptr; +String Logging::_mqttLogTopic = ""; + +// ═══════════════════════════════════════════════════════════════════════════════════ +// GLOBAL CHANNEL LEVEL SETTERS / GETTERS +// ═══════════════════════════════════════════════════════════════════════════════════ + +void Logging::setSerialLevel(LogLevel level) { + _serialLevel = level; + Serial.printf("[Logger] Serial level -> %d\n", level); } -Logging::LogLevel Logging::getLevel() { - return currentLevel; +void Logging::setMqttLevel(LogLevel level) { + _mqttLevel = level; + Serial.printf("[Logger] MQTT level -> %d\n", level); } -void Logging::setMqttLogLevel(LogLevel level) { - mqttLogLevel = level; - Serial.printf("[LOGGING] MQTT log level set to %d\n", level); +void Logging::setSdLevel(LogLevel level) { + _sdLevel = level; + Serial.printf("[Logger] SD level -> %d\n", level); } -Logging::LogLevel Logging::getMqttLogLevel() { - return mqttLogLevel; +Logging::LogLevel Logging::getSerialLevel() { return _serialLevel; } +Logging::LogLevel Logging::getMqttLevel() { return _mqttLevel; } +Logging::LogLevel Logging::getSdLevel() { return _sdLevel; } + +// ═══════════════════════════════════════════════════════════════════════════════════ +// PER-SUBSYSTEM OVERRIDES +// ═══════════════════════════════════════════════════════════════════════════════════ + +void Logging::setSubsystemSerialLevel(const char* tag, LogLevel level) { + _serialOverrides[String(tag)] = level; } +void Logging::setSubsystemMqttLevel(const char* tag, LogLevel level) { + _mqttOverrides[String(tag)] = level; +} + +void Logging::setSubsystemSdLevel(const char* tag, LogLevel level) { + _sdOverrides[String(tag)] = level; +} + +// ═══════════════════════════════════════════════════════════════════════════════════ +// CALLBACK REGISTRATION +// ═══════════════════════════════════════════════════════════════════════════════════ + void Logging::setMqttPublishCallback(MqttPublishCallback callback, const String& logTopic) { - mqttPublishCallback = callback; - mqttLogTopic = logTopic; - Serial.printf("[LOGGING] MQTT publish callback registered for topic: %s\n", logTopic.c_str()); + _mqttCallback = callback; + _mqttLogTopic = logTopic; + Serial.printf("[Logger] MQTT publish callback registered: %s\n", logTopic.c_str()); } +void Logging::setSdWriteCallback(SdWriteCallback callback) { + _sdCallback = callback; + Serial.printf("[Logger] SD write callback registered\n"); +} + +// ═══════════════════════════════════════════════════════════════════════════════════ +// PUBLIC LOGGING FUNCTIONS +// ═══════════════════════════════════════════════════════════════════════════════════ + +void Logging::error(const char* tag, const char* format, ...) { + va_list args; + va_start(args, format); + log(ERROR, "ERROR", tag, format, args); + va_end(args); +} + +void Logging::warning(const char* tag, const char* format, ...) { + va_list args; + va_start(args, format); + log(WARNING, "WARN", tag, format, args); + va_end(args); +} + +void Logging::info(const char* tag, const char* format, ...) { + va_list args; + va_start(args, format); + log(INFO, "INFO", tag, format, args); + va_end(args); +} + +void Logging::debug(const char* tag, const char* format, ...) { + va_list args; + va_start(args, format); + log(DEBUG, "DEBG", tag, format, args); + va_end(args); +} + +void Logging::verbose(const char* tag, const char* format, ...) { + va_list args; + va_start(args, format); + log(VERBOSE, "VERB", tag, format, args); + va_end(args); +} + +// ═══════════════════════════════════════════════════════════════════════════════════ +// UTILITIES +// ═══════════════════════════════════════════════════════════════════════════════════ + bool Logging::isLevelEnabled(LogLevel level) { - return currentLevel >= level; + return _serialLevel >= level; } -void Logging::error(const char* format, ...) { - va_list args; - va_start(args, format); - log(ERROR, "🔴 EROR", format, args); - va_end(args); +String Logging::levelToString(LogLevel level) { + switch (level) { + case ERROR: return "ERROR"; + case WARNING: return "WARNING"; + case INFO: return "INFO"; + case DEBUG: return "DEBUG"; + case VERBOSE: return "VERBOSE"; + default: return "NONE"; + } } -void Logging::warning(const char* format, ...) { - va_list args; - va_start(args, format); - log(WARNING, "🟡 WARN", format, args); - va_end(args); +// ═══════════════════════════════════════════════════════════════════════════════════ +// PRIVATE: RESOLVE EFFECTIVE LEVEL FOR A TAG ON A CHANNEL +// Returns the override level if one exists for this tag, otherwise the global level. +// ═══════════════════════════════════════════════════════════════════════════════════ + +Logging::LogLevel Logging::resolveLevel(const char* tag, LogLevel globalLevel, const std::map& overrides) { + auto it = overrides.find(String(tag)); + if (it != overrides.end()) { + return it->second; + } + return globalLevel; } -void Logging::info(const char* format, ...) { - va_list args; - va_start(args, format); - log(INFO, "🟢 INFO", format, args); - va_end(args); -} +// ═══════════════════════════════════════════════════════════════════════════════════ +// PRIVATE: CORE LOG DISPATCH +// ═══════════════════════════════════════════════════════════════════════════════════ -void Logging::debug(const char* format, ...) { - va_list args; - va_start(args, format); - log(DEBUG, "🐞 DEBG", format, args); - va_end(args); -} +void Logging::log(LogLevel level, const char* levelStr, const char* tag, const char* format, va_list args) { + // Resolve effective level for each channel (override wins over global) + LogLevel serialEffective = resolveLevel(tag, _serialLevel, _serialOverrides); + LogLevel mqttEffective = resolveLevel(tag, _mqttLevel, _mqttOverrides); + LogLevel sdEffective = resolveLevel(tag, _sdLevel, _sdOverrides); -void Logging::verbose(const char* format, ...) { - va_list args; - va_start(args, format); - log(VERBOSE, "🧾 VERB", format, args); - va_end(args); -} + bool serialEnabled = (serialEffective >= level); + bool mqttEnabled = (mqttEffective >= level) && (_mqttCallback != nullptr); + bool sdEnabled = (sdEffective >= level) && (_sdCallback != nullptr); -void Logging::log(LogLevel level, const char* levelStr, const char* format, va_list args) { - // Check if ANY output needs this log level - bool serialEnabled = (currentLevel >= level); - bool mqttEnabled = (mqttLogLevel >= level && mqttPublishCallback); - // bool sdEnabled = (sdLogLevel >= level && sdLogCallback); // Future: SD logging - - // Early exit if no outputs need this message - if (!serialEnabled && !mqttEnabled) { + // Early exit if nothing will output this message + if (!serialEnabled && !mqttEnabled && !sdEnabled) { return; } - // Format the message once (only if at least one output needs it) + // Format the message once char buffer[512]; vsnprintf(buffer, sizeof(buffer), format, args); - // Serial output (independent check) + // Serial output if (serialEnabled) { - Serial.printf("[%s] ", levelStr); - Serial.print(buffer); - Serial.println(); + Serial.printf("[%s][%s] %s\n", levelStr, tag, buffer); } - // MQTT output (independent check) + // MQTT output if (mqttEnabled) { - publishToMqtt(level, levelStr, buffer); + publishToMqtt(level, levelStr, tag, buffer); } - // Future: SD logging would go here with its own independent check + // SD output + if (sdEnabled) { + writeToSd(level, levelStr, tag, buffer); + } } -void Logging::publishToMqtt(LogLevel level, const char* levelStr, const char* message) { - if (!mqttPublishCallback || mqttLogTopic.isEmpty()) { - return; - } +// ═══════════════════════════════════════════════════════════════════════════════════ +// PRIVATE: MQTT PUBLISH +// Uses a re-entrancy guard to prevent log-of-a-log recursion. +// ═══════════════════════════════════════════════════════════════════════════════════ + +void Logging::publishToMqtt(LogLevel level, const char* levelStr, const char* tag, const char* message) { + if (!_mqttCallback || _mqttLogTopic.isEmpty()) return; - // CRITICAL: Prevent infinite recursion if MQTT publish fails - // Temporarily disable MQTT logging during publish to avoid cascading errors static bool isPublishing = false; - if (isPublishing) { - return; // Already publishing, don't create recursive log loop - } - + if (isPublishing) return; isPublishing = true; - // Build JSON manually to minimize stack usage (no StaticJsonDocument) - // Format: {"level":"🟢 INFO","message":"text","timestamp":12345} + // JSON: {"level":"WARNING","subsystem":"BellEngine","message":"...","timestamp":12345} String payload; - payload.reserve(600); // Pre-allocate to avoid fragmentation - + payload.reserve(600); payload = "{\"level\":\""; payload += levelStr; + payload += "\",\"subsystem\":\""; + payload += tag; payload += "\",\"message\":\""; - // Escape special JSON characters in message - String escapedMsg = message; - escapedMsg.replace("\\", "\\\\"); - escapedMsg.replace("\"", "\\\""); - escapedMsg.replace("\n", "\\n"); - escapedMsg.replace("\r", "\\r"); + // Escape special JSON characters + const char* p = message; + while (*p) { + char c = *p++; + if (c == '\\') payload += "\\\\"; + else if (c == '"') payload += "\\\""; + else if (c == '\n') payload += "\\n"; + else if (c == '\r') payload += "\\r"; + else payload += c; + } - payload += escapedMsg; payload += "\",\"timestamp\":"; payload += millis(); payload += "}"; - // Publish with QoS 1 (guaranteed delivery) - // Note: If this fails, it won't trigger another MQTT log due to isPublishing flag - mqttPublishCallback(mqttLogTopic, payload, 1); + _mqttCallback(_mqttLogTopic, payload, 1); isPublishing = false; } + +// ═══════════════════════════════════════════════════════════════════════════════════ +// PRIVATE: SD WRITE +// ═══════════════════════════════════════════════════════════════════════════════════ + +void Logging::writeToSd(LogLevel level, const char* levelStr, const char* tag, const char* message) { + if (!_sdCallback) return; + + static bool isWriting = false; + if (isWriting) return; + isWriting = true; + + // Plain text line: [WARN][BellEngine] message (timestamp: 12345ms) + String line; + line.reserve(300); + line = "["; + line += levelStr; + line += "]["; + line += tag; + line += "] "; + line += message; + line += " ("; + line += millis(); + line += "ms)"; + + _sdCallback(line); + + isWriting = false; +} diff --git a/vesper/src/Logging/Logging.hpp b/vesper/src/Logging/Logging.hpp index 1811f8d..7ac402b 100644 --- a/vesper/src/Logging/Logging.hpp +++ b/vesper/src/Logging/Logging.hpp @@ -1,14 +1,28 @@ /* * ═══════════════════════════════════════════════════════════════════════════════════ - * LOGGING.HPP - Centralized Logging System + * LOGGING.HPP - Subsystem-Aware Centralized Logging System * ═══════════════════════════════════════════════════════════════════════════════════ - * + * * 📝 THE INFORMATION CHRONICLER OF VESPER 📝 - * - * This header provides a unified logging interface with multiple levels, - * timestamps, and comprehensive debugging support throughout the system. - * - * 📋 VERSION: 2.0 (Enhanced logging system) + * + * Three independent output channels, each with their own level: + * • Serial — USB debugging, local connection + * • MQTT — Remote troubleshooting via web dashboard + * • SD — Persistent log storage for post-mortem analysis + * + * Per-subsystem filtering: each subsystem tag can have its own level + * overrides per channel. If no override is set, the global channel + * level applies. Set a tag's level to NONE on a specific channel to + * silence it entirely on that channel (e.g. MQTT internals on MQTT). + * + * Usage in each .cpp file: + * #define TAG "BellEngine" // one line at the top + * LOG_INFO(TAG, "Ring scheduled"); // all calls include the tag + * + * The JSON payload sent over MQTT includes the subsystem field: + * {"level":"WARNING","subsystem":"BellEngine","message":"...","timestamp":12345} + * + * 📋 VERSION: 3.0 (Subsystem-aware logging) * 📅 DATE: 2025 * 👨‍💻 AUTHOR: Advanced Bell Systems * ═══════════════════════════════════════════════════════════════════════════════════ @@ -18,67 +32,114 @@ #define LOGGING_HPP #include - -// Forward declaration -class MQTTAsyncClient; +#include +#include class Logging { public: - // Log Levels + // ═══════════════════════════════════════════════════════════════════════════════ + // LOG LEVELS + // ═══════════════════════════════════════════════════════════════════════════════ enum LogLevel { - NONE = 0, // No logs - ERROR = 1, // Errors only - WARNING = 2, // Warnings and errors - INFO = 3, // Info, warnings, and errors - DEBUG = 4, // Debug logs. Really high level (full debugging) - VERBOSE = 5 // Nearly every command gets printed + NONE = 0, // No output + ERROR = 1, // Errors only + WARNING = 2, // Warnings and errors + INFO = 3, // Info, warnings, errors + DEBUG = 4, // Debug detail + VERBOSE = 5 // Everything }; - // MQTT Log Publishing Callback + // ═══════════════════════════════════════════════════════════════════════════════ + // CALLBACK TYPES + // ═══════════════════════════════════════════════════════════════════════════════ using MqttPublishCallback = std::function; + using SdWriteCallback = std::function; -private: - static LogLevel currentLevel; - static LogLevel mqttLogLevel; - static MqttPublishCallback mqttPublishCallback; - static String mqttLogTopic; + // ═══════════════════════════════════════════════════════════════════════════════ + // GLOBAL CHANNEL LEVELS + // Set the baseline level for each output channel. + // Per-subsystem overrides take precedence when set. + // ═══════════════════════════════════════════════════════════════════════════════ + static void setSerialLevel(LogLevel level); + static void setMqttLevel(LogLevel level); + static void setSdLevel(LogLevel level); -public: - // Set the active log level - static void setLevel(LogLevel level); + static LogLevel getSerialLevel(); + static LogLevel getMqttLevel(); + static LogLevel getSdLevel(); - // Get current log level - static LogLevel getLevel(); + // Legacy compatibility (maps to serial level) + static void setLevel(LogLevel level) { setSerialLevel(level); } + static LogLevel getLevel() { return getSerialLevel(); } + static void setMqttLogLevel(LogLevel level) { setMqttLevel(level); } + static LogLevel getMqttLogLevel() { return getMqttLevel(); } - // Set MQTT log level (independent from serial logging) - static void setMqttLogLevel(LogLevel level); + // ═══════════════════════════════════════════════════════════════════════════════ + // PER-SUBSYSTEM LEVEL OVERRIDES + // Call these at startup to silence or focus specific subsystems per channel. + // Pass NONE to completely silence a subsystem on a channel. + // Pass a level to cap that subsystem at that level on that channel. + // ═══════════════════════════════════════════════════════════════════════════════ + static void setSubsystemSerialLevel(const char* tag, LogLevel level); + static void setSubsystemMqttLevel(const char* tag, LogLevel level); + static void setSubsystemSdLevel(const char* tag, LogLevel level); - // Get MQTT log level - static LogLevel getMqttLogLevel(); - - // Set MQTT callback for publishing logs + // ═══════════════════════════════════════════════════════════════════════════════ + // OUTPUT CHANNEL REGISTRATION + // ═══════════════════════════════════════════════════════════════════════════════ static void setMqttPublishCallback(MqttPublishCallback callback, const String& logTopic); + static void setSdWriteCallback(SdWriteCallback callback); - // Logging functions - static void error(const char* format, ...); - static void warning(const char* format, ...); - static void info(const char* format, ...); - static void debug(const char* format, ...); - static void verbose(const char* format, ...); + // ═══════════════════════════════════════════════════════════════════════════════ + // LOGGING FUNCTIONS (tag = subsystem name, e.g. "BellEngine") + // ═══════════════════════════════════════════════════════════════════════════════ + static void error(const char* tag, const char* format, ...); + static void warning(const char* tag, const char* format, ...); + static void info(const char* tag, const char* format, ...); + static void debug(const char* tag, const char* format, ...); + static void verbose(const char* tag, const char* format, ...); - // Check if level is enabled (for conditional logging) + // ═══════════════════════════════════════════════════════════════════════════════ + // UTILITIES + // ═══════════════════════════════════════════════════════════════════════════════ static bool isLevelEnabled(LogLevel level); + static String levelToString(LogLevel level); private: - static void log(LogLevel level, const char* levelStr, const char* format, va_list args); - static void publishToMqtt(LogLevel level, const char* levelStr, const char* message); + // Global channel levels + static LogLevel _serialLevel; + static LogLevel _mqttLevel; + static LogLevel _sdLevel; + + // Per-subsystem overrides per channel (tag -> level) + // A value of NONE means "suppress this subsystem on this channel entirely" + static std::map _serialOverrides; + static std::map _mqttOverrides; + static std::map _sdOverrides; + + // Output channel callbacks + static MqttPublishCallback _mqttCallback; + static SdWriteCallback _sdCallback; + static String _mqttLogTopic; + + // Core internal methods + static void log(LogLevel level, const char* levelStr, const char* tag, const char* format, va_list args); + static void publishToMqtt(LogLevel level, const char* levelStr, const char* tag, const char* message); + static void writeToSd(LogLevel level, const char* levelStr, const char* tag, const char* message); + + // Resolve effective level for a tag on a channel + static LogLevel resolveLevel(const char* tag, LogLevel globalLevel, const std::map& overrides); }; -// Convenience macros for easier use -#define LOG_ERROR(...) Logging::error(__VA_ARGS__) -#define LOG_WARNING(...) Logging::warning(__VA_ARGS__) -#define LOG_INFO(...) Logging::info(__VA_ARGS__) -#define LOG_DEBUG(...) Logging::debug(__VA_ARGS__) -#define LOG_VERBOSE(...) Logging::verbose(__VA_ARGS__) +// ═══════════════════════════════════════════════════════════════════════════════════ +// MACROS +// Each .cpp file defines: #define TAG "SubsystemName" +// Then uses: LOG_INFO(TAG, "message %d", value) +// ═══════════════════════════════════════════════════════════════════════════════════ +#define LOG_ERROR(tag, ...) Logging::error(tag, __VA_ARGS__) +#define LOG_WARNING(tag, ...) Logging::warning(tag, __VA_ARGS__) +#define LOG_INFO(tag, ...) Logging::info(tag, __VA_ARGS__) +#define LOG_DEBUG(tag, ...) Logging::debug(tag, __VA_ARGS__) +#define LOG_VERBOSE(tag, ...) Logging::verbose(tag, __VA_ARGS__) #endif diff --git a/vesper/src/Networking/Networking.cpp b/vesper/src/Networking/Networking.cpp index 20d641b..57eaa25 100644 --- a/vesper/src/Networking/Networking.cpp +++ b/vesper/src/Networking/Networking.cpp @@ -1,4 +1,6 @@ #include "Networking.hpp" + +#define TAG "Networking" #include "../ConfigManager/ConfigManager.hpp" #include "../Logging/Logging.hpp" #include @@ -20,7 +22,7 @@ Networking::Networking(ConfigManager& configManager) // Safety check for multiple instances if (_instance != nullptr) { - LOG_WARNING("Multiple Networking instances detected! Previous instance will be overridden."); + LOG_WARNING(TAG, "Multiple Networking instances detected! Previous instance will be overridden."); } _instance = this; @@ -48,7 +50,7 @@ Networking::~Networking() { void Networking::begin() { - LOG_INFO("Initializing Networking System"); + LOG_INFO(TAG, "Initializing Networking System"); // Create reconnection timer _reconnectionTimer = xTimerCreate("reconnectionTimer", pdMS_TO_TICKS(RECONNECTION_INTERVAL), @@ -66,7 +68,7 @@ void Networking::begin() { // Check if permanent AP mode is enabled if (_configManager.getPermanentAPMode()) { - LOG_INFO("Permanent AP mode enabled - starting AP mode on 192.168.4.1"); + LOG_INFO(TAG, "Permanent AP mode enabled - starting AP mode on 192.168.4.1"); startPermanentAPMode(); return; } @@ -78,23 +80,23 @@ void Networking::begin() { // hwConfig.ethPhyIrq, hwConfig.ethPhyRst, SPI); // Start connection sequence - Skip Ethernet, go directly to WiFi - LOG_INFO("Starting WiFi connection (Ethernet disabled)..."); + LOG_INFO(TAG, "Starting WiFi connection (Ethernet disabled)..."); startWiFiConnection(); } void Networking::startEthernetConnection() { // ETHERNET DISABLED - Skip to WiFi immediately - LOG_DEBUG("Ethernet connection disabled - falling back to WiFi"); + LOG_DEBUG(TAG, "Ethernet connection disabled - falling back to WiFi"); startWiFiConnection(); // Original Ethernet code (DISABLED): - // LOG_INFO("Attempting Ethernet connection..."); + // LOG_INFO(TAG, "Attempting Ethernet connection..."); // setState(NetworkState::CONNECTING_ETHERNET); // // // Check if Ethernet hardware initialization failed // if (!ETH.linkUp()) { - // LOG_WARNING("Ethernet hardware not detected or failed to initialize"); - // LOG_INFO("Falling back to WiFi immediately"); + // LOG_WARNING(TAG, "Ethernet hardware not detected or failed to initialize"); + // LOG_INFO(TAG, "Falling back to WiFi immediately"); // startWiFiConnection(); // return; // } @@ -108,13 +110,13 @@ void Networking::startEthernetConnection() { } void Networking::startWiFiConnection() { - LOG_INFO("Attempting WiFi connection..."); + LOG_INFO(TAG, "Attempting WiFi connection..."); setState(NetworkState::CONNECTING_WIFI); // ALWAYS try default credentials first (for bundled router deployment) auto& netConfig = _configManager.getNetworkConfig(); - LOG_INFO("Using DEFAULT WiFi credentials - SSID: %s", netConfig.defaultWifiSsid.c_str()); + LOG_INFO(TAG, "Using DEFAULT WiFi credentials - SSID: %s", netConfig.defaultWifiSsid.c_str()); applyNetworkConfig(false); // false = WiFi config WiFi.mode(WIFI_STA); @@ -126,7 +128,7 @@ void Networking::startWiFiConnection() { // Original WiFiManager fallback code (DISABLED for fixed deployment): // // First, try default credentials if this is the first boot attempt // if (!_bootSequenceComplete && !hasValidWiFiCredentials()) { - // LOG_INFO("No saved credentials - trying default WiFi credentials"); + // LOG_INFO(TAG, "No saved credentials - trying default WiFi credentials"); // auto& netConfig = _configManager.getNetworkConfig(); // // applyNetworkConfig(false); // false = WiFi config @@ -140,7 +142,7 @@ void Networking::startWiFiConnection() { // // // Check if we have valid saved credentials // if (!hasValidWiFiCredentials()) { - // LOG_WARNING("No valid WiFi credentials found"); + // LOG_WARNING(TAG, "No valid WiFi credentials found"); // if (!_bootSequenceComplete) { // // No credentials during boot - start portal // startWiFiPortal(); @@ -150,7 +152,7 @@ void Networking::startWiFiConnection() { // // // Get and log saved credentials (for debugging) // String savedSSID = _wifiManager->getWiFiSSID(true); - // LOG_INFO("Using WiFiManager saved credentials - SSID: %s", savedSSID.c_str()); + // LOG_INFO(TAG, "Using WiFiManager saved credentials - SSID: %s", savedSSID.c_str()); // // applyNetworkConfig(false); // false = WiFi config // WiFi.mode(WIFI_STA); @@ -165,7 +167,7 @@ void Networking::startWiFiConnection() { } void Networking::startWiFiPortal() { - LOG_INFO("Starting WiFi configuration portal..."); + LOG_INFO(TAG, "Starting WiFi configuration portal..."); setState(NetworkState::WIFI_PORTAL_MODE); WiFi.mode(WIFI_AP_STA); @@ -173,7 +175,7 @@ void Networking::startWiFiPortal() { auto& netConfig = _configManager.getNetworkConfig(); String apName = "Vesper-" + _configManager.getDeviceUID(); - LOG_INFO("WiFi Portal: SSID='%s', Password='%s'", apName.c_str(), netConfig.apPass.c_str()); + LOG_INFO(TAG, "WiFi Portal: SSID='%s', Password='%s'", apName.c_str(), netConfig.apPass.c_str()); // Add custom HTML to WiFiManager portal for permanent AP mode toggle String customHTML = "

Network Mode

"; @@ -188,10 +190,10 @@ void Networking::startWiFiPortal() { _wifiManager->setCustomHeadElement(customHTML.c_str()); if (_wifiManager->autoConnect(apName.c_str(), netConfig.apPass.c_str())) { - LOG_INFO("WiFi configured successfully via portal"); + LOG_INFO(TAG, "WiFi configured successfully via portal"); onWiFiConnected(); } else { - LOG_ERROR("WiFi portal configuration failed"); + LOG_ERROR(TAG, "WiFi portal configuration failed"); setState(NetworkState::DISCONNECTED); // Start reconnection timer to try again xTimerStart(_reconnectionTimer, 0); @@ -203,14 +205,14 @@ void Networking::handleReconnection() { return; // Already connected } - LOG_DEBUG("Attempting reconnection..."); + LOG_DEBUG(TAG, "Attempting reconnection..."); // ETHERNET DISABLED - Skip Ethernet timeout checks // Check for Ethernet timeout (fall back to WiFi) // if (_state == NetworkState::CONNECTING_ETHERNET) { // unsigned long now = millis(); // if (now - _lastConnectionAttempt > 5000) { // 5 second timeout - // LOG_INFO("Ethernet connection timeout - falling back to WiFi"); + // LOG_INFO(TAG, "Ethernet connection timeout - falling back to WiFi"); // startWiFiConnection(); // return; // } @@ -222,20 +224,20 @@ void Networking::handleReconnection() { unsigned long now = millis(); if (now - _lastConnectionAttempt > 10000) { // 10 second timeout _wifiConnectionFailures++; - LOG_WARNING("WiFi connection timeout (failure #%d)", _wifiConnectionFailures); + LOG_WARNING(TAG, "WiFi connection timeout (failure #%d)", _wifiConnectionFailures); // After 3 failed attempts during boot, start portal if (_wifiConnectionFailures >= MAX_WIFI_FAILURES) { - LOG_ERROR("Multiple WiFi connection failures - credentials may be invalid"); + LOG_ERROR(TAG, "Multiple WiFi connection failures - credentials may be invalid"); if (!_bootSequenceComplete) { // Boot not complete yet - open portal - LOG_INFO("Opening WiFi portal for reconfiguration"); + LOG_INFO(TAG, "Opening WiFi portal for reconfiguration"); _wifiConnectionFailures = 0; // Reset counter startWiFiPortal(); } else { // Boot already complete - just keep retrying - LOG_WARNING("WiFi connection lost - continuing retry attempts"); + LOG_WARNING(TAG, "WiFi connection lost - continuing retry attempts"); // Reset counter after extended failure to prevent overflow if (_wifiConnectionFailures > 10) { _wifiConnectionFailures = 3; @@ -252,14 +254,14 @@ void Networking::handleReconnection() { } // State is DISCONNECTED - WiFi only mode (Ethernet disabled) - LOG_INFO("Disconnected - trying WiFi"); + LOG_INFO(TAG, "Disconnected - trying WiFi"); if (hasValidWiFiCredentials()) { startWiFiConnection(); } else if (!_bootSequenceComplete) { // No credentials during boot - start portal startWiFiPortal(); } else { - LOG_WARNING("No WiFi credentials and boot sequence complete - waiting"); + LOG_WARNING(TAG, "No WiFi credentials and boot sequence complete - waiting"); } } @@ -270,34 +272,34 @@ void Networking::handleReconnection() { bool Networking::isHealthy() const { // Check if we have any active connection if (_activeConnection == ConnectionType::NONE) { - LOG_DEBUG("Networking: Unhealthy - No active connection"); + LOG_DEBUG(TAG, "Networking: Unhealthy - No active connection"); return false; } // Check connection state (Ethernet disabled, only check WiFi or AP) if (_state != NetworkState::CONNECTED_WIFI && _state != NetworkState::AP_MODE_PERMANENT) { - LOG_DEBUG("Networking: Unhealthy - Not in connected state"); + LOG_DEBUG(TAG, "Networking: Unhealthy - Not in connected state"); return false; } // Check IP address validity String ip = getLocalIP(); if (ip == "0.0.0.0" || ip.isEmpty()) { - LOG_DEBUG("Networking: Unhealthy - Invalid IP address"); + LOG_DEBUG(TAG, "Networking: Unhealthy - Invalid IP address"); return false; } // For WiFi connections, check signal strength if (_activeConnection == ConnectionType::WIFI) { if (WiFi.status() != WL_CONNECTED) { - LOG_DEBUG("Networking: Unhealthy - WiFi not connected"); + LOG_DEBUG(TAG, "Networking: Unhealthy - WiFi not connected"); return false; } // Check signal strength (RSSI should be better than -80 dBm) int32_t rssi = WiFi.RSSI(); if (rssi < -80) { - LOG_DEBUG("Networking: Unhealthy - Poor WiFi signal: %d dBm", rssi); + LOG_DEBUG(TAG, "Networking: Unhealthy - Poor WiFi signal: %d dBm", rssi); return false; } } @@ -306,7 +308,7 @@ bool Networking::isHealthy() const { // For Ethernet connections, check link status // if (_activeConnection == ConnectionType::ETHERNET) { // if (!ETH.linkUp()) { - // LOG_DEBUG("Networking: Unhealthy - Ethernet link down"); + // LOG_DEBUG(TAG, "Networking: Unhealthy - Ethernet link down"); // return false; // } // } @@ -316,14 +318,14 @@ bool Networking::isHealthy() const { void Networking::setState(NetworkState newState) { if (_state != newState) { - LOG_DEBUG("Network state: %d -> %d", (int)_state, (int)newState); + LOG_DEBUG(TAG, "Network state: %d -> %d", (int)_state, (int)newState); _state = newState; } } void Networking::setActiveConnection(ConnectionType type) { if (_activeConnection != type) { - LOG_INFO("Active connection changed: %d -> %d", (int)_activeConnection, (int)type); + LOG_INFO(TAG, "Active connection changed: %d -> %d", (int)_activeConnection, (int)type); _activeConnection = type; } } @@ -339,10 +341,10 @@ void Networking::notifyConnectionChange(bool connected) { // Event handlers (ETHERNET DISABLED) void Networking::onEthernetConnected() { // ETHERNET DISABLED - This should never be called - LOG_WARNING("Ethernet event received but Ethernet is disabled - ignoring"); + LOG_WARNING(TAG, "Ethernet event received but Ethernet is disabled - ignoring"); // Original code (DISABLED): - // LOG_INFO("Ethernet connected successfully"); + // LOG_INFO(TAG, "Ethernet connected successfully"); // setState(NetworkState::CONNECTED_ETHERNET); // setActiveConnection(ConnectionType::ETHERNET); // @@ -360,10 +362,10 @@ void Networking::onEthernetConnected() { void Networking::onEthernetDisconnected() { // ETHERNET DISABLED - This should never be called - LOG_WARNING("Ethernet disconnect event received but Ethernet is disabled - ignoring"); + LOG_WARNING(TAG, "Ethernet disconnect event received but Ethernet is disabled - ignoring"); // Original code (DISABLED): - // LOG_WARNING("Ethernet disconnected"); + // LOG_WARNING(TAG, "Ethernet disconnected"); // // if (_activeConnection == ConnectionType::ETHERNET) { // setState(NetworkState::DISCONNECTED); @@ -376,7 +378,7 @@ void Networking::onEthernetDisconnected() { } void Networking::onWiFiConnected() { - LOG_INFO("WiFi connected successfully - IP: %s", WiFi.localIP().toString().c_str()); + LOG_INFO(TAG, "WiFi connected successfully - IP: %s", WiFi.localIP().toString().c_str()); setState(NetworkState::CONNECTED_WIFI); setActiveConnection(ConnectionType::WIFI); @@ -393,7 +395,7 @@ void Networking::onWiFiConnected() { } void Networking::onWiFiDisconnected() { - LOG_WARNING("WiFi disconnected"); + LOG_WARNING(TAG, "WiFi disconnected"); if (_activeConnection == ConnectionType::WIFI) { setState(NetworkState::DISCONNECTED); @@ -407,11 +409,11 @@ void Networking::onWiFiDisconnected() { void Networking::onEthernetCableChange(bool connected) { // ETHERNET DISABLED - Ignore cable events - LOG_DEBUG("Ethernet cable event ignored (Ethernet disabled)"); + LOG_DEBUG(TAG, "Ethernet cable event ignored (Ethernet disabled)"); // Original code (DISABLED): // _ethernetCableConnected = connected; - // LOG_INFO("Ethernet cable %s", connected ? "connected" : "disconnected"); + // LOG_INFO(TAG, "Ethernet cable %s", connected ? "connected" : "disconnected"); // // if (connected && _activeConnection != ConnectionType::ETHERNET) { // // Cable connected and we're not using Ethernet - try to connect @@ -425,15 +427,15 @@ void Networking::applyNetworkConfig(bool ethernet) { // ETHERNET DISABLED - Only apply WiFi config if (ethernet) { - LOG_WARNING("applyNetworkConfig called with ethernet=true but Ethernet is disabled"); + LOG_WARNING(TAG, "applyNetworkConfig called with ethernet=true but Ethernet is disabled"); return; } if (netConfig.useStaticIP) { - LOG_INFO("Applying static IP configuration"); + LOG_INFO(TAG, "Applying static IP configuration"); WiFi.config(netConfig.ip, netConfig.gateway, netConfig.subnet, netConfig.dns1, netConfig.dns2); } else { - LOG_INFO("Using DHCP configuration"); + LOG_INFO(TAG, "Using DHCP configuration"); } WiFi.setHostname(netConfig.hostname.c_str()); @@ -455,7 +457,7 @@ String Networking::getLocalIP() const { switch (_activeConnection) { case ConnectionType::ETHERNET: // ETHERNET DISABLED - Should never reach here - LOG_WARNING("getLocalIP called with ETHERNET type but Ethernet is disabled"); + LOG_WARNING(TAG, "getLocalIP called with ETHERNET type but Ethernet is disabled"); return "0.0.0.0"; case ConnectionType::WIFI: return WiFi.localIP().toString(); @@ -470,7 +472,7 @@ String Networking::getGateway() const { switch (_activeConnection) { case ConnectionType::ETHERNET: // ETHERNET DISABLED - Should never reach here - LOG_WARNING("getGateway called with ETHERNET type but Ethernet is disabled"); + LOG_WARNING(TAG, "getGateway called with ETHERNET type but Ethernet is disabled"); return "0.0.0.0"; case ConnectionType::WIFI: return WiFi.gatewayIP().toString(); @@ -480,7 +482,7 @@ String Networking::getGateway() const { } void Networking::forceReconnect() { - LOG_INFO("Forcing reconnection..."); + LOG_INFO(TAG, "Forcing reconnection..."); setState(NetworkState::RECONNECTING); setActiveConnection(ConnectionType::NONE); @@ -499,7 +501,7 @@ void Networking::forceReconnect() { void Networking::networkEventHandler(arduino_event_id_t event, arduino_event_info_t info) { if (!_instance) return; - LOG_DEBUG("Network event: %d", event); + LOG_DEBUG(TAG, "Network event: %d", event); switch (event) { // ETHERNET EVENTS DISABLED - Ignored @@ -508,22 +510,22 @@ void Networking::networkEventHandler(arduino_event_id_t event, arduino_event_inf case ARDUINO_EVENT_ETH_GOT_IP: case ARDUINO_EVENT_ETH_DISCONNECTED: case ARDUINO_EVENT_ETH_STOP: - LOG_DEBUG("Ethernet event ignored (Ethernet disabled)"); + LOG_DEBUG(TAG, "Ethernet event ignored (Ethernet disabled)"); break; // WiFi events (ACTIVE) case ARDUINO_EVENT_WIFI_STA_GOT_IP: - LOG_INFO("WiFi Got IP: %s", WiFi.localIP().toString().c_str()); + LOG_INFO(TAG, "WiFi Got IP: %s", WiFi.localIP().toString().c_str()); _instance->onWiFiConnected(); break; case ARDUINO_EVENT_WIFI_STA_DISCONNECTED: - LOG_WARNING("WiFi Disconnected"); + LOG_WARNING(TAG, "WiFi Disconnected"); _instance->onWiFiDisconnected(); break; case ARDUINO_EVENT_WIFI_STA_CONNECTED: - LOG_DEBUG("WiFi STA Connected"); + LOG_DEBUG(TAG, "WiFi STA Connected"); break; default: @@ -538,7 +540,7 @@ void Networking::reconnectionTimerCallback(TimerHandle_t xTimer) { } void Networking::startPermanentAPMode() { - LOG_INFO("Starting Permanent AP Mode"); + LOG_INFO(TAG, "Starting Permanent AP Mode"); setState(NetworkState::AP_MODE_PERMANENT); // Stop any existing connections @@ -559,24 +561,24 @@ void Networking::startPermanentAPMode() { IPAddress subnet(255, 255, 255, 0); if (!WiFi.softAPConfig(local_IP, gateway, subnet)) { - LOG_ERROR("Failed to configure AP IP address"); + LOG_ERROR(TAG, "Failed to configure AP IP address"); } // Start AP bool apStarted; if (apPass.isEmpty()) { apStarted = WiFi.softAP(apName.c_str()); - LOG_INFO("Starting open AP (no password): %s", apName.c_str()); + LOG_INFO(TAG, "Starting open AP (no password): %s", apName.c_str()); } else { apStarted = WiFi.softAP(apName.c_str(), apPass.c_str()); - LOG_INFO("Starting AP with password: %s", apName.c_str()); + LOG_INFO(TAG, "Starting AP with password: %s", apName.c_str()); } if (apStarted) { - LOG_INFO("✅ Permanent AP Mode active"); - LOG_INFO(" SSID: %s", apName.c_str()); - LOG_INFO(" IP: 192.168.4.1"); - LOG_INFO(" Subnet: 255.255.255.0"); + LOG_INFO(TAG, "✅ Permanent AP Mode active"); + LOG_INFO(TAG, " SSID: %s", apName.c_str()); + LOG_INFO(TAG, " IP: 192.168.4.1"); + LOG_INFO(TAG, " Subnet: 255.255.255.0"); setActiveConnection(ConnectionType::AP); @@ -591,7 +593,7 @@ void Networking::startPermanentAPMode() { // Notify connected notifyConnectionChange(true); } else { - LOG_ERROR("❌ Failed to start AP Mode"); + LOG_ERROR(TAG, "❌ Failed to start AP Mode"); setState(NetworkState::DISCONNECTED); } } diff --git a/vesper/src/OTAManager/OTAManager.cpp b/vesper/src/OTAManager/OTAManager.cpp index b7bb296..a718b86 100644 --- a/vesper/src/OTAManager/OTAManager.cpp +++ b/vesper/src/OTAManager/OTAManager.cpp @@ -1,4 +1,6 @@ #include "OTAManager.hpp" + +#define TAG "OTAManager" #include "../ConfigManager/ConfigManager.hpp" #include "../Logging/Logging.hpp" #include "../Player/Player.hpp" @@ -56,13 +58,13 @@ OTAManager::~OTAManager() { } void OTAManager::begin() { - LOG_INFO("OTA Manager initialized"); + LOG_INFO(TAG, "OTA Manager initialized"); setStatus(Status::IDLE); // Create semaphore for worker task signaling _otaWorkSignal = xSemaphoreCreateBinary(); if (_otaWorkSignal == NULL) { - LOG_ERROR("Failed to create OTA work semaphore!"); + LOG_ERROR(TAG, "Failed to create OTA work semaphore!"); return; } @@ -78,13 +80,13 @@ void OTAManager::begin() { ); if (taskCreated != pdPASS) { - LOG_ERROR("Failed to create OTA worker task!"); + LOG_ERROR(TAG, "Failed to create OTA worker task!"); vSemaphoreDelete(_otaWorkSignal); _otaWorkSignal = NULL; return; } - LOG_INFO("OTA worker task created with 8KB stack on Core 0"); + LOG_INFO(TAG, "OTA worker task created with 8KB stack on Core 0"); // Create timer for scheduled checks (checks every minute if it's 3:00 AM) _scheduledCheckTimer = xTimerCreate( @@ -97,9 +99,9 @@ void OTAManager::begin() { if (_scheduledCheckTimer != NULL) { xTimerStart(_scheduledCheckTimer, 0); - LOG_INFO("OTA scheduled check timer started (will check at 3:00 AM)"); + LOG_INFO(TAG, "OTA scheduled check timer started (will check at 3:00 AM)"); } else { - LOG_ERROR("Failed to create OTA scheduled check timer!"); + LOG_ERROR(TAG, "Failed to create OTA scheduled check timer!"); } // 🔥 NEW: Create one-shot timer for initial boot check (5 seconds after boot) @@ -114,9 +116,9 @@ void OTAManager::begin() { if (_initialCheckTimer != NULL) { xTimerStart(_initialCheckTimer, 0); - LOG_INFO("OTA initial check scheduled for 5 seconds after boot (non-blocking)"); + LOG_INFO(TAG, "OTA initial check scheduled for 5 seconds after boot (non-blocking)"); } else { - LOG_ERROR("Failed to create OTA initial check timer!"); + LOG_ERROR(TAG, "Failed to create OTA initial check timer!"); } } @@ -172,7 +174,7 @@ void OTAManager::scheduledCheckCallback(TimerHandle_t xTimer) { ota->_pendingWork = OTAWorkType::SCHEDULED_CHECK; xSemaphoreGive(ota->_otaWorkSignal); } else if (ota->isPlayerActive()) { - LOG_WARNING("⚠️ Player is active - skipping scheduled update check"); + LOG_WARNING(TAG, "⚠️ Player is active - skipping scheduled update check"); } } } @@ -180,21 +182,21 @@ void OTAManager::scheduledCheckCallback(TimerHandle_t xTimer) { // ✅ NEW: Check for emergency updates only (called by scheduled timer) void OTAManager::checkForEmergencyUpdates() { if (_status != Status::IDLE) { - LOG_WARNING("OTA check already in progress"); + LOG_WARNING(TAG, "OTA check already in progress"); return; } - LOG_INFO("Checking for EMERGENCY updates only..."); + LOG_INFO(TAG, "Checking for EMERGENCY updates only..."); checkForUpdates("stable"); // Check stable channel // Only proceed if emergency flag is set if (_updateAvailable && _isEmergency) { - LOG_INFO("🚨 EMERGENCY update detected during scheduled check - updating immediately"); + LOG_INFO(TAG, "🚨 EMERGENCY update detected during scheduled check - updating immediately"); update("stable"); } else if (_updateAvailable && _isMandatory) { - LOG_INFO("⚠️ Mandatory update available, but will wait for next boot"); + LOG_INFO(TAG, "⚠️ Mandatory update available, but will wait for next boot"); } else { - LOG_INFO("✅ No emergency updates available"); + LOG_INFO(TAG, "✅ No emergency updates available"); } } @@ -205,39 +207,39 @@ void OTAManager::checkForUpdates() { void OTAManager::checkForUpdates(const String& channel) { if (_status != Status::IDLE) { - LOG_WARNING("OTA check already in progress"); + LOG_WARNING(TAG, "OTA check already in progress"); return; } // 🔥 CRITICAL: Check network connectivity before attempting HTTP requests - if (WiFi.status() != WL_CONNECTED && !ETH.linkUp()) { - LOG_WARNING("OTA check skipped - no network connectivity"); + if (WiFi.status() != WL_CONNECTED) { // ETHERNET DISABLED - WiFi only + LOG_WARNING(TAG, "OTA check skipped - no network connectivity"); return; } setStatus(Status::CHECKING_VERSION); - LOG_INFO("Checking for firmware updates in %s channel for %s...", + LOG_INFO(TAG, "Checking for firmware updates in %s channel for %s...", channel.c_str(), _configManager.getHardwareVariant().c_str()); if (checkVersion(channel)) { uint16_t currentVersion = getCurrentVersion(); - LOG_INFO("Current version: %u, Available version: %u (Channel: %s)", + LOG_INFO(TAG, "Current version: %u, Available version: %u (Channel: %s)", currentVersion, _availableVersion, channel.c_str()); if (_availableVersion > currentVersion) { _updateAvailable = true; - LOG_INFO("New version available! Mandatory: %s, Emergency: %s", + LOG_INFO(TAG, "New version available! Mandatory: %s, Emergency: %s", _isMandatory ? "YES" : "NO", _isEmergency ? "YES" : "NO"); setStatus(Status::IDLE); // Auto-update for emergency or mandatory updates during boot check if (channel == "stable" && (_isEmergency || _isMandatory)) { - LOG_INFO("Emergency/Mandatory update detected - starting automatic update"); + LOG_INFO(TAG, "Emergency/Mandatory update detected - starting automatic update"); update(channel); } } else { _updateAvailable = false; - LOG_INFO("No new version available"); + LOG_INFO(TAG, "No new version available"); setStatus(Status::IDLE); } } else { @@ -252,21 +254,21 @@ void OTAManager::update() { void OTAManager::update(const String& channel) { if (_status != Status::IDLE) { - LOG_WARNING("OTA update already in progress"); + LOG_WARNING(TAG, "OTA update already in progress"); return; } if (!_updateAvailable) { - LOG_WARNING("No update available for channel: %s", channel.c_str()); + LOG_WARNING(TAG, "No update available for channel: %s", channel.c_str()); return; } - LOG_INFO("Starting OTA update from %s channel...", channel.c_str()); + LOG_INFO(TAG, "Starting OTA update from %s channel...", channel.c_str()); setStatus(Status::DOWNLOADING); if (downloadAndInstall(channel)) { setStatus(Status::SUCCESS); - LOG_INFO("Update successfully finished. Rebooting..."); + LOG_INFO(TAG, "Update successfully finished. Rebooting..."); delay(1000); ESP.restart(); } else { @@ -304,7 +306,7 @@ bool OTAManager::checkVersion(const String& channel) { String baseUrl = servers[serverIndex]; String metadataUrl = baseUrl + "/ota/" + _configManager.getHardwareVariant() + "/" + channel + "/metadata.json"; - LOG_INFO("OTA: Trying server %d/%d: %s", serverIndex + 1, servers.size(), baseUrl.c_str()); + LOG_INFO(TAG, "OTA: Trying server %d/%d: %s", serverIndex + 1, servers.size(), baseUrl.c_str()); HTTPClient http; http.setTimeout(updateConfig.timeout); @@ -316,7 +318,7 @@ bool OTAManager::checkVersion(const String& channel) { // Retry logic for current server while (retryCount < updateConfig.retries && httpCode != HTTP_CODE_OK) { if (retryCount > 0) { - LOG_INFO("OTA: Retry %d/%d for %s", retryCount + 1, updateConfig.retries, baseUrl.c_str()); + LOG_INFO(TAG, "OTA: Retry %d/%d for %s", retryCount + 1, updateConfig.retries, baseUrl.c_str()); delay(1000 * retryCount); // Exponential backoff } @@ -333,7 +335,7 @@ bool OTAManager::checkVersion(const String& channel) { DeserializationError error = deserializeJson(doc, jsonStr); if (error) { - LOG_ERROR("OTA: Failed to parse metadata JSON from %s: %s", + LOG_ERROR(TAG, "OTA: Failed to parse metadata JSON from %s: %s", baseUrl.c_str(), error.c_str()); continue; // Try next server } @@ -349,7 +351,7 @@ bool OTAManager::checkVersion(const String& channel) { // ✅ NEW: Validate channel matches requested if (_updateChannel != channel) { - LOG_ERROR("OTA: Channel mismatch! Requested: %s, Got: %s", + LOG_ERROR(TAG, "OTA: Channel mismatch! Requested: %s, Got: %s", channel.c_str(), _updateChannel.c_str()); _lastError = ErrorCode::CHANNEL_MISMATCH; continue; // Try next server @@ -359,7 +361,7 @@ bool OTAManager::checkVersion(const String& channel) { String hwVariant = doc["hardwareVariant"].as(); String ourHardwareVariant = _configManager.getHardwareVariant(); if (!hwVariant.isEmpty() && hwVariant != ourHardwareVariant) { - LOG_ERROR("OTA: Hardware variant mismatch! Expected: %s, Got: %s", + LOG_ERROR(TAG, "OTA: Hardware variant mismatch! Expected: %s, Got: %s", ourHardwareVariant.c_str(), hwVariant.c_str()); continue; // Try next server } @@ -367,36 +369,36 @@ bool OTAManager::checkVersion(const String& channel) { // ✅ NEW: Check minVersion compatibility uint16_t currentVersion = getCurrentVersion(); if (_minVersion > 0 && currentVersion < _minVersion) { - LOG_ERROR("OTA: Current version %u is below minimum required %u", + LOG_ERROR(TAG, "OTA: Current version %u is below minimum required %u", currentVersion, _minVersion); - LOG_ERROR("OTA: Intermediate update required first - cannot proceed"); + LOG_ERROR(TAG, "OTA: Intermediate update required first - cannot proceed"); _lastError = ErrorCode::VERSION_TOO_LOW; continue; // Try next server } if (_availableVersion == 0) { - LOG_ERROR("OTA: Invalid version in metadata from %s", baseUrl.c_str()); + LOG_ERROR(TAG, "OTA: Invalid version in metadata from %s", baseUrl.c_str()); continue; // Try next server } if (_availableChecksum.length() != 64) { // SHA256 is 64 hex characters - LOG_ERROR("OTA: Invalid checksum in metadata from %s", baseUrl.c_str()); + LOG_ERROR(TAG, "OTA: Invalid checksum in metadata from %s", baseUrl.c_str()); continue; // Try next server } - LOG_INFO("OTA: Successfully got metadata from %s", baseUrl.c_str()); - LOG_INFO("OTA: Expected file size: %u bytes, Min version: %u", + LOG_INFO(TAG, "OTA: Successfully got metadata from %s", baseUrl.c_str()); + LOG_INFO(TAG, "OTA: Expected file size: %u bytes, Min version: %u", _expectedFileSize, _minVersion); return true; // Success! } else { - LOG_ERROR("OTA: Server %s failed after %d retries. HTTP error: %d", + LOG_ERROR(TAG, "OTA: Server %s failed after %d retries. HTTP error: %d", baseUrl.c_str(), updateConfig.retries, httpCode); http.end(); } } // All servers failed - LOG_ERROR("OTA: All %d servers failed to provide metadata", servers.size()); + LOG_ERROR(TAG, "OTA: All %d servers failed to provide metadata", servers.size()); _lastError = ErrorCode::HTTP_ERROR; return false; } @@ -409,26 +411,26 @@ bool OTAManager::downloadAndInstall(const String& channel) { String baseUrl = servers[serverIndex]; String firmwareUrl = baseUrl + "/ota/" + _configManager.getHardwareVariant() + "/" + channel + "/firmware.bin"; - LOG_INFO("OTA: Trying firmware download from server %d/%d: %s", + LOG_INFO(TAG, "OTA: Trying firmware download from server %d/%d: %s", serverIndex + 1, servers.size(), baseUrl.c_str()); // 🔥 Download directly to flash (bypassing problematic SD card writes) if (downloadDirectToFlash(firmwareUrl, _expectedFileSize)) { - LOG_INFO("✅ OTA update successful!"); + LOG_INFO(TAG, "✅ OTA update successful!"); return true; } else { - LOG_WARNING("OTA: Firmware download failed from %s, trying next server", baseUrl.c_str()); + LOG_WARNING(TAG, "OTA: Firmware download failed from %s, trying next server", baseUrl.c_str()); } } // All servers failed - LOG_ERROR("OTA: All %d servers failed to provide firmware", servers.size()); + LOG_ERROR(TAG, "OTA: All %d servers failed to provide firmware", servers.size()); return false; } // 🔥 NEW: Download directly to flash memory, bypassing SD card bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { - LOG_INFO("OTA: Starting direct-to-flash download (bypassing SD card)"); + LOG_INFO(TAG, "OTA: Starting direct-to-flash download (bypassing SD card)"); HTTPClient http; http.begin(url.c_str()); @@ -437,7 +439,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { int httpCode = http.GET(); if (httpCode != HTTP_CODE_OK) { - LOG_ERROR("Download HTTP error code: %d", httpCode); + LOG_ERROR(TAG, "Download HTTP error code: %d", httpCode); setStatus(Status::FAILED, ErrorCode::HTTP_ERROR); http.end(); return false; @@ -445,11 +447,11 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { int contentLength = http.getSize(); - LOG_INFO("OTA: HTTP Response Code: %d", httpCode); - LOG_INFO("OTA: Content-Length: %d bytes", contentLength); + LOG_INFO(TAG, "OTA: HTTP Response Code: %d", httpCode); + LOG_INFO(TAG, "OTA: Content-Length: %d bytes", contentLength); if (contentLength <= 0) { - LOG_ERROR("Invalid content length"); + LOG_ERROR(TAG, "Invalid content length"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); http.end(); return false; @@ -457,7 +459,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { // Validate file size if (expectedSize > 0 && (size_t)contentLength != expectedSize) { - LOG_ERROR("OTA: File size mismatch! Expected: %u, Got: %d", expectedSize, contentLength); + LOG_ERROR(TAG, "OTA: File size mismatch! Expected: %u, Got: %d", expectedSize, contentLength); setStatus(Status::FAILED, ErrorCode::SIZE_MISMATCH); http.end(); return false; @@ -466,7 +468,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { // ═══════════════════════════════════════════════════════════════════════════ // ENTER OTA FREEZE MODE - Pause all non-critical systems // ═══════════════════════════════════════════════════════════════════════════ - LOG_INFO("OTA: Entering freeze mode - pausing TimeKeeper and Telemetry"); + LOG_INFO(TAG, "OTA: Entering freeze mode - pausing TimeKeeper and Telemetry"); if (_timeKeeper) { _timeKeeper->pauseClockUpdates(); @@ -478,7 +480,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { // Begin OTA update to flash with MD5 validation enabled if (!Update.begin(contentLength)) { - LOG_ERROR("Not enough space to begin OTA update"); + LOG_ERROR(TAG, "Not enough space to begin OTA update"); setStatus(Status::FAILED, ErrorCode::INSUFFICIENT_SPACE); http.end(); @@ -489,8 +491,8 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { return false; } - LOG_INFO("OTA: Update partition ready, starting stream write..."); - LOG_INFO("OTA: Checksum validation will be performed by ESP32 bootloader"); + LOG_INFO(TAG, "OTA: Update partition ready, starting stream write..."); + LOG_INFO(TAG, "OTA: Checksum validation will be performed by ESP32 bootloader"); setStatus(Status::INSTALLING); // Stream directly to flash with periodic watchdog feeding @@ -511,7 +513,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { size_t bytesWritten = Update.write(buffer, bytesRead); if (bytesWritten != bytesRead) { - LOG_ERROR("OTA: Flash write failed at offset %u (%u/%u bytes written)", + LOG_ERROR(TAG, "OTA: Flash write failed at offset %u (%u/%u bytes written)", written, bytesWritten, bytesRead); http.end(); @@ -528,7 +530,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { // Log progress every 20% size_t currentPercent = (written * 100) / contentLength; if (currentPercent >= lastLoggedPercent + 20) { - LOG_INFO("OTA: Flash write progress: %u%% (%u/%u bytes)", + LOG_INFO(TAG, "OTA: Flash write progress: %u%% (%u/%u bytes)", currentPercent, written, contentLength); lastLoggedPercent = currentPercent; } @@ -550,7 +552,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { // ═══════════════════════════════════════════════════════════════════════════ // EXIT OTA FREEZE MODE - Resume all paused systems // ═══════════════════════════════════════════════════════════════════════════ - LOG_INFO("OTA: Exiting freeze mode - resuming TimeKeeper and Telemetry"); + LOG_INFO(TAG, "OTA: Exiting freeze mode - resuming TimeKeeper and Telemetry"); if (_timeKeeper) { _timeKeeper->resumeClockUpdates(); @@ -561,18 +563,18 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { } if (written == (size_t)contentLength) { - LOG_INFO("OTA: Successfully written %u bytes to flash", written); + LOG_INFO(TAG, "OTA: Successfully written %u bytes to flash", written); } else { - LOG_ERROR("OTA: Written only %u/%d bytes", written, contentLength); + LOG_ERROR(TAG, "OTA: Written only %u/%d bytes", written, contentLength); setStatus(Status::FAILED, ErrorCode::WRITE_FAILED); return false; } if (Update.end(true)) { // true = set new boot partition - LOG_INFO("OTA: Update complete!"); + LOG_INFO(TAG, "OTA: Update complete!"); if (Update.isFinished()) { setStatus(Status::SUCCESS); - LOG_INFO("OTA: Firmware update successful. Rebooting..."); + LOG_INFO(TAG, "OTA: Firmware update successful. Rebooting..."); // Update version in config _configManager.setFwVersion(String(_availableVersion)); @@ -582,12 +584,12 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { ESP.restart(); return true; } else { - LOG_ERROR("OTA: Update not finished"); + LOG_ERROR(TAG, "OTA: Update not finished"); setStatus(Status::FAILED, ErrorCode::VERIFICATION_FAILED); return false; } } else { - LOG_ERROR("OTA: Update error: %s", Update.errorString()); + LOG_ERROR(TAG, "OTA: Update error: %s", Update.errorString()); setStatus(Status::FAILED, ErrorCode::VERIFICATION_FAILED); return false; } @@ -595,7 +597,7 @@ bool OTAManager::downloadDirectToFlash(const String& url, size_t expectedSize) { bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, size_t expectedSize) { if (!_fileManager) { - LOG_ERROR("FileManager not set!"); + LOG_ERROR(TAG, "FileManager not set!"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; } @@ -615,7 +617,7 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, int httpCode = http.GET(); if (httpCode != HTTP_CODE_OK) { - LOG_ERROR("Download HTTP error code: %d", httpCode); + LOG_ERROR(TAG, "Download HTTP error code: %d", httpCode); setStatus(Status::FAILED, ErrorCode::HTTP_ERROR); http.end(); return false; @@ -624,10 +626,10 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, int contentLength = http.getSize(); // Log HTTP response headers for debugging - LOG_INFO("OTA: HTTP Response Code: %d", httpCode); - LOG_INFO("OTA: Content-Length header: %d bytes", contentLength); + LOG_INFO(TAG, "OTA: HTTP Response Code: %d", httpCode); + LOG_INFO(TAG, "OTA: Content-Length header: %d bytes", contentLength); if (contentLength <= 0) { - LOG_ERROR("Invalid content length"); + LOG_ERROR(TAG, "Invalid content length"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); http.end(); return false; @@ -635,7 +637,7 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // ✅ NEW: Validate file size against metadata if (expectedSize > 0 && (size_t)contentLength != expectedSize) { - LOG_ERROR("OTA: File size mismatch! Expected: %u, Got: %d", expectedSize, contentLength); + LOG_ERROR(TAG, "OTA: File size mismatch! Expected: %u, Got: %d", expectedSize, contentLength); setStatus(Status::FAILED, ErrorCode::SIZE_MISMATCH); http.end(); return false; @@ -643,18 +645,18 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // ✅ NEW: Check available SD card space if (!checkAvailableSpace(contentLength)) { - LOG_ERROR("OTA: Insufficient SD card space for update"); + LOG_ERROR(TAG, "OTA: Insufficient SD card space for update"); setStatus(Status::FAILED, ErrorCode::INSUFFICIENT_SPACE); http.end(); return false; } - LOG_INFO("OTA: Starting download of %d bytes...", contentLength); + LOG_INFO(TAG, "OTA: Starting download of %d bytes...", contentLength); // ═══════════════════════════════════════════════════════════════════════════ // ENTER OTA FREEZE MODE - Pause all non-critical systems to prevent SD contention // ═══════════════════════════════════════════════════════════════════════════ - LOG_INFO("OTA: Entering freeze mode - pausing TimeKeeper and Telemetry"); + LOG_INFO(TAG, "OTA: Entering freeze mode - pausing TimeKeeper and Telemetry"); if (_timeKeeper) { _timeKeeper->pauseClockUpdates(); @@ -665,9 +667,9 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, } // 🔒 ACQUIRE SD CARD MUTEX - Prevents concurrent SD access - LOG_INFO("OTA: Acquiring SD card mutex for safe file operations"); + LOG_INFO(TAG, "OTA: Acquiring SD card mutex for safe file operations"); if (!SDCardMutex::getInstance().lock(10000)) { // 10 second timeout - LOG_ERROR("OTA: Failed to acquire SD card mutex!"); + LOG_ERROR(TAG, "OTA: Failed to acquire SD card mutex!"); if (_timeKeeper) _timeKeeper->resumeClockUpdates(); if (_telemetry) _telemetry->resume(); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); @@ -677,9 +679,9 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // Delete file if it exists, before opening if (SD.exists(tempPath.c_str())) { - LOG_INFO("OTA: Removing existing staged update file"); + LOG_INFO(TAG, "OTA: Removing existing staged update file"); if (!SD.remove(tempPath.c_str())) { - LOG_ERROR("OTA: Failed to remove existing file!"); + LOG_ERROR(TAG, "OTA: Failed to remove existing file!"); } delay(200); // Give SD card time to complete deletion } @@ -687,7 +689,7 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // Open file for writing File file = SD.open(tempPath.c_str(), FILE_WRITE); if (!file) { - LOG_ERROR("Failed to create temporary update file"); + LOG_ERROR(TAG, "Failed to create temporary update file"); // Release mutex and resume systems before returning SDCardMutex::getInstance().unlock(); @@ -699,7 +701,7 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, return false; } - LOG_INFO("OTA: File opened successfully for writing (mutex locked)"); + LOG_INFO(TAG, "OTA: File opened successfully for writing (mutex locked)"); WiFiClient* stream = http.getStreamPtr(); uint8_t buffer[4096]; // ✅ Increased to 4KB for better performance @@ -721,7 +723,7 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // Check if write succeeded if (bytesWritten != bytesRead) { - LOG_ERROR("SD write failed at offset %u (%u/%u bytes written)", written, bytesWritten, bytesRead); + LOG_ERROR(TAG, "SD write failed at offset %u (%u/%u bytes written)", written, bytesWritten, bytesRead); file.close(); SDCardMutex::getInstance().unlock(); http.end(); @@ -741,7 +743,7 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // Log progress every 20% size_t currentPercent = (written * 100) / contentLength; if (currentPercent >= lastLoggedPercent + 20) { - LOG_INFO("OTA: Download progress: %u%% (%u/%u bytes)", + LOG_INFO(TAG, "OTA: Download progress: %u%% (%u/%u bytes)", currentPercent, written, contentLength); lastLoggedPercent = currentPercent; } @@ -770,14 +772,14 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, // 🔓 RELEASE SD CARD MUTEX - Other tasks can now access SD SDCardMutex::getInstance().unlock(); - LOG_INFO("OTA: SD card mutex released"); + LOG_INFO(TAG, "OTA: SD card mutex released"); http.end(); // ═══════════════════════════════════════════════════════════════════════════ // EXIT OTA FREEZE MODE - Resume all paused systems // ═══════════════════════════════════════════════════════════════════════════ - LOG_INFO("OTA: Exiting freeze mode - resuming TimeKeeper and Telemetry"); + LOG_INFO(TAG, "OTA: Exiting freeze mode - resuming TimeKeeper and Telemetry"); if (_timeKeeper) { _timeKeeper->resumeClockUpdates(); @@ -788,26 +790,26 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, } if (written != (size_t)contentLength) { - LOG_ERROR("Download incomplete: %u/%d bytes", written, contentLength); + LOG_ERROR(TAG, "Download incomplete: %u/%d bytes", written, contentLength); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; } - LOG_INFO("Download complete (%u bytes)", written); + LOG_INFO(TAG, "Download complete (%u bytes)", written); // 🔒 Acquire mutex for file verification operations if (!SDCardMutex::getInstance().lock(5000)) { - LOG_ERROR("OTA: Failed to acquire SD mutex for verification"); + LOG_ERROR(TAG, "OTA: Failed to acquire SD mutex for verification"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; } // 🔍 DEBUG: Check actual file size on SD card size_t actualFileSize = _fileManager->getFileSize(tempPath); - LOG_INFO("OTA: File size on SD card: %u bytes (expected: %u)", actualFileSize, written); + LOG_INFO(TAG, "OTA: File size on SD card: %u bytes (expected: %u)", actualFileSize, written); if (actualFileSize != written) { - LOG_ERROR("OTA: FILE SIZE MISMATCH ON SD CARD! Expected %u, got %u", written, actualFileSize); + LOG_ERROR(TAG, "OTA: FILE SIZE MISMATCH ON SD CARD! Expected %u, got %u", written, actualFileSize); SDCardMutex::getInstance().unlock(); setStatus(Status::FAILED, ErrorCode::WRITE_FAILED); return false; @@ -826,20 +828,20 @@ bool OTAManager::downloadToSD(const String& url, const String& expectedChecksum, sprintf(hex, "%02X ", debugBuffer[i]); hexDump += hex; } - LOG_INFO("%s", hexDump.c_str()); + LOG_INFO(TAG, "%s", hexDump.c_str()); } SDCardMutex::getInstance().unlock(); // Release before checksum (checksum will acquire its own) // Verify checksum (verifyChecksum acquires its own mutex) if (!verifyChecksum(tempPath, expectedChecksum)) { - LOG_ERROR("Checksum verification failed after download"); + LOG_ERROR(TAG, "Checksum verification failed after download"); _fileManager->deleteFile(tempPath); setStatus(Status::FAILED, ErrorCode::CHECKSUM_MISMATCH); return false; } - LOG_INFO("Download and checksum verification successful"); + LOG_INFO(TAG, "Download and checksum verification successful"); return true; } @@ -847,18 +849,18 @@ bool OTAManager::verifyChecksum(const String& filePath, const String& expectedCh String calculatedChecksum = calculateSHA256(filePath); if (calculatedChecksum.isEmpty()) { - LOG_ERROR("Failed to calculate checksum"); + LOG_ERROR(TAG, "Failed to calculate checksum"); return false; } bool match = calculatedChecksum.equalsIgnoreCase(expectedChecksum); if (match) { - LOG_INFO("Checksum verification passed"); + LOG_INFO(TAG, "Checksum verification passed"); } else { - LOG_ERROR("Checksum mismatch!"); - LOG_ERROR("Expected: %s", expectedChecksum.c_str()); - LOG_ERROR("Calculated: %s", calculatedChecksum.c_str()); + LOG_ERROR(TAG, "Checksum mismatch!"); + LOG_ERROR(TAG, "Expected: %s", expectedChecksum.c_str()); + LOG_ERROR(TAG, "Calculated: %s", calculatedChecksum.c_str()); } return match; @@ -867,13 +869,13 @@ bool OTAManager::verifyChecksum(const String& filePath, const String& expectedCh String OTAManager::calculateSHA256(const String& filePath) { // 🔒 Acquire SD mutex for file reading if (!SDCardMutex::getInstance().lock(5000)) { - LOG_ERROR("Failed to acquire SD mutex for checksum calculation"); + LOG_ERROR(TAG, "Failed to acquire SD mutex for checksum calculation"); return ""; } File file = SD.open(filePath.c_str()); if (!file) { - LOG_ERROR("Failed to open file for checksum calculation: %s", filePath.c_str()); + LOG_ERROR(TAG, "Failed to open file for checksum calculation: %s", filePath.c_str()); SDCardMutex::getInstance().unlock(); return ""; } @@ -917,7 +919,7 @@ String OTAManager::calculateSHA256(const String& filePath) { bool OTAManager::installFromSD(const String& filePath) { // 🔒 Acquire SD mutex for file size check if (!SDCardMutex::getInstance().lock(5000)) { - LOG_ERROR("Failed to acquire SD mutex for installation"); + LOG_ERROR(TAG, "Failed to acquire SD mutex for installation"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; } @@ -927,30 +929,30 @@ bool OTAManager::installFromSD(const String& filePath) { SDCardMutex::getInstance().unlock(); // Release after size check if (updateSize == 0) { - LOG_ERROR("Empty update file"); + LOG_ERROR(TAG, "Empty update file"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; } - LOG_INFO("Installing firmware from SD (%u bytes)...", updateSize); + LOG_INFO(TAG, "Installing firmware from SD (%u bytes)...", updateSize); setStatus(Status::INSTALLING); if (!Update.begin(updateSize)) { - LOG_ERROR("Not enough space to begin update"); + LOG_ERROR(TAG, "Not enough space to begin update"); setStatus(Status::FAILED, ErrorCode::INSUFFICIENT_SPACE); return false; } // 🔒 Acquire SD mutex for file reading during flash if (!SDCardMutex::getInstance().lock(30000)) { // 30 second timeout for flash operation - LOG_ERROR("Failed to acquire SD mutex for firmware flash"); + LOG_ERROR(TAG, "Failed to acquire SD mutex for firmware flash"); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; } File updateBin = SD.open(filePath.c_str()); if (!updateBin) { - LOG_ERROR("Failed to open update file: %s", filePath.c_str()); + LOG_ERROR(TAG, "Failed to open update file: %s", filePath.c_str()); SDCardMutex::getInstance().unlock(); setStatus(Status::FAILED, ErrorCode::DOWNLOAD_FAILED); return false; @@ -963,18 +965,18 @@ bool OTAManager::installFromSD(const String& filePath) { SDCardMutex::getInstance().unlock(); if (written == updateSize) { - LOG_INFO("Update written successfully (%u bytes)", written); + LOG_INFO(TAG, "Update written successfully (%u bytes)", written); } else { - LOG_ERROR("Written only %u/%u bytes", written, updateSize); + LOG_ERROR(TAG, "Written only %u/%u bytes", written, updateSize); setStatus(Status::FAILED, ErrorCode::WRITE_FAILED); return false; } if (Update.end(true)) { // true = set new boot partition - LOG_INFO("Update finished!"); + LOG_INFO(TAG, "Update finished!"); if (Update.isFinished()) { setStatus(Status::SUCCESS); - LOG_INFO("Update complete. Cleaning up and rebooting..."); + LOG_INFO(TAG, "Update complete. Cleaning up and rebooting..."); // Clean up the update files _fileManager->deleteFile(filePath); @@ -990,9 +992,9 @@ bool OTAManager::installFromSD(const String& filePath) { nvs_erase_key(nvsHandle, "fail_count"); nvs_commit(nvsHandle); nvs_close(nvsHandle); - LOG_INFO("✅ OTA: Firmware validation state cleared - new firmware will be validated"); + LOG_INFO(TAG, "✅ OTA: Firmware validation state cleared - new firmware will be validated"); } else { - LOG_WARNING("⚠️ OTA: Failed to clear validation state: %s", esp_err_to_name(err)); + LOG_WARNING(TAG, "⚠️ OTA: Failed to clear validation state: %s", esp_err_to_name(err)); } delay(1000); @@ -1003,12 +1005,12 @@ bool OTAManager::installFromSD(const String& filePath) { ESP.restart(); return true; } else { - LOG_ERROR("Update not complete"); + LOG_ERROR(TAG, "Update not complete"); setStatus(Status::FAILED, ErrorCode::VERIFICATION_FAILED); return false; } } else { - LOG_ERROR("Update error: %s", Update.errorString()); + LOG_ERROR(TAG, "Update error: %s", Update.errorString()); setStatus(Status::FAILED, ErrorCode::VERIFICATION_FAILED); return false; } @@ -1016,19 +1018,19 @@ bool OTAManager::installFromSD(const String& filePath) { void OTAManager::checkFirmwareUpdateFromSD() { if (!_fileManager) { - LOG_ERROR("FileManager not set!"); + LOG_ERROR(TAG, "FileManager not set!"); return; } if (!_fileManager->fileExists("/firmware/update.bin")) { - LOG_DEBUG("No update.bin found on SD card"); + LOG_DEBUG(TAG, "No update.bin found on SD card"); return; } // Check for checksum file String checksumFile = "/firmware/update.sha256"; if (!_fileManager->fileExists(checksumFile)) { - LOG_WARNING("No checksum file found, proceeding without verification"); + LOG_WARNING(TAG, "No checksum file found, proceeding without verification"); installFromSD("/firmware/update.bin"); return; } @@ -1036,7 +1038,7 @@ void OTAManager::checkFirmwareUpdateFromSD() { // Read expected checksum File checksumFileHandle = SD.open(checksumFile.c_str()); if (!checksumFileHandle) { - LOG_ERROR("Failed to open checksum file"); + LOG_ERROR(TAG, "Failed to open checksum file"); return; } @@ -1046,12 +1048,12 @@ void OTAManager::checkFirmwareUpdateFromSD() { // Verify checksum if (!verifyChecksum("/firmware/update.bin", expectedChecksum)) { - LOG_ERROR("Checksum verification failed, aborting update"); + LOG_ERROR(TAG, "Checksum verification failed, aborting update"); setStatus(Status::FAILED, ErrorCode::CHECKSUM_MISMATCH); return; } - LOG_INFO("Checksum verified, proceeding with update"); + LOG_INFO(TAG, "Checksum verified, proceeding with update"); installFromSD("/firmware/update.bin"); } @@ -1061,7 +1063,7 @@ bool OTAManager::performManualUpdate() { bool OTAManager::performManualUpdate(const String& channel) { if (_status != Status::IDLE) { - LOG_WARNING("OTA update already in progress"); + LOG_WARNING(TAG, "OTA update already in progress"); return false; } @@ -1069,11 +1071,11 @@ bool OTAManager::performManualUpdate(const String& channel) { checkForUpdates(channel); if (!_updateAvailable) { - LOG_WARNING("No update available in %s channel", channel.c_str()); + LOG_WARNING(TAG, "No update available in %s channel", channel.c_str()); return false; } - LOG_INFO("Starting manual OTA update from %s channel (direct-to-flash)...", channel.c_str()); + LOG_INFO(TAG, "Starting manual OTA update from %s channel (direct-to-flash)...", channel.c_str()); setStatus(Status::DOWNLOADING); String firmwareUrl = buildFirmwareUrl(channel); @@ -1088,27 +1090,27 @@ bool OTAManager::performManualUpdate(const String& channel) { bool OTAManager::performCustomUpdate(const String& firmwareUrl, const String& checksum, size_t fileSize, uint16_t version) { if (_status != Status::IDLE) { - LOG_WARNING("OTA update already in progress"); + LOG_WARNING(TAG, "OTA update already in progress"); return false; } // Check if player is active if (isPlayerActive()) { - LOG_ERROR("Cannot perform custom update: Player is active"); + LOG_ERROR(TAG, "Cannot perform custom update: Player is active"); setStatus(Status::FAILED, ErrorCode::PLAYER_ACTIVE); return false; } - LOG_INFO("🔥 Starting CUSTOM firmware update (direct-to-flash)..."); - LOG_INFO(" URL: %s", firmwareUrl.c_str()); - LOG_INFO(" File Size: %u bytes", fileSize); + LOG_INFO(TAG, "🔥 Starting CUSTOM firmware update (direct-to-flash)..."); + LOG_INFO(TAG, " URL: %s", firmwareUrl.c_str()); + LOG_INFO(TAG, " File Size: %u bytes", fileSize); if (!checksum.isEmpty()) { - LOG_INFO(" Checksum: %s (NOTE: ESP32 will validate after flash)", checksum.c_str()); + LOG_INFO(TAG, " Checksum: %s (NOTE: ESP32 will validate after flash)", checksum.c_str()); } if (version > 0) { - LOG_INFO(" Target Version: %u", version); + LOG_INFO(TAG, " Target Version: %u", version); } setStatus(Status::DOWNLOADING); @@ -1121,14 +1123,14 @@ bool OTAManager::performCustomUpdate(const String& firmwareUrl, const String& ch if (version > 0) { _configManager.setFwVersion(String(version)); _configManager.saveDeviceConfig(); - LOG_INFO("✅ Custom firmware version %u saved to NVS", version); + LOG_INFO(TAG, "✅ Custom firmware version %u saved to NVS", version); } else { - LOG_WARNING("⚠️ No version provided - NVS version unchanged"); + LOG_WARNING(TAG, "⚠️ No version provided - NVS version unchanged"); } - LOG_INFO("🚀 Custom firmware installed - device will reboot"); + LOG_INFO(TAG, "🚀 Custom firmware installed - device will reboot"); } else { - LOG_ERROR("❌ Custom firmware installation failed"); + LOG_ERROR(TAG, "❌ Custom firmware installation failed"); } return result; @@ -1140,7 +1142,7 @@ String OTAManager::getHardwareVariant() const { } void OTAManager::setHardwareVariant(const String& variant) { - LOG_WARNING("OTAManager::setHardwareVariant is deprecated. Use ConfigManager::setHardwareVariant instead"); + LOG_WARNING(TAG, "OTAManager::setHardwareVariant is deprecated. Use ConfigManager::setHardwareVariant instead"); } // URL builders for multi-channel architecture @@ -1173,7 +1175,7 @@ bool OTAManager::isPlayerActive() const { // ✅ NEW: Check if SD card has enough free space bool OTAManager::checkAvailableSpace(size_t requiredBytes) const { if (!_fileManager) { - LOG_WARNING("OTA: FileManager not set, cannot check available space"); + LOG_WARNING(TAG, "OTA: FileManager not set, cannot check available space"); return true; // Assume it's okay if we can't check } @@ -1185,18 +1187,18 @@ bool OTAManager::checkAvailableSpace(size_t requiredBytes) const { uint64_t usedBytes = SD.usedBytes(); uint64_t freeBytes = totalBytes - usedBytes; - LOG_INFO("OTA: SD card space - Total: %llu MB, Used: %llu MB, Free: %llu MB", + LOG_INFO(TAG, "OTA: SD card space - Total: %llu MB, Used: %llu MB, Free: %llu MB", totalBytes / (1024 * 1024), usedBytes / (1024 * 1024), freeBytes / (1024 * 1024)); if (freeBytes < requiredWithMargin) { - LOG_ERROR("OTA: Insufficient space! Required: %u bytes (+10%% margin), Available: %llu bytes", + LOG_ERROR(TAG, "OTA: Insufficient space! Required: %u bytes (+10%% margin), Available: %llu bytes", requiredWithMargin, freeBytes); return false; } - LOG_INFO("OTA: Sufficient space available for update"); + LOG_INFO(TAG, "OTA: Sufficient space available for update"); return true; } @@ -1207,45 +1209,45 @@ bool OTAManager::checkAvailableSpace(size_t requiredBytes) const { bool OTAManager::isHealthy() const { // Check if FileManager dependency is set if (!_fileManager) { - LOG_DEBUG("OTAManager: Unhealthy - FileManager not set"); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - FileManager not set"); return false; } // Check if we're not in a failed state if (_status == Status::FAILED) { - LOG_DEBUG("OTAManager: Unhealthy - In failed state"); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - In failed state"); return false; } // Check if ConfigManager has valid configuration String hwVariant = _configManager.getHardwareVariant(); if (hwVariant.isEmpty() || hwVariant == "BellSystems") { - LOG_DEBUG("OTAManager: Unhealthy - Invalid hardware variant: %s", hwVariant.c_str()); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - Invalid hardware variant: %s", hwVariant.c_str()); return false; } String fwVersion = _configManager.getFwVersion(); if (fwVersion.isEmpty() || fwVersion == "0") { - LOG_DEBUG("OTAManager: Unhealthy - Invalid firmware version: %s", fwVersion.c_str()); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - Invalid firmware version: %s", fwVersion.c_str()); return false; } // Check if update servers are available std::vector servers = _configManager.getUpdateServers(); if (servers.empty()) { - LOG_DEBUG("OTAManager: Unhealthy - No update servers configured"); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - No update servers configured"); return false; } // Check if FileManager is healthy (can access SD card) if (!_fileManager->isHealthy()) { - LOG_DEBUG("OTAManager: Unhealthy - FileManager is unhealthy"); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - FileManager is unhealthy"); return false; } // Check if scheduled timer is running if (_scheduledCheckTimer == NULL || xTimerIsTimerActive(_scheduledCheckTimer) == pdFALSE) { - LOG_DEBUG("OTAManager: Unhealthy - Scheduled check timer not running"); + LOG_DEBUG(TAG, "OTAManager: Unhealthy - Scheduled check timer not running"); return false; } @@ -1259,13 +1261,13 @@ bool OTAManager::isHealthy() const { // Static entry point for worker task void OTAManager::otaWorkerTaskFunction(void* parameter) { OTAManager* ota = static_cast(parameter); - LOG_INFO("🔧 OTA Worker task started on Core %d with 8KB stack", xPortGetCoreID()); + LOG_INFO(TAG, "🔧 OTA Worker task started on Core %d with 8KB stack", xPortGetCoreID()); // Run the worker loop ota->otaWorkerLoop(); // Should not reach here - LOG_ERROR("❌ OTA Worker task ended unexpectedly!"); + LOG_ERROR(TAG, "❌ OTA Worker task ended unexpectedly!"); vTaskDelete(NULL); } @@ -1277,18 +1279,18 @@ void OTAManager::otaWorkerLoop() { // Check what type of work to perform switch (_pendingWork) { case OTAWorkType::INITIAL_CHECK: - LOG_INFO("🚀 Worker: Performing initial OTA check"); + LOG_INFO(TAG, "🚀 Worker: Performing initial OTA check"); performInitialCheck(); break; case OTAWorkType::SCHEDULED_CHECK: - LOG_INFO("🕒 Worker: Performing scheduled emergency check"); + LOG_INFO(TAG, "🕒 Worker: Performing scheduled emergency check"); checkForEmergencyUpdates(); break; case OTAWorkType::NONE: default: - LOG_WARNING("⚠️ Worker: Received signal but no work pending"); + LOG_WARNING(TAG, "⚠️ Worker: Received signal but no work pending"); break; } diff --git a/vesper/src/OutputManager/OutputManager.cpp b/vesper/src/OutputManager/OutputManager.cpp index b25e0eb..d7712ea 100644 --- a/vesper/src/OutputManager/OutputManager.cpp +++ b/vesper/src/OutputManager/OutputManager.cpp @@ -5,6 +5,8 @@ */ #include "OutputManager.hpp" + +#define TAG "OutputManager" #include "../ConfigManager/ConfigManager.hpp" #include "../Logging/Logging.hpp" #include @@ -25,7 +27,7 @@ void OutputManager::startDurationTask() { } _activeOutputs.reserve(32); // Support up to 32 virtual outputs xTaskCreatePinnedToCore(durationTask, "OutputDuration", 4096, this, 5, &_durationTaskHandle, 1); - LOG_INFO("⚡ Output Duration Management Task Initialized"); + LOG_INFO(TAG, "⚡ Output Duration Management Task Initialized"); } void OutputManager::stopDurationTask() { @@ -35,13 +37,13 @@ void OutputManager::stopDurationTask() { portENTER_CRITICAL(&_outputMutex); _activeOutputs.clear(); portEXIT_CRITICAL(&_outputMutex); - LOG_INFO("⚡ Output Duration Management Task Stopped"); + LOG_INFO(TAG, "⚡ Output Duration Management Task Stopped"); } } void OutputManager::durationTask(void* parameter) { OutputManager* manager = static_cast(parameter); - LOG_DEBUG("⚡ Output duration management task running on Core %d", xPortGetCoreID()); + LOG_DEBUG(TAG, "⚡ Output duration management task running on Core %d", xPortGetCoreID()); while (true) { manager->processExpiredOutputs(); vTaskDelay(pdMS_TO_TICKS(1)); @@ -58,7 +60,7 @@ void OutputManager::processExpiredOutputs() { _activeOutputs.erase(it); portEXIT_CRITICAL(&_outputMutex); extinguishOutput(outputIndex); - LOG_VERBOSE("⚡ AUTO-EXTINGUISH Output:%d after %dms", outputIndex, duration_micros / 1000); + LOG_VERBOSE(TAG, "⚡ AUTO-EXTINGUISH Output:%d after %dms", outputIndex, duration_micros / 1000); return; } } @@ -67,11 +69,11 @@ void OutputManager::processExpiredOutputs() { uint8_t OutputManager::getPhysicalOutput(uint8_t virtualOutput) const { if (!_configManager) { - LOG_WARNING("⚠️ ConfigManager not available, using direct mapping for virtual output %d", virtualOutput); + LOG_WARNING(TAG, "⚠️ ConfigManager not available, using direct mapping for virtual output %d", virtualOutput); return virtualOutput; } if (!isValidVirtualOutput(virtualOutput)) { - LOG_ERROR("❌ Invalid virtual output %d, using direct mapping", virtualOutput); + LOG_ERROR(TAG, "❌ Invalid virtual output %d, using direct mapping", virtualOutput); return virtualOutput; } @@ -80,14 +82,14 @@ uint8_t OutputManager::getPhysicalOutput(uint8_t virtualOutput) const { // Handle unconfigured bells (255 = disabled) if (bellOutput == 255) { - LOG_WARNING("⚠️ Bell %d not configured (255)", virtualOutput); + LOG_WARNING(TAG, "⚠️ Bell %d not configured (255)", virtualOutput); return 255; // Return invalid to prevent firing } // Physical output is already 0-indexed from config uint8_t physicalOutput = (uint8_t)bellOutput; - LOG_DEBUG("🔗 Bell %d → 0-indexed output %d", + LOG_DEBUG(TAG, "🔗 Bell %d → 0-indexed output %d", virtualOutput, physicalOutput); return physicalOutput; @@ -104,12 +106,12 @@ bool OutputManager::isValidPhysicalOutput(uint8_t physicalOutput) const { void OutputManager::fireClockOutput(uint8_t virtualOutput, uint16_t durationMs) { if (!_initialized) { - LOG_ERROR("❌ OutputManager not initialized for clock output!"); + LOG_ERROR(TAG, "❌ OutputManager not initialized for clock output!"); return; } if (!_configManager) { - LOG_ERROR("❌ ConfigManager not available for clock output mapping!"); + LOG_ERROR(TAG, "❌ ConfigManager not available for clock output mapping!"); return; } @@ -119,24 +121,24 @@ void OutputManager::fireClockOutput(uint8_t virtualOutput, uint16_t durationMs) // Virtual clock output 0 = C1 physicalOutput = _configManager->getClockOutput1(); if (physicalOutput == 255) { - LOG_WARNING("⚠️ Clock C1 not configured (255)"); + LOG_WARNING(TAG, "⚠️ Clock C1 not configured (255)"); return; } } else if (virtualOutput == 1) { // Virtual clock output 1 = C2 physicalOutput = _configManager->getClockOutput2(); if (physicalOutput == 255) { - LOG_WARNING("⚠️ Clock C2 not configured (255)"); + LOG_WARNING(TAG, "⚠️ Clock C2 not configured (255)"); return; } } else { - LOG_ERROR("❌ Invalid virtual clock output: %d (only 0=C1, 1=C2 supported)", virtualOutput); + LOG_ERROR(TAG, "❌ Invalid virtual clock output: %d (only 0=C1, 1=C2 supported)", virtualOutput); return; } // Physical output is already 0-indexed from config if (!isValidPhysicalOutput(physicalOutput)) { - LOG_ERROR("❌ Invalid physical output for clock: %d (max outputs: %d)", + LOG_ERROR(TAG, "❌ Invalid physical output for clock: %d (max outputs: %d)", physicalOutput, getMaxOutputs()); return; } @@ -144,7 +146,7 @@ void OutputManager::fireClockOutput(uint8_t virtualOutput, uint16_t durationMs) // Fire the physical output directly fireOutputForDuration(physicalOutput, durationMs); - LOG_DEBUG("🕐 FIRE Clock Virtual %d (C%d) → 0-indexed output %d for %dms", + LOG_DEBUG(TAG, "🕐 FIRE Clock Virtual %d (C%d) → 0-indexed output %d for %dms", virtualOutput, virtualOutput + 1, physicalOutput, durationMs); } @@ -175,19 +177,19 @@ PCF8574OutputManager::~PCF8574OutputManager() { } bool PCF8574OutputManager::initialize() { - LOG_INFO("🔌 Initializing Multi-Chip PCF857x Output Manager (%d chips)", _chipCount); + LOG_INFO(TAG, "🔌 Initializing Multi-Chip PCF857x Output Manager (%d chips)", _chipCount); delay(100); bool allSuccess = true; for (uint8_t i = 0; i < _chipCount; i++) { if (!initializeChip(i)) { - LOG_ERROR("❌ Failed to initialize chip %d!", i); + LOG_ERROR(TAG, "❌ Failed to initialize chip %d!", i); allSuccess = false; } } if (!allSuccess) { - LOG_ERROR("❌ Not all chips initialized successfully!"); + LOG_ERROR(TAG, "❌ Not all chips initialized successfully!"); return false; } @@ -196,46 +198,46 @@ bool PCF8574OutputManager::initialize() { _allChipsInitialized = true; _initialized = true; // Set base class flag too! - LOG_INFO("✅ Multi-Chip PCF857x Output Manager Initialized (%d total outputs)", _totalOutputs); + LOG_INFO(TAG, "✅ Multi-Chip PCF857x Output Manager Initialized (%d total outputs)", _totalOutputs); generateHardwareTypeString(); if (_configManager) { - LOG_INFO("📋 Virtual Output Configuration Mappings:"); + LOG_INFO(TAG, "📋 Virtual Output Configuration Mappings:"); for (uint8_t i = 0; i < min(16, (int)_totalOutputs); i++) { // Check virtual outputs uint16_t configOutput = _configManager->getBellOutput(i); if (configOutput < _totalOutputs) { VirtualOutputInfo info = getVirtualOutputInfo(configOutput); - LOG_DEBUG(" Bell %d → Virtual Output %d → %s[%d] Pin %d", i, configOutput, info.chipType, info.chipIndex, info.localPin); + LOG_DEBUG(TAG, " Bell %d → Virtual Output %d → %s[%d] Pin %d", i, configOutput, info.chipType, info.chipIndex, info.localPin); } else if (configOutput == 255) { - LOG_DEBUG(" Bell %d → Not configured (255)", i); + LOG_DEBUG(TAG, " Bell %d → Not configured (255)", i); } else { - LOG_WARNING("⚠️ Bell %d mapped to invalid virtual output %d (max: %d)", i, configOutput, _totalOutputs - 1); + LOG_WARNING(TAG, "⚠️ Bell %d mapped to invalid virtual output %d (max: %d)", i, configOutput, _totalOutputs - 1); } } uint8_t c1 = _configManager->getClockOutput1(); uint8_t c2 = _configManager->getClockOutput2(); - LOG_INFO("🕐 Clock Virtual Output Mappings:"); + LOG_INFO(TAG, "🕐 Clock Virtual Output Mappings:"); if (c1 != 255 && c1 < _totalOutputs) { VirtualOutputInfo info = getVirtualOutputInfo(c1); - LOG_DEBUG(" Clock C1 → Virtual Output %d → %s[%d] Pin %d", c1, info.chipType, info.chipIndex, info.localPin); + LOG_DEBUG(TAG, " Clock C1 → Virtual Output %d → %s[%d] Pin %d", c1, info.chipType, info.chipIndex, info.localPin); } else { - LOG_DEBUG(" Clock C1 → Not configured"); + LOG_DEBUG(TAG, " Clock C1 → Not configured"); } if (c2 != 255 && c2 < _totalOutputs) { VirtualOutputInfo info = getVirtualOutputInfo(c2); - LOG_DEBUG(" Clock C2 → Virtual Output %d → %s[%d] Pin %d", c2, info.chipType, info.chipIndex, info.localPin); + LOG_DEBUG(TAG, " Clock C2 → Virtual Output %d → %s[%d] Pin %d", c2, info.chipType, info.chipIndex, info.localPin); } else { - LOG_DEBUG(" Clock C2 → Not configured"); + LOG_DEBUG(TAG, " Clock C2 → Not configured"); } // Show virtual output mapping - LOG_INFO("🔗 Virtual Output Mapping:"); + LOG_INFO(TAG, "🔗 Virtual Output Mapping:"); for (uint8_t i = 0; i < _totalOutputs; i++) { VirtualOutputInfo info = getVirtualOutputInfo(i); - LOG_DEBUG(" Virtual Output %d → %s[%d] Pin %d", i, info.chipType, info.chipIndex, info.localPin); + LOG_DEBUG(TAG, " Virtual Output %d → %s[%d] Pin %d", i, info.chipType, info.chipIndex, info.localPin); } } return true; @@ -243,18 +245,18 @@ bool PCF8574OutputManager::initialize() { void PCF8574OutputManager::fireOutput(uint8_t outputIndex) { if (!_allChipsInitialized) { - LOG_ERROR("❌ PCF857x chips not initialized!"); + LOG_ERROR(TAG, "❌ PCF857x chips not initialized!"); return; } if (!isValidVirtualOutput(outputIndex)) { - LOG_ERROR("❌ Invalid virtual output: %d (max: %d)", outputIndex, _totalOutputs - 1); + LOG_ERROR(TAG, "❌ Invalid virtual output: %d (max: %d)", outputIndex, _totalOutputs - 1); return; } VirtualOutputInfo info = getVirtualOutputInfo(outputIndex); writeOutputToChip(info.chipIndex, info.localPin, false); - LOG_DEBUG("🔥 FIRE Virtual Output %d → %s[%d] Pin %d", outputIndex, info.chipType, info.chipIndex, info.localPin); + LOG_DEBUG(TAG, "🔥 FIRE Virtual Output %d → %s[%d] Pin %d", outputIndex, info.chipType, info.chipIndex, info.localPin); } void PCF8574OutputManager::extinguishOutput(uint8_t outputIndex) { @@ -264,7 +266,7 @@ void PCF8574OutputManager::extinguishOutput(uint8_t outputIndex) { VirtualOutputInfo info = getVirtualOutputInfo(outputIndex); writeOutputToChip(info.chipIndex, info.localPin, true); - LOG_DEBUG("💧 EXTINGUISH Virtual Output %d → %s[%d] Pin %d", outputIndex, info.chipType, info.chipIndex, info.localPin); + LOG_DEBUG(TAG, "💧 EXTINGUISH Virtual Output %d → %s[%d] Pin %d", outputIndex, info.chipType, info.chipIndex, info.localPin); } void PCF8574OutputManager::fireOutputForDuration(uint8_t outputIndex, uint16_t durationMs) { @@ -316,7 +318,7 @@ void PCF8574OutputManager::fireOutputsBatchForDuration(const std::vector= MAX_CHIPS) { - LOG_ERROR("❌ Cannot add more chips - maximum %d chips supported", MAX_CHIPS); + LOG_ERROR(TAG, "❌ Cannot add more chips - maximum %d chips supported", MAX_CHIPS); return false; } @@ -352,7 +354,7 @@ bool PCF8574OutputManager::addChip(uint8_t i2cAddress, ChipType chipType, uint8_ _chipCount++; updateTotalOutputs(); - LOG_INFO("✅ Added chip %d: %s at 0x%02X (%d/%d active outputs)", + LOG_INFO(TAG, "✅ Added chip %d: %s at 0x%02X (%d/%d active outputs)", _chipCount - 1, (chipType == ChipType::PCF8574) ? "PCF8574" : "PCF8575", i2cAddress, @@ -370,7 +372,7 @@ PCF8574OutputManager::VirtualOutputInfo PCF8574OutputManager::getVirtualOutputIn info.chipIndex = 0; info.localPin = 0; info.chipType = (_chipCount > 0 && _chips[0].chipType == ChipType::PCF8574) ? "PCF8574" : "PCF8575"; - LOG_ERROR("❌ Invalid virtual output %d (max: %d)", virtualOutput, _totalOutputs - 1); + LOG_ERROR(TAG, "❌ Invalid virtual output %d (max: %d)", virtualOutput, _totalOutputs - 1); return info; } @@ -390,7 +392,7 @@ PCF8574OutputManager::VirtualOutputInfo PCF8574OutputManager::getVirtualOutputIn info.chipIndex = 0; info.localPin = 0; info.chipType = (_chips[0].chipType == ChipType::PCF8574) ? "PCF8574" : "PCF8575"; - LOG_ERROR("❌ Virtual output %d exceeds available outputs on single chip", virtualOutput); + LOG_ERROR(TAG, "❌ Virtual output %d exceeds available outputs on single chip", virtualOutput); } return info; @@ -398,7 +400,7 @@ PCF8574OutputManager::VirtualOutputInfo PCF8574OutputManager::getVirtualOutputIn void PCF8574OutputManager::setChipActiveOutputs(uint8_t chipIndex, uint8_t activeOutputs) { if (chipIndex >= _chipCount) { - LOG_ERROR("❌ Invalid chip index %d (max: %d)", chipIndex, _chipCount - 1); + LOG_ERROR(TAG, "❌ Invalid chip index %d (max: %d)", chipIndex, _chipCount - 1); return; } @@ -406,12 +408,12 @@ void PCF8574OutputManager::setChipActiveOutputs(uint8_t chipIndex, uint8_t activ _chips[chipIndex].activeOutputs = min(activeOutputs, maxOutputs); updateTotalOutputs(); - LOG_INFO("✅ Updated chip %d active outputs: %d/%d", chipIndex, _chips[chipIndex].activeOutputs, maxOutputs); + LOG_INFO(TAG, "✅ Updated chip %d active outputs: %d/%d", chipIndex, _chips[chipIndex].activeOutputs, maxOutputs); } uint8_t PCF8574OutputManager::getChipActiveOutputs(uint8_t chipIndex) const { if (chipIndex >= _chipCount) { - LOG_ERROR("❌ Invalid chip index %d (max: %d)", chipIndex, _chipCount - 1); + LOG_ERROR(TAG, "❌ Invalid chip index %d (max: %d)", chipIndex, _chipCount - 1); return 0; } return _chips[chipIndex].activeOutputs; @@ -424,7 +426,7 @@ bool PCF8574OutputManager::initializeChip(uint8_t chipIndex) { ChipConfig& chip = _chips[chipIndex]; const char* chipTypeStr = (chip.chipType == ChipType::PCF8574) ? "PCF8574" : "PCF8575"; - LOG_DEBUG("🔌 Initializing %s at address 0x%02X", chipTypeStr, chip.i2cAddress); + LOG_DEBUG(TAG, "🔌 Initializing %s at address 0x%02X", chipTypeStr, chip.i2cAddress); try { if (chip.chipType == ChipType::PCF8574) { @@ -434,7 +436,7 @@ bool PCF8574OutputManager::initializeChip(uint8_t chipIndex) { Adafruit_PCF8574* pcf = static_cast(chip.chipInstance); if (!pcf->begin(chip.i2cAddress, &Wire)) { - LOG_ERROR("❌ Failed to initialize PCF8574 at address 0x%02X", chip.i2cAddress); + LOG_ERROR(TAG, "❌ Failed to initialize PCF8574 at address 0x%02X", chip.i2cAddress); chip.chipInstance = nullptr; return false; } @@ -451,7 +453,7 @@ bool PCF8574OutputManager::initializeChip(uint8_t chipIndex) { Adafruit_PCF8575* pcf = static_cast(chip.chipInstance); if (!pcf->begin(chip.i2cAddress, &Wire)) { - LOG_ERROR("❌ Failed to initialize PCF8575 at address 0x%02X", chip.i2cAddress); + LOG_ERROR(TAG, "❌ Failed to initialize PCF8575 at address 0x%02X", chip.i2cAddress); chip.chipInstance = nullptr; return false; } @@ -464,11 +466,11 @@ bool PCF8574OutputManager::initializeChip(uint8_t chipIndex) { } chip.initialized = true; - LOG_DEBUG("✅ %s at 0x%02X initialized successfully", chipTypeStr, chip.i2cAddress); + LOG_DEBUG(TAG, "✅ %s at 0x%02X initialized successfully", chipTypeStr, chip.i2cAddress); return true; } catch (...) { - LOG_ERROR("❌ Exception during %s initialization at 0x%02X", chipTypeStr, chip.i2cAddress); + LOG_ERROR(TAG, "❌ Exception during %s initialization at 0x%02X", chipTypeStr, chip.i2cAddress); chip.chipInstance = nullptr; return false; } @@ -503,7 +505,7 @@ PCF8574OutputManager::OutputMapping PCF8574OutputManager::getOutputMapping(uint8 // Invalid output - return chip 0, pin 0 as safe fallback mapping.chipIndex = 0; mapping.localPin = 0; - LOG_ERROR("❌ Invalid physical output %d mapped to fallback", physicalOutput); + LOG_ERROR(TAG, "❌ Invalid physical output %d mapped to fallback", physicalOutput); } return mapping; diff --git a/vesper/src/Player/Player.cpp b/vesper/src/Player/Player.cpp index dac5389..e548059 100644 --- a/vesper/src/Player/Player.cpp +++ b/vesper/src/Player/Player.cpp @@ -1,4 +1,6 @@ #include "Player.hpp" + +#define TAG "Player" #include "../Communication/CommunicationRouter/CommunicationRouter.hpp" #include "../BellEngine/BellEngine.hpp" #include "../Telemetry/Telemetry.hpp" @@ -85,7 +87,7 @@ Player::~Player() { } void Player::begin() { - LOG_INFO("Initializing Player with FreeRTOS Timer (saves 4KB RAM!)"); + LOG_INFO(TAG, "Initializing Player with FreeRTOS Timer (saves 4KB RAM!)"); // Create a periodic timer that fires every 500ms _durationTimerHandle = xTimerCreate( @@ -98,22 +100,22 @@ void Player::begin() { if (_durationTimerHandle != NULL) { xTimerStart(_durationTimerHandle, 0); - LOG_INFO("Player initialized successfully with timer"); + LOG_INFO(TAG, "Player initialized successfully with timer"); } else { - LOG_ERROR("Failed to create Player timer!"); + LOG_ERROR(TAG, "Failed to create Player timer!"); } } void Player::play() { if (_melodySteps.empty()) { - LOG_ERROR("Cannot play: No melody loaded"); + LOG_ERROR(TAG, "Cannot play: No melody loaded"); return; } // 🔥 CRITICAL: Interrupt any active clock alerts - user playback has priority! if (_timekeeper) { _timekeeper->interruptActiveAlert(); - LOG_DEBUG("Player: Interrupted any active clock alerts"); + LOG_DEBUG(TAG, "Player: Interrupted any active clock alerts"); } if (_bellEngine) { @@ -125,7 +127,7 @@ void Player::play() { hardStop = false; startTime = segmentStartTime = millis(); setStatus(PlayerStatus::PLAYING); // Update status and notify clients - LOG_DEBUG("Plbck: PLAY"); + LOG_DEBUG(TAG, "Plbck: PLAY"); } void Player::forceStop() { @@ -142,7 +144,7 @@ void Player::forceStop() { _telemetry->saveStrikeCounters(); } - LOG_DEBUG("Plbck: FORCE STOP"); + LOG_DEBUG(TAG, "Plbck: FORCE STOP"); } void Player::stop() { @@ -162,10 +164,10 @@ void Player::stop() { _telemetry->saveStrikeCounters(); } - LOG_DEBUG("Plbck: STOP from PAUSED state"); + LOG_DEBUG(TAG, "Plbck: STOP from PAUSED state"); } else { setStatus(PlayerStatus::STOPPING); - LOG_DEBUG("Plbck: SOFT STOP (waiting for melody to complete)"); + LOG_DEBUG(TAG, "Plbck: SOFT STOP (waiting for melody to complete)"); } // NOTE: The actual "stop" message is now sent in onMelodyLoopCompleted() // when the BellEngine actually finishes the current loop @@ -174,14 +176,14 @@ void Player::stop() { void Player::pause() { isPaused = true; setStatus(PlayerStatus::PAUSED); - LOG_DEBUG("Plbck: PAUSE"); + LOG_DEBUG(TAG, "Plbck: PAUSE"); } void Player::unpause() { isPaused = false; segmentStartTime = millis(); setStatus(PlayerStatus::PLAYING); - LOG_DEBUG("Plbck: RESUME"); + LOG_DEBUG(TAG, "Plbck: RESUME"); } bool Player::command(JsonVariant data) { @@ -189,7 +191,7 @@ bool Player::command(JsonVariant data) { loadMelodyInRAM(); // Removed parameter - use internal storage String action = data["action"]; - LOG_DEBUG("Incoming Command: %s", action.c_str()); + LOG_DEBUG(TAG, "Incoming Command: %s", action.c_str()); // Play or Stop Logic if (action == "play") { @@ -199,7 +201,7 @@ bool Player::command(JsonVariant data) { forceStop(); return true; } else { - LOG_WARNING("Unknown playback action: %s", action.c_str()); + LOG_WARNING(TAG, "Unknown playback action: %s", action.c_str()); return false; } } @@ -245,10 +247,10 @@ void Player::setMelodyAttributes(JsonVariant doc) { } // Print Just for Debugging Purposes - LOG_DEBUG("Set Melody Vars / Name: %s, UID: %s", + LOG_DEBUG(TAG, "Set Melody Vars / Name: %s, UID: %s", name.c_str(), uid.c_str()); - LOG_DEBUG("URL: %s", url.c_str()); - LOG_DEBUG("Speed: %d, Per Segment Duration: %lu, Pause Duration: %lu, Total Duration: %d, Continuous: %s, Infinite: %s", + LOG_DEBUG(TAG, "URL: %s", url.c_str()); + LOG_DEBUG(TAG, "Speed: %d, Per Segment Duration: %lu, Pause Duration: %lu, Total Duration: %d, Continuous: %s, Infinite: %s", speed, segment_duration, pause_duration, total_duration, continuous_loop ? "true" : "false", infinite_play ? "true" : "false"); } @@ -258,13 +260,13 @@ void Player::loadMelodyInRAM() { // 🎵 PRIORITY 1: Check if this is a built-in melody if (BuiltInMelodies::isBuiltInMelody(uidStr)) { - LOG_INFO("Loading built-in melody: %s", uidStr.c_str()); + LOG_INFO(TAG, "Loading built-in melody: %s", uidStr.c_str()); if (BuiltInMelodies::loadBuiltInMelody(uidStr, _melodySteps)) { - LOG_INFO("✅ Built-in melody loaded successfully: %d steps", _melodySteps.size()); + LOG_INFO(TAG, "✅ Built-in melody loaded successfully: %d steps", _melodySteps.size()); return; } else { - LOG_ERROR("Failed to load built-in melody: %s", uidStr.c_str()); + LOG_ERROR(TAG, "Failed to load built-in melody: %s", uidStr.c_str()); return; } } @@ -274,8 +276,8 @@ void Player::loadMelodyInRAM() { File bin_file = SD.open(filePath.c_str(), FILE_READ); if (!bin_file) { - LOG_ERROR("Failed to open file: %s", filePath.c_str()); - LOG_ERROR("Check Servers for the File..."); + LOG_ERROR(TAG, "Failed to open file: %s", filePath.c_str()); + LOG_ERROR(TAG, "Check Servers for the File..."); // Try to download the file using FileManager if (_fileManager) { @@ -284,20 +286,20 @@ void Player::loadMelodyInRAM() { doc["melodys_uid"] = uid; if (!_fileManager->addMelody(doc)) { - LOG_ERROR("Failed to Download File. Check Internet Connection"); + LOG_ERROR(TAG, "Failed to Download File. Check Internet Connection"); return; } else { bin_file = SD.open(filePath.c_str(), FILE_READ); } } else { - LOG_ERROR("FileManager not available for download"); + LOG_ERROR(TAG, "FileManager not available for download"); return; } } size_t fileSize = bin_file.size(); if (fileSize % 2 != 0) { - LOG_ERROR("Invalid file size: %u (not a multiple of 2)", fileSize); + LOG_ERROR(TAG, "Invalid file size: %u (not a multiple of 2)", fileSize); bin_file.close(); return; } @@ -311,7 +313,7 @@ void Player::loadMelodyInRAM() { _melodySteps[i] = (high << 8) | low; } - LOG_INFO("Melody loaded successfully from SD: %d steps", _melodySteps.size()); + LOG_INFO(TAG, "Melody loaded successfully from SD: %d steps", _melodySteps.size()); bin_file.close(); } @@ -341,7 +343,7 @@ bool Player::timeToStop(unsigned long now) { if (isPlaying && !infinite_play) { uint64_t stopTime = startTime + total_duration; if (now >= stopTime) { - LOG_DEBUG("(TimerFunction) Total Run Duration Reached. Soft Stopping."); + LOG_DEBUG(TAG, "(TimerFunction) Total Run Duration Reached. Soft Stopping."); return true; } } @@ -392,7 +394,7 @@ void Player::setStatus(PlayerStatus newStatus) { // 🔥 Use broadcastStatus() to send to BOTH WebSocket AND MQTT clients! _commManager->broadcastStatus(doc); - LOG_DEBUG("Status changed: %d → %d, broadcast sent with runTime: %llu", + LOG_DEBUG(TAG, "Status changed: %d → %d, broadcast sent with runTime: %llu", (int)oldStatus, (int)newStatus, projectedRunTime); } } @@ -402,7 +404,7 @@ void Player::onMelodyLoopCompleted() { if (_status == PlayerStatus::STOPPING) { // We were in soft stop mode, now actually stop setStatus(PlayerStatus::STOPPED); - LOG_DEBUG("Plbck: ACTUAL STOP (melody loop completed)"); + LOG_DEBUG(TAG, "Plbck: ACTUAL STOP (melody loop completed)"); } // Mark segment completion time @@ -413,9 +415,9 @@ void Player::onMelodyLoopCompleted() { bool Player::timeToPause(unsigned long now) { if (isPlaying && continuous_loop) { uint64_t timeToPause = segmentStartTime + segment_duration; - LOG_DEBUG("PTL: %llu // NOW: %lu", timeToPause, now); + LOG_DEBUG(TAG, "PTL: %llu // NOW: %lu", timeToPause, now); if (now >= timeToPause && !isPaused) { - LOG_DEBUG("(TimerFunction) Segment Duration Reached. Pausing."); + LOG_DEBUG(TAG, "(TimerFunction) Segment Duration Reached. Pausing."); pauseTime = now; return true; } @@ -428,7 +430,7 @@ bool Player::timeToResume(unsigned long now) { if (isPaused) { uint64_t timeToResume = segmentCmpltTime + pause_duration; if (now >= timeToResume) { - LOG_DEBUG("(TimerFunction) Pause Duration Reached. Resuming"); + LOG_DEBUG(TAG, "(TimerFunction) Pause Duration Reached. Resuming"); segmentStartTime = now; // Reset segment start time for next cycle return true; } @@ -466,35 +468,35 @@ uint64_t Player::calculateProjectedRunTime() const { bool Player::isHealthy() const { // Check if dependencies are properly set if (!_commManager) { - LOG_DEBUG("Player: Unhealthy - Communication manager not set"); + LOG_DEBUG(TAG, "Player: Unhealthy - Communication manager not set"); return false; } if (!_fileManager) { - LOG_DEBUG("Player: Unhealthy - File manager not set"); + LOG_DEBUG(TAG, "Player: Unhealthy - File manager not set"); return false; } if (!_bellEngine) { - LOG_DEBUG("Player: Unhealthy - BellEngine not set"); + LOG_DEBUG(TAG, "Player: Unhealthy - BellEngine not set"); return false; } // Check if timer is properly created if (_durationTimerHandle == NULL) { - LOG_DEBUG("Player: Unhealthy - Duration timer not created"); + LOG_DEBUG(TAG, "Player: Unhealthy - Duration timer not created"); return false; } // Check if timer is actually running if (xTimerIsTimerActive(_durationTimerHandle) == pdFALSE) { - LOG_DEBUG("Player: Unhealthy - Duration timer not active"); + LOG_DEBUG(TAG, "Player: Unhealthy - Duration timer not active"); return false; } // Check for consistent playback state if (isPlaying && (_status == PlayerStatus::STOPPED)) { - LOG_DEBUG("Player: Unhealthy - Inconsistent playback state"); + LOG_DEBUG(TAG, "Player: Unhealthy - Inconsistent playback state"); return false; } diff --git a/vesper/src/SDCardMutex/SDCardMutex.hpp b/vesper/src/SDCardMutex/SDCardMutex.hpp index dc81d30..559db41 100644 --- a/vesper/src/SDCardMutex/SDCardMutex.hpp +++ b/vesper/src/SDCardMutex/SDCardMutex.hpp @@ -70,18 +70,18 @@ public: */ bool begin() { if (_mutex != NULL) { - LOG_WARNING("SDCardMutex already initialized"); + LOG_WARNING("SDCardMutex", "SDCardMutex already initialized"); return true; } _mutex = xSemaphoreCreateMutex(); if (_mutex == NULL) { - LOG_ERROR("Failed to create SD card mutex!"); + LOG_ERROR("SDCardMutex", "Failed to create SD card mutex!"); return false; } - LOG_INFO("SD card mutex initialized"); + LOG_INFO("SDCardMutex", "SD card mutex initialized"); return true; } @@ -92,7 +92,7 @@ public: */ bool lock(uint32_t timeoutMs = 5000) { if (_mutex == NULL) { - LOG_ERROR("SDCardMutex not initialized!"); + LOG_ERROR("SDCardMutex", "SDCardMutex not initialized!"); return false; } @@ -104,7 +104,7 @@ public: _lockCount++; return true; } else { - LOG_ERROR("SD card mutex timeout after %u ms!", timeoutMs); + LOG_ERROR("SDCardMutex", "SD card mutex timeout after %u ms!", timeoutMs); return false; } } @@ -114,7 +114,7 @@ public: */ void unlock() { if (_mutex == NULL) { - LOG_ERROR("SDCardMutex not initialized!"); + LOG_ERROR("SDCardMutex", "SDCardMutex not initialized!"); return; } @@ -190,7 +190,7 @@ public: : _locked(false) { _locked = SDCardMutex::getInstance().lock(timeoutMs); if (!_locked) { - LOG_ERROR("SDCardLock failed to acquire mutex!"); + LOG_ERROR("SDCardMutex", "SDCardLock failed to acquire mutex!"); } } diff --git a/vesper/src/SettingsWebServer/SettingsWebServer.cpp b/vesper/src/SettingsWebServer/SettingsWebServer.cpp index 1a56004..3e2421f 100644 --- a/vesper/src/SettingsWebServer/SettingsWebServer.cpp +++ b/vesper/src/SettingsWebServer/SettingsWebServer.cpp @@ -5,6 +5,8 @@ */ #include "SettingsWebServer.hpp" + +#define TAG "SettingsWebServer" #include "SettingsPage.h" #include "../ConfigManager/ConfigManager.hpp" #include "../Networking/Networking.hpp" @@ -22,7 +24,7 @@ SettingsWebServer::~SettingsWebServer() { } void SettingsWebServer::begin() { - LOG_INFO("SettingsWebServer - Initializing settings web interface"); + LOG_INFO(TAG, "SettingsWebServer - Initializing settings web interface"); // GET /settings - Main settings page _server.on("/settings", HTTP_GET, @@ -45,14 +47,14 @@ void SettingsWebServer::begin() { } ); - LOG_INFO("SettingsWebServer - Endpoints registered"); - LOG_INFO(" GET /settings - Settings page"); - LOG_INFO(" POST /api/set-mode - Set network mode"); - LOG_INFO(" POST /api/reboot - Reboot device"); + LOG_INFO(TAG, "SettingsWebServer - Endpoints registered"); + LOG_INFO(TAG, " GET /settings - Settings page"); + LOG_INFO(TAG, " POST /api/set-mode - Set network mode"); + LOG_INFO(TAG, " POST /api/reboot - Reboot device"); } void SettingsWebServer::handleSettingsPage(AsyncWebServerRequest* request) { - LOG_DEBUG("SettingsWebServer - Settings page requested"); + LOG_DEBUG(TAG, "SettingsWebServer - Settings page requested"); String html = generateSettingsHTML(); request->send(200, "text/html", html); } @@ -64,13 +66,13 @@ void SettingsWebServer::handleSetMode(AsyncWebServerRequest* request) { } String mode = request->getParam("mode", true)->value(); - LOG_INFO("SettingsWebServer - Mode change requested: %s", mode.c_str()); + LOG_INFO(TAG, "SettingsWebServer - Mode change requested: %s", mode.c_str()); if (mode == "ap") { // Switch to permanent AP mode _configManager.setPermanentAPMode(true); _configManager.saveNetworkConfig(); - LOG_INFO("✅ Permanent AP mode enabled - will activate on reboot"); + LOG_INFO(TAG, "✅ Permanent AP mode enabled - will activate on reboot"); request->send(200, "text/plain", "AP mode enabled. Device will reboot in 3 seconds."); // Reboot after 3 seconds @@ -81,7 +83,7 @@ void SettingsWebServer::handleSetMode(AsyncWebServerRequest* request) { // Switch to station mode (router mode) _configManager.setPermanentAPMode(false); _configManager.saveNetworkConfig(); - LOG_INFO("✅ Station mode enabled - will activate on reboot"); + LOG_INFO(TAG, "✅ Station mode enabled - will activate on reboot"); request->send(200, "text/plain", "Station mode enabled. Device will reboot in 3 seconds."); // Reboot after 3 seconds @@ -94,7 +96,7 @@ void SettingsWebServer::handleSetMode(AsyncWebServerRequest* request) { } void SettingsWebServer::handleReboot(AsyncWebServerRequest* request) { - LOG_INFO("SettingsWebServer - Reboot requested"); + LOG_INFO(TAG, "SettingsWebServer - Reboot requested"); request->send(200, "text/plain", "Rebooting device in 2 seconds..."); delay(2000); diff --git a/vesper/src/Telemetry/Telemetry.cpp b/vesper/src/Telemetry/Telemetry.cpp index 9df1558..df6576c 100644 --- a/vesper/src/Telemetry/Telemetry.cpp +++ b/vesper/src/Telemetry/Telemetry.cpp @@ -1,4 +1,6 @@ #include "Telemetry.hpp" + +#define TAG "Telemetry" #include void Telemetry::begin() { @@ -17,27 +19,27 @@ void Telemetry::begin() { // Create the telemetry task xTaskCreatePinnedToCore(telemetryTask, "TelemetryTask", 4096, this, 2, &telemetryTaskHandle, 1); - LOG_INFO("Telemetry initialized"); + LOG_INFO(TAG, "Telemetry initialized"); } void Telemetry::setPlayerReference(bool* isPlayingPtr) { playerIsPlayingPtr = isPlayingPtr; - LOG_DEBUG("Player reference set"); + LOG_DEBUG(TAG, "Player reference set"); } void Telemetry::setFileManager(FileManager* fm) { fileManager = fm; - LOG_DEBUG("FileManager reference set"); + LOG_DEBUG(TAG, "FileManager reference set"); } void Telemetry::setForceStopCallback(void (*callback)()) { forceStopCallback = callback; - LOG_DEBUG("Force stop callback set"); + LOG_DEBUG(TAG, "Force stop callback set"); } void Telemetry::recordBellStrike(uint8_t bellIndex) { if (bellIndex >= 16) { - LOG_ERROR("Invalid bell index: %d", bellIndex); + LOG_ERROR(TAG, "Invalid bell index: %d", bellIndex); return; } @@ -52,7 +54,7 @@ void Telemetry::recordBellStrike(uint8_t bellIndex) { uint32_t Telemetry::getStrikeCount(uint8_t bellIndex) { if (bellIndex >= 16) { - LOG_ERROR("Invalid bell index: %d", bellIndex); + LOG_ERROR(TAG, "Invalid bell index: %d", bellIndex); return 0; } return strikeCounters[bellIndex]; @@ -65,12 +67,12 @@ void Telemetry::resetStrikeCounters() { } portEXIT_CRITICAL(&telemetrySpinlock); - LOG_WARNING("Strike counters reset by user"); + LOG_WARNING(TAG, "Strike counters reset by user"); } uint16_t Telemetry::getBellLoad(uint8_t bellIndex) { if (bellIndex >= 16) { - LOG_ERROR("Invalid bell index: %d", bellIndex); + LOG_ERROR(TAG, "Invalid bell index: %d", bellIndex); return 0; } return bellLoad[bellIndex]; @@ -78,17 +80,17 @@ uint16_t Telemetry::getBellLoad(uint8_t bellIndex) { void Telemetry::setBellMaxLoad(uint8_t bellIndex, uint16_t maxLoad) { if (bellIndex >= 16) { - LOG_ERROR("Invalid bell index: %d", bellIndex); + LOG_ERROR(TAG, "Invalid bell index: %d", bellIndex); return; } bellMaxLoad[bellIndex] = maxLoad; - LOG_INFO("Bell %d max load set to %d", bellIndex, maxLoad); + LOG_INFO(TAG, "Bell %d max load set to %d", bellIndex, maxLoad); } bool Telemetry::isOverloaded(uint8_t bellIndex) { if (bellIndex >= 16) { - LOG_ERROR("Invalid bell index: %d", bellIndex); + LOG_ERROR(TAG, "Invalid bell index: %d", bellIndex); return false; } return bellLoad[bellIndex] > bellMaxLoad[bellIndex]; @@ -100,12 +102,12 @@ bool Telemetry::isCoolingActive() { void Telemetry::logTemperature(float temperature) { // Future implementation for temperature logging - LOG_INFO("Temperature: %.2f°C", temperature); + LOG_INFO(TAG, "Temperature: %.2f°C", temperature); } void Telemetry::logVibration(float vibration) { // Future implementation for vibration logging - LOG_INFO("Vibration: %.2f", vibration); + LOG_INFO(TAG, "Vibration: %.2f", vibration); } void Telemetry::checkBellLoads() { @@ -132,7 +134,7 @@ void Telemetry::checkBellLoads() { // Critical overload - protection kicks in if (bellLoad[i] > bellMaxLoad[i]) { - LOG_ERROR("Bell %d OVERLOADED! load=%d max=%d", + LOG_ERROR(TAG, "Bell %d OVERLOADED! load=%d max=%d", i, bellLoad[i], bellMaxLoad[i]); criticalBells.push_back(i); @@ -141,7 +143,7 @@ void Telemetry::checkBellLoads() { } else if (bellLoad[i] > criticalThreshold) { // Critical warning - approaching overload - LOG_WARNING("Bell %d approaching overload! load=%d (critical threshold=%d)", + LOG_WARNING(TAG, "Bell %d approaching overload! load=%d (critical threshold=%d)", i, bellLoad[i], criticalThreshold); criticalBells.push_back(i); @@ -149,7 +151,7 @@ void Telemetry::checkBellLoads() { } else if (bellLoad[i] > warningThreshold) { // Warning - moderate load - LOG_INFO("Bell %d moderate load warning! load=%d (warning threshold=%d)", + LOG_INFO(TAG, "Bell %d moderate load warning! load=%d (warning threshold=%d)", i, bellLoad[i], warningThreshold); warningBells.push_back(i); @@ -169,7 +171,7 @@ void Telemetry::checkBellLoads() { void Telemetry::telemetryTask(void* parameter) { Telemetry* telemetry = static_cast(parameter); - LOG_INFO("Telemetry task started"); + LOG_INFO(TAG, "Telemetry task started"); while(1) { // Skip processing if paused (OTA freeze mode) @@ -193,7 +195,7 @@ void Telemetry::telemetryTask(void* parameter) { void Telemetry::saveStrikeCounters() { if (!fileManager) { - LOG_WARNING("Cannot save strike counters: FileManager not set"); + LOG_WARNING(TAG, "Cannot save strike counters: FileManager not set"); return; } @@ -208,28 +210,28 @@ void Telemetry::saveStrikeCounters() { portEXIT_CRITICAL(&telemetrySpinlock); if (fileManager->writeJsonFile("/telemetry_data.json", doc)) { - LOG_INFO("Strike counters saved to SD card"); + LOG_INFO(TAG, "Strike counters saved to SD card"); } else { - LOG_ERROR("Failed to save strike counters to SD card"); + LOG_ERROR(TAG, "Failed to save strike counters to SD card"); } } void Telemetry::loadStrikeCounters() { if (!fileManager) { - LOG_WARNING("Cannot load strike counters: FileManager not set"); + LOG_WARNING(TAG, "Cannot load strike counters: FileManager not set"); return; } StaticJsonDocument<512> doc; if (!fileManager->readJsonFile("/telemetry_data.json", doc)) { - LOG_INFO("No previous strike counter data found, starting fresh"); + LOG_INFO(TAG, "No previous strike counter data found, starting fresh"); return; } JsonArray counters = doc["strikeCounters"]; if (counters.isNull()) { - LOG_WARNING("Invalid telemetry data format"); + LOG_WARNING(TAG, "Invalid telemetry data format"); return; } @@ -240,7 +242,7 @@ void Telemetry::loadStrikeCounters() { } portEXIT_CRITICAL(&telemetrySpinlock); - LOG_INFO("Strike counters loaded from SD card"); + LOG_INFO(TAG, "Strike counters loaded from SD card"); } // ════════════════════════════════════════════════════════════════════════════ @@ -250,20 +252,20 @@ void Telemetry::loadStrikeCounters() { bool Telemetry::isHealthy() const { // Check if telemetry task is created and running if (telemetryTaskHandle == NULL) { - LOG_DEBUG("Telemetry: Unhealthy - Task not created"); + LOG_DEBUG(TAG, "Telemetry: Unhealthy - Task not created"); return false; } // Check if task is still alive eTaskState taskState = eTaskGetState(telemetryTaskHandle); if (taskState == eDeleted || taskState == eInvalid) { - LOG_DEBUG("Telemetry: Unhealthy - Task deleted or invalid"); + LOG_DEBUG(TAG, "Telemetry: Unhealthy - Task deleted or invalid"); return false; } // Check if player reference is set if (playerIsPlayingPtr == nullptr) { - LOG_DEBUG("Telemetry: Unhealthy - Player reference not set"); + LOG_DEBUG(TAG, "Telemetry: Unhealthy - Player reference not set"); return false; } @@ -277,7 +279,7 @@ bool Telemetry::isHealthy() const { } if (hasCriticalOverload) { - LOG_DEBUG("Telemetry: Unhealthy - Critical bell overload detected"); + LOG_DEBUG(TAG, "Telemetry: Unhealthy - Critical bell overload detected"); return false; } diff --git a/vesper/src/TimeKeeper/TimeKeeper.cpp b/vesper/src/TimeKeeper/TimeKeeper.cpp index 9f0b4ab..82760ef 100644 --- a/vesper/src/TimeKeeper/TimeKeeper.cpp +++ b/vesper/src/TimeKeeper/TimeKeeper.cpp @@ -1,4 +1,6 @@ #include "TimeKeeper.hpp" + +#define TAG "TimeKeeper" #include "../OutputManager/OutputManager.hpp" #include "../ConfigManager/ConfigManager.hpp" #include "../Networking/Networking.hpp" @@ -7,18 +9,18 @@ #include void Timekeeper::begin() { - LOG_INFO("Timekeeper initialized - clock outputs managed by ConfigManager"); + LOG_INFO(TAG, "Timekeeper initialized - clock outputs managed by ConfigManager"); // Initialize RTC if (!rtc.begin()) { - LOG_ERROR("Couldn't find RTC"); + LOG_ERROR(TAG, "Couldn't find RTC"); // Continue anyway, but log the error } else { - LOG_INFO("RTC initialized successfully"); + LOG_INFO(TAG, "RTC initialized successfully"); // Check if RTC lost power if (!rtc.isrunning()) { - LOG_WARNING("RTC is NOT running! Setting time..."); + LOG_WARNING(TAG, "RTC is NOT running! Setting time..."); // Set to compile time as fallback rtc.adjust(DateTime(F(__DATE__), F(__TIME__))); } @@ -30,32 +32,32 @@ void Timekeeper::begin() { // Create SINGLE consolidated task (saves 8KB RAM!) xTaskCreatePinnedToCore(mainTimekeeperTask, "TimeKeeper", 4096, this, 2, &mainTaskHandle, 1); - LOG_INFO("TimeKeeper initialized with SIMPLE sync approach (like your Arduino code)"); + LOG_INFO(TAG, "TimeKeeper initialized with SIMPLE sync approach (like your Arduino code)"); } void Timekeeper::setOutputManager(OutputManager* outputManager) { _outputManager = outputManager; - LOG_INFO("Timekeeper connected to OutputManager - CLEAN ARCHITECTURE!"); + LOG_INFO(TAG, "Timekeeper connected to OutputManager - CLEAN ARCHITECTURE!"); } void Timekeeper::setConfigManager(ConfigManager* configManager) { _configManager = configManager; - LOG_INFO("Timekeeper connected to ConfigManager"); + LOG_INFO(TAG, "Timekeeper connected to ConfigManager"); } void Timekeeper::setNetworking(Networking* networking) { _networking = networking; - LOG_INFO("Timekeeper connected to Networking"); + LOG_INFO(TAG, "Timekeeper connected to Networking"); } void Timekeeper::setPlayer(Player* player) { _player = player; - LOG_INFO("Timekeeper connected to Player for playback coordination"); + LOG_INFO(TAG, "Timekeeper connected to Player for playback coordination"); } void Timekeeper::interruptActiveAlert() { if (alertInProgress.load()) { - LOG_INFO("⚡ ALERT INTERRUPTED by user playback - marking as complete"); + LOG_INFO(TAG, "⚡ ALERT INTERRUPTED by user playback - marking as complete"); alertInProgress.store(false); // Alert will stop naturally on next check in fireAlertBell loop } @@ -63,26 +65,26 @@ void Timekeeper::interruptActiveAlert() { void Timekeeper::setRelayWriteFunction(void (*func)(int, int)) { relayWriteFunc = func; - LOG_WARNING("Using LEGACY relay function - consider upgrading to OutputManager"); + LOG_WARNING(TAG, "Using LEGACY relay function - consider upgrading to OutputManager"); } void Timekeeper::setClockOutputs(int relay1, int relay2) { - LOG_WARNING("⚠️ setClockOutputs() is DEPRECATED! Use ConfigManager.setClockOutput1/2() instead"); - LOG_WARNING("⚠️ Clock outputs should be configured via MQTT/WebSocket commands"); + LOG_WARNING(TAG, "⚠️ setClockOutputs() is DEPRECATED! Use ConfigManager.setClockOutput1/2() instead"); + LOG_WARNING(TAG, "⚠️ Clock outputs should be configured via MQTT/WebSocket commands"); // For backward compatibility, still set the config if ConfigManager is available if (_configManager) { _configManager->setClockOutput1(relay1); _configManager->setClockOutput2(relay2); - LOG_INFO("Clock outputs updated via legacy method: C1=%d, C2=%d", relay1, relay2); + LOG_INFO(TAG, "Clock outputs updated via legacy method: C1=%d, C2=%d", relay1, relay2); } else { - LOG_ERROR("ConfigManager not available - cannot set clock outputs"); + LOG_ERROR(TAG, "ConfigManager not available - cannot set clock outputs"); } } void Timekeeper::setTime(unsigned long timestamp) { if (!rtc.begin()) { - LOG_ERROR("RTC not available - cannot set time"); + LOG_ERROR(TAG, "RTC not available - cannot set time"); return; } @@ -99,7 +101,7 @@ void Timekeeper::setTime(unsigned long timestamp) { // Set the RTC with local time rtc.adjust(newTime); - LOG_INFO("RTC time set to LOCAL: %04d-%02d-%02d %02d:%02d:%02d (UTC timestamp: %lu + %ld offset = %lu)", + LOG_INFO(TAG, "RTC time set to LOCAL: %04d-%02d-%02d %02d:%02d:%02d (UTC timestamp: %lu + %ld offset = %lu)", newTime.year(), newTime.month(), newTime.day(), newTime.hour(), newTime.minute(), newTime.second(), timestamp, totalOffset, localTimestamp); @@ -110,7 +112,7 @@ void Timekeeper::setTime(unsigned long timestamp) { void Timekeeper::setTimeWithLocalTimestamp(unsigned long localTimestamp) { if (!rtc.begin()) { - LOG_ERROR("RTC not available - cannot set time"); + LOG_ERROR(TAG, "RTC not available - cannot set time"); return; } @@ -120,7 +122,7 @@ void Timekeeper::setTimeWithLocalTimestamp(unsigned long localTimestamp) { // Set the RTC with local time rtc.adjust(newTime); - LOG_INFO("RTC time set to LOCAL: %04d-%02d-%02d %02d:%02d:%02d (local timestamp: %lu)", + LOG_INFO(TAG, "RTC time set to LOCAL: %04d-%02d-%02d %02d:%02d:%02d (local timestamp: %lu)", newTime.year(), newTime.month(), newTime.day(), newTime.hour(), newTime.minute(), newTime.second(), localTimestamp); @@ -131,14 +133,14 @@ void Timekeeper::setTimeWithLocalTimestamp(unsigned long localTimestamp) { unsigned long Timekeeper::getTime() { if (!rtc.isrunning()) { - LOG_ERROR("RTC not running - cannot get time"); + LOG_ERROR(TAG, "RTC not running - cannot get time"); return 0; } DateTime now = rtc.now(); unsigned long timestamp = now.unixtime(); - LOG_DEBUG("Current RTC time: %04d-%02d-%02d %02d:%02d:%02d (timestamp: %lu)", + LOG_DEBUG(TAG, "Current RTC time: %04d-%02d-%02d %02d:%02d:%02d (timestamp: %lu)", now.year(), now.month(), now.day(), now.hour(), now.minute(), now.second(), timestamp); @@ -149,16 +151,16 @@ unsigned long Timekeeper::getTime() { void Timekeeper::syncTimeWithNTP() { // Check if we have network connection and required dependencies if (!_networking || !_configManager) { - LOG_WARNING("Cannot sync time: Networking or ConfigManager not set - using RTC time"); + LOG_WARNING(TAG, "Cannot sync time: Networking or ConfigManager not set - using RTC time"); return; } if (!_networking->isConnected()) { - LOG_INFO("No network connection - skipping NTP sync, using RTC time"); + LOG_INFO(TAG, "No network connection - skipping NTP sync, using RTC time"); return; } - LOG_INFO("⏰ Starting non-blocking NTP sync..."); + LOG_INFO(TAG, "⏰ Starting non-blocking NTP sync..."); // Get config from ConfigManager auto& timeConfig = _configManager->getTimeConfig(); @@ -173,7 +175,7 @@ void Timekeeper::syncTimeWithNTP() { rtc.adjust(DateTime(timeInfo.tm_year + 1900, timeInfo.tm_mon + 1, timeInfo.tm_mday, timeInfo.tm_hour, timeInfo.tm_min, timeInfo.tm_sec)); - LOG_INFO("✅ NTP sync successful: %04d-%02d-%02d %02d:%02d:%02d", + LOG_INFO(TAG, "✅ NTP sync successful: %04d-%02d-%02d %02d:%02d:%02d", timeInfo.tm_year + 1900, timeInfo.tm_mon + 1, timeInfo.tm_mday, timeInfo.tm_hour, timeInfo.tm_min, timeInfo.tm_sec); @@ -181,7 +183,7 @@ void Timekeeper::syncTimeWithNTP() { loadTodaysEvents(); } else { // No internet or NTP server unreachable - this is NORMAL for local networks - LOG_INFO("⚠️ NTP sync skipped (no internet) - using RTC time. This is normal for local networks."); + LOG_INFO(TAG, "⚠️ NTP sync skipped (no internet) - using RTC time. This is normal for local networks."); } } @@ -191,7 +193,7 @@ void Timekeeper::syncTimeWithNTP() { void Timekeeper::mainTimekeeperTask(void* parameter) { Timekeeper* keeper = static_cast(parameter); - LOG_INFO("🕒 SIMPLE TimeKeeper task started - based on your Arduino code approach"); + LOG_INFO(TAG, "🕒 SIMPLE TimeKeeper task started - based on your Arduino code approach"); unsigned long lastRtcCheck = 0; unsigned long lastScheduleCheck = 0; @@ -223,19 +225,19 @@ void Timekeeper::mainTimekeeperTask(void* parameter) { if (keeper->rtc.isrunning()) { // Check for midnight - reload events for new day if (rtcNow.hour() == 0 && rtcNow.minute() == 0 && rtcNow.second() < 10) { - LOG_INFO("🌙 Midnight detected - reloading events"); + LOG_INFO(TAG, "🌙 Midnight detected - reloading events"); keeper->loadTodaysEvents(); keeper->loadNextDayEvents(); } // Hourly maintenance if (rtcNow.minute() == 0 && rtcNow.second() < 10) { - LOG_DEBUG("🕐 Hourly check at %02d:00", rtcNow.hour()); + LOG_DEBUG(TAG, "🕐 Hourly check at %02d:00", rtcNow.hour()); } } else { static uint8_t rtcWarningCounter = 0; if (rtcWarningCounter++ % 6 == 0) { // Log every minute - LOG_WARNING("⚠️ RTC not running!"); + LOG_WARNING(TAG, "⚠️ RTC not running!"); } } lastRtcCheck = now; @@ -274,19 +276,19 @@ void Timekeeper::checkAndSyncPhysicalClock() { // Calculate time difference (your exact logic!) int16_t timeDifference = (realHour * 60 + realMinute) - (physicalHour * 60 + physicalMinute); - LOG_VERBOSE("⏰ CHECK: Real time %02d:%02d vs Physical %02d:%02d - DIFF: %d mins", + LOG_VERBOSE(TAG, "⏰ CHECK: Real time %02d:%02d vs Physical %02d:%02d - DIFF: %d mins", realHour, realMinute, physicalHour, physicalMinute, timeDifference); // Handle 12-hour rollover (if negative, add 12 hours) if (timeDifference < 0) { timeDifference += 12 * 60; // Add 12 hours to handle rollover - LOG_VERBOSE("⏰ DIFF: Adjusted for rollover, new difference %d minutes", timeDifference); + LOG_VERBOSE(TAG, "⏰ DIFF: Adjusted for rollover, new difference %d minutes", timeDifference); } // If there's a difference, advance the clock by one minute (your runMotor equivalent) if (timeDifference >= 1) { advancePhysicalClockOneMinute(); - LOG_DEBUG("⏰ SYNC: Advanced physical clock by 1 minute to %02d:%02d (real: %02d:%02d, diff: %lu mins)", + LOG_DEBUG(TAG, "⏰ SYNC: Advanced physical clock by 1 minute to %02d:%02d (real: %02d:%02d, diff: %lu mins)", _configManager->getPhysicalClockHour(), _configManager->getPhysicalClockMinute(), realHour, realMinute, timeDifference); } @@ -302,7 +304,7 @@ void Timekeeper::advancePhysicalClockOneMinute() { bool useC1 = _configManager->getNextOutputIsC1(); uint8_t outputToFire = useC1 ? (clockConfig.c1output - 1) : (clockConfig.c2output - 1); - LOG_DEBUG("🔥 ADVANCE: Firing %s (output %d) for %dms", + LOG_DEBUG(TAG, "🔥 ADVANCE: Firing %s (output %d) for %dms", useC1 ? "C1" : "C2", outputToFire + 1, clockConfig.pulseDuration); _outputManager->fireOutputForDuration(outputToFire, clockConfig.pulseDuration); @@ -330,7 +332,7 @@ void Timekeeper::updatePhysicalClockTime() { _configManager->setLastSyncTime(millis() / 1000); _configManager->saveClockState(); - LOG_DEBUG("📅 STATE: Physical clock advanced to %d:%02d", currentHour, currentMinute); + LOG_DEBUG(TAG, "📅 STATE: Physical clock advanced to %d:%02d", currentHour, currentMinute); } @@ -345,7 +347,7 @@ void Timekeeper::loadTodaysEvents() { // Get current date/time from RTC DateTime now = rtc.now(); if (!rtc.isrunning()) { - LOG_ERROR("RTC not running - cannot load events"); + LOG_ERROR(TAG, "RTC not running - cannot load events"); return; } @@ -354,13 +356,13 @@ void Timekeeper::loadTodaysEvents() { int currentDay = now.day(); int currentDayOfWeek = now.dayOfTheWeek(); // 0=Sunday, 1=Monday, etc. - LOG_INFO("Loading events for: %04d-%02d-%02d (day %d)", + LOG_INFO(TAG, "Loading events for: %04d-%02d-%02d (day %d)", currentYear, currentMonth, currentDay, currentDayOfWeek); // Open and parse events file File file = SD.open("/events/events.json"); if (!file) { - LOG_ERROR("Failed to open events.json"); + LOG_ERROR(TAG, "Failed to open events.json"); return; } @@ -372,7 +374,7 @@ void Timekeeper::loadTodaysEvents() { file.close(); if (error) { - LOG_ERROR("JSON parsing failed: %s", error.c_str()); + LOG_ERROR(TAG, "JSON parsing failed: %s", error.c_str()); return; } @@ -426,7 +428,7 @@ void Timekeeper::loadTodaysEvents() { // Sort events by time sortEventsByTime(); - LOG_INFO("Loaded %d events for today", eventsLoaded); + LOG_INFO(TAG, "Loaded %d events for today", eventsLoaded); } bool Timekeeper::isSameDate(String eventDateTime, int year, int month, int day) { @@ -460,7 +462,7 @@ void Timekeeper::addToTodaysSchedule(JsonObject event) { todaysEvents.push_back(schedEvent); - LOG_DEBUG("Added event '%s' at %s", + LOG_DEBUG(TAG, "Added event '%s' at %s", event["name"].as().c_str(), schedEvent.timeStr.c_str()); } @@ -510,7 +512,7 @@ void Timekeeper::checkScheduledEvents() { void Timekeeper::triggerEvent(ScheduledEvent& event) { JsonObject eventData = event.eventData; - LOG_INFO("TRIGGERING EVENT: %s at %s", + LOG_INFO(TAG, "TRIGGERING EVENT: %s at %s", eventData["name"].as().c_str(), event.timeStr.c_str()); @@ -523,7 +525,7 @@ void Timekeeper::triggerEvent(ScheduledEvent& event) { String melodyUID = melody["uid"].as(); String melodyName = melody["name"].as(); - LOG_INFO("Playing melody: %s (UID: %s)", + LOG_INFO(TAG, "Playing melody: %s (UID: %s)", melodyName.c_str(), melodyUID.c_str()); // TODO: Add your melody trigger code here @@ -533,7 +535,7 @@ void Timekeeper::triggerEvent(ScheduledEvent& event) { void Timekeeper::loadNextDayEvents() { // This function would load tomorrow's events for smooth midnight transition // Implementation similar to loadTodaysEvents() but for tomorrow's date - LOG_DEBUG("Pre-loading tomorrow's events..."); + LOG_DEBUG(TAG, "Pre-loading tomorrow's events..."); // TODO: Implement if needed for smoother transitions } @@ -567,7 +569,7 @@ void Timekeeper::checkClockAlerts() { lastMinute = currentMinute; // Mark quarter-hour as processed } - LOG_DEBUG("⏭️ SKIPPING clock alert - Player is busy (playing/paused)"); + LOG_DEBUG(TAG, "⏭️ SKIPPING clock alert - Player is busy (playing/paused)"); return; } @@ -605,7 +607,7 @@ void Timekeeper::checkClockAlerts() { // 🕕 HALF-HOUR ALERTS (at xx:30) if (currentMinute == 30 && lastMinute != 30) { if (clockConfig.halfBell != 255) { // 255 = disabled - LOG_INFO("🕕 Half-hour alert at %02d:30", currentHour); + LOG_INFO(TAG, "🕕 Half-hour alert at %02d:30", currentHour); fireAlertBell(clockConfig.halfBell, 1); } lastMinute = 30; @@ -614,7 +616,7 @@ void Timekeeper::checkClockAlerts() { // 🕒 QUARTER-HOUR ALERTS (at xx:15 and xx:45) if ((currentMinute == 15 || currentMinute == 45) && lastMinute != currentMinute) { if (clockConfig.quarterBell != 255) { // 255 = disabled - LOG_INFO("🕒 Quarter-hour alert at %02d:%02d", currentHour, currentMinute); + LOG_INFO(TAG, "🕒 Quarter-hour alert at %02d:%02d", currentHour, currentMinute); fireAlertBell(clockConfig.quarterBell, 1); } lastMinute = currentMinute; @@ -638,7 +640,7 @@ void Timekeeper::triggerHourlyAlert(int hour) { if (clockConfig.alertType == "SINGLE") { // Single ding for any hour - LOG_INFO("🕐 Hourly alert (SINGLE) at %02d:00", hour); + LOG_INFO(TAG, "🕐 Hourly alert (SINGLE) at %02d:00", hour); fireAlertBell(clockConfig.hourBell, 1); } else if (clockConfig.alertType == "HOURS") { @@ -647,7 +649,7 @@ void Timekeeper::triggerHourlyAlert(int hour) { if (bellCount == 0) bellCount = 12; // Midnight = 12 bells if (bellCount > 12) bellCount = bellCount - 12; // 24h to 12h conversion - LOG_INFO("🕐 Hourly alert (HOURS) at %02d:00 - %d rings", hour, bellCount); + LOG_INFO(TAG, "🕐 Hourly alert (HOURS) at %02d:00 - %d rings", hour, bellCount); fireAlertBell(clockConfig.hourBell, bellCount); } } @@ -665,14 +667,14 @@ void Timekeeper::fireAlertBell(uint8_t bellNumber, int count) { for (int i = 0; i < count; i++) { // 🔥 Check for interruption by user playback if (!alertInProgress.load()) { - LOG_INFO("⚡ Alert interrupted at ring %d/%d - stopping immediately", i + 1, count); + LOG_INFO(TAG, "⚡ Alert interrupted at ring %d/%d - stopping immediately", i + 1, count); return; } // Get bell duration from bell configuration uint16_t bellDuration = _configManager->getBellDuration(bellNumber); - LOG_DEBUG("🔔 Alert bell #%d ring %d/%d (duration: %dms)", + LOG_DEBUG(TAG, "🔔 Alert bell #%d ring %d/%d (duration: %dms)", bellNumber + 1, i + 1, count, bellDuration); // Fire the bell using OutputManager @@ -714,14 +716,14 @@ void Timekeeper::checkBacklightAutomation() { // Check if it's time to turn backlight ON if (currentTime == clockConfig.backlightOnTime && !backlightState) { - LOG_INFO("💡 Turning backlight ON at %s (output #%d)", + LOG_INFO(TAG, "💡 Turning backlight ON at %s (output #%d)", currentTime.c_str(), clockConfig.backlightOutput + 1); _outputManager->fireOutput(clockConfig.backlightOutput); backlightState = true; } // Check if it's time to turn backlight OFF else if (currentTime == clockConfig.backlightOffTime && backlightState) { - LOG_INFO("💡 Turning backlight OFF at %s (output #%d)", + LOG_INFO(TAG, "💡 Turning backlight OFF at %s (output #%d)", currentTime.c_str(), clockConfig.backlightOutput + 1); _outputManager->extinguishOutput(clockConfig.backlightOutput); backlightState = false; @@ -744,7 +746,7 @@ bool Timekeeper::isInSilencePeriod() { // Check daytime silence period if (clockConfig.daytimeSilenceEnabled) { bool inDaytime = isTimeInRange(currentTime, clockConfig.daytimeSilenceOnTime, clockConfig.daytimeSilenceOffTime); - LOG_DEBUG("🔇 Daytime silence check: current=%s, range=%s-%s, inRange=%s", + LOG_DEBUG(TAG, "🔇 Daytime silence check: current=%s, range=%s-%s, inRange=%s", currentTime.c_str(), clockConfig.daytimeSilenceOnTime.c_str(), clockConfig.daytimeSilenceOffTime.c_str(), inDaytime ? "YES" : "NO"); if (inDaytime) { @@ -755,7 +757,7 @@ bool Timekeeper::isInSilencePeriod() { // Check nighttime silence period if (clockConfig.nighttimeSilenceEnabled) { bool inNighttime = isTimeInRange(currentTime, clockConfig.nighttimeSilenceOnTime, clockConfig.nighttimeSilenceOffTime); - LOG_DEBUG("🌙 Nighttime silence check: current=%s, range=%s-%s, inRange=%s", + LOG_DEBUG(TAG, "🌙 Nighttime silence check: current=%s, range=%s-%s, inRange=%s", currentTime.c_str(), clockConfig.nighttimeSilenceOnTime.c_str(), clockConfig.nighttimeSilenceOffTime.c_str(), inNighttime ? "YES" : "NO"); if (inNighttime) { @@ -784,38 +786,38 @@ bool Timekeeper::isTimeInRange(const String& currentTime, const String& startTim bool Timekeeper::isHealthy() { // Check if RTC is running if (!rtc.isrunning()) { - LOG_DEBUG("TimeKeeper: Unhealthy - RTC not running"); + LOG_DEBUG(TAG, "TimeKeeper: Unhealthy - RTC not running"); return false; } // Check if main task is created and running if (mainTaskHandle == NULL) { - LOG_DEBUG("TimeKeeper: Unhealthy - Main task not created"); + LOG_DEBUG(TAG, "TimeKeeper: Unhealthy - Main task not created"); return false; } // Check if task is still alive eTaskState taskState = eTaskGetState(mainTaskHandle); if (taskState == eDeleted || taskState == eInvalid) { - LOG_DEBUG("TimeKeeper: Unhealthy - Main task deleted or invalid"); + LOG_DEBUG(TAG, "TimeKeeper: Unhealthy - Main task deleted or invalid"); return false; } // Check if required dependencies are set if (!_configManager) { - LOG_DEBUG("TimeKeeper: Unhealthy - ConfigManager not set"); + LOG_DEBUG(TAG, "TimeKeeper: Unhealthy - ConfigManager not set"); return false; } if (!_outputManager) { - LOG_DEBUG("TimeKeeper: Unhealthy - OutputManager not set"); + LOG_DEBUG(TAG, "TimeKeeper: Unhealthy - OutputManager not set"); return false; } // Check if time is reasonable (not stuck at epoch or way in the future) DateTime now = rtc.now(); if (now.year() < 2020 || now.year() > 2100) { - LOG_DEBUG("TimeKeeper: Unhealthy - RTC time unreasonable: %d", now.year()); + LOG_DEBUG(TAG, "TimeKeeper: Unhealthy - RTC time unreasonable: %d", now.year()); return false; }