bonamin/project-vesper
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: Add per-subsystem log tags to all firmware modules

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
Vasileios Kousaridas
2026-02-26 17:31:28 +02:00
parent c656835d8e
commit fe6b1d871a
26 changed files with 1334 additions and 1074 deletions
Download Patch File Download Diff File Expand all files Collapse all files

60
vesper/src/BellEngine/BellEngine.cpp
View File

@@ -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<uint16_t>& 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<BellEngine*>(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<uint8_t>& 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<uint8_t>& 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;
}

26
vesper/src/ClientManager/ClientManager.cpp
View File

@@ -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 {

193
vesper/src/Communication/CommandHandler/CommandHandler.cpp
View File

@@ -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<String>());
}
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
}
}

131
vesper/src/Communication/CommunicationRouter/CommunicationRouter.cpp
View File

@@ -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<uint8_t
overloadMsg["payload"]["severity"] = severity;
broadcastStatus(overloadMsg);
LOG_WARNING("Bell overload notification sent: %d bells, severity: %s",
LOG_WARNING(TAG, "Bell overload notification sent: %d bells, severity: %s",
bellNumbers.size(), severity.c_str());
}
void CommunicationRouter::onNetworkConnected() {
LOG_DEBUG("Network connected - notifying MQTT client");
LOG_DEBUG(TAG, "Network connected - notifying MQTT client");
_mqttClient.onNetworkConnected();
}
void CommunicationRouter::onNetworkDisconnected() {
LOG_DEBUG("Network disconnected - notifying MQTT client");
LOG_DEBUG(TAG, "Network disconnected - notifying MQTT client");
_mqttClient.onNetworkDisconnected();
}
void CommunicationRouter::onMqttMessage(const String& topic, const String& payload) {
LOG_DEBUG("MQTT message received: %s", payload.c_str());
LOG_DEBUG(TAG, "MQTT message received: %s", payload.c_str());
// Parse JSON
StaticJsonDocument<2048> 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<JsonDocument&>(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!");
}
}

22
vesper/src/Communication/HTTPRequestHandler/HTTPRequestHandler.cpp
View File

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

66
vesper/src/Communication/MQTTAsyncClient/MQTTAsyncClient.cpp
View File

@@ -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<int>(reason));
LOG_ERROR(TAG, "❌ Disconnected from MQTT broker - Reason: %s (%d)", reasonStr, static_cast<int>(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();
}

8
vesper/src/Communication/ResponseBuilder/ResponseBuilder.cpp
View File

@@ -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;
}

24
vesper/src/Communication/UARTCommandHandler/UARTCommandHandler.cpp
View File

@@ -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");
}
}

30
vesper/src/Communication/WebSocketServer/WebSocketServer.cpp
View File

@@ -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());
}
}

254
vesper/src/ConfigManager/ConfigManager.cpp
View File

@@ -1,4 +1,6 @@
#include "ConfigManager.hpp"
#define TAG "ConfigManager"
#include "../../src/Logging/Logging.hpp"
#include <WiFi.h> // For MAC address generation
#include <time.h> // 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<String>();
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<uint16_t>();
}
}
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<uint16_t>() - 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<uint16_t>();
}
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<String>();
}
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<String>();
}
}
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<String>();
if (doc.containsKey("nighttimeSilenceOffTime")) clockConfig.nighttimeSilenceOffTime = doc["nighttimeSilenceOffTime"].as<String>();
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<bool>();
clockConfig.lastSyncTime = doc["lastSyncTime"].as<uint32_t>();
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<String>();
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<bool>();
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<int>();
}
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;
}

7
vesper/src/ConfigManager/ConfigManager.hpp
View File

@@ -25,7 +25,6 @@
#include <ArduinoJson.h>
#include <SD.h>
#include <IPAddress.h>
#include <ETH.h>
#include <vector>
#include <nvs_flash.h>
#include <nvs.h>
@@ -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; }

89
vesper/src/FileManager/FileManager.cpp
View File

@@ -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;
}

3
vesper/src/FileManager/FileManager.hpp
View File

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

160
vesper/src/FirmwareValidator/FirmwareValidator.cpp
View File

@@ -5,6 +5,8 @@
*/
#include "FirmwareValidator.hpp"
#define TAG "FirmwareValidator"
#include "../HealthMonitor/HealthMonitor.hpp"
#include "../ConfigManager/ConfigManager.hpp"
#include <esp_task_wdt.h>
@@ -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<FirmwareValidationState>(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<uint8_t>(_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<FirmwareValidator*>(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<FirmwareValidator*>(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() {

43
vesper/src/HealthMonitor/HealthMonitor.cpp
View File

@@ -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<HealthMonitor*>(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());

38
vesper/src/InputManager/InputManager.cpp
View File

@@ -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<InputManager*>(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;

283
vesper/src/Logging/Logging.cpp
View File

@@ -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<String, Logging::LogLevel> Logging::_serialOverrides;
std::map<String, Logging::LogLevel> Logging::_mqttOverrides;
std::map<String, Logging::LogLevel> 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<String, LogLevel>& 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;
}

159
vesper/src/Logging/Logging.hpp
View File

@@ -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 <Arduino.h>
// Forward declaration
class MQTTAsyncClient;
#include <map>
#include <functional>
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<void(const String& topic, const String& payload, int qos)>;
using SdWriteCallback = std::function<void(const String& line)>;
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<String, LogLevel> _serialOverrides;
static std::map<String, LogLevel> _mqttOverrides;
static std::map<String, LogLevel> _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<String, LogLevel>& 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

124
vesper/src/Networking/Networking.cpp
View File

@@ -1,4 +1,6 @@
#include "Networking.hpp"
#define TAG "Networking"
#include "../ConfigManager/ConfigManager.hpp"
#include "../Logging/Logging.hpp"
#include <WiFiManager.h>
@@ -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 = "<br/><br/><h3>Network Mode</h3>";
@@ -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);
}
}

296
vesper/src/OTAManager/OTAManager.cpp
View File

@@ -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>();
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<String> 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<OTAManager*>(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;
}

98
vesper/src/OutputManager/OutputManager.cpp
View File

@@ -5,6 +5,8 @@
*/
#include "OutputManager.hpp"
#define TAG "OutputManager"
#include "../ConfigManager/ConfigManager.hpp"
#include "../Logging/Logging.hpp"
#include <Adafruit_PCF8574.h>
@@ -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<OutputManager*>(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<std::pa
}
void PCF8574OutputManager::emergencyShutdown() {
LOG_WARNING("🚨 PCF857x EMERGENCY SHUTDOWN - All outputs HIGH");
LOG_WARNING(TAG, "🚨 PCF857x EMERGENCY SHUTDOWN - All outputs HIGH");
portENTER_CRITICAL(&_outputMutex);
_activeOutputs.clear();
portEXIT_CRITICAL(&_outputMutex);
@@ -344,7 +346,7 @@ ChipConfig PCF8574OutputManager::getChipConfig(uint8_t chipIndex) const {
bool PCF8574OutputManager::addChip(uint8_t i2cAddress, ChipType chipType, uint8_t activeOutputs) {
if (_chipCount >= 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<Adafruit_PCF8574*>(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<Adafruit_PCF8575*>(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;

76
vesper/src/Player/Player.cpp
View File

@@ -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;
}

14
vesper/src/SDCardMutex/SDCardMutex.hpp
View File

@@ -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!");
}
}

22
vesper/src/SettingsWebServer/SettingsWebServer.cpp
View File

@@ -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);

58
vesper/src/Telemetry/Telemetry.cpp
View File

@@ -1,4 +1,6 @@
#include "Telemetry.hpp"
#define TAG "Telemetry"
#include <ArduinoJson.h>
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<Telemetry*>(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;
}

124
vesper/src/TimeKeeper/TimeKeeper.cpp
View File

@@ -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 <time.h>
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<Timekeeper*>(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<String>().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<String>().c_str(),
event.timeStr.c_str());
@@ -523,7 +525,7 @@ void Timekeeper::triggerEvent(ScheduledEvent& event) {
String melodyUID = melody["uid"].as<String>();
String melodyName = melody["name"].as<String>();
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;
}