diff --git a/docs/mqtt-usage.md b/docs/mqtt-usage.md index 5cb3555..faffdbd 100644 --- a/docs/mqtt-usage.md +++ b/docs/mqtt-usage.md @@ -114,7 +114,30 @@ myButton.setPayloadPress("PRESS"); Defined in `ArduinoHADefines.h` or via build flags. -- **`ARDUINOHA_DEBUG`** — enables library logging (useful when debugging MQTT). By default lines go to **`Serial`** unless you install a sink with **`arduinoHASetLogSink(ArduinoHALogSink*)`** (for example **DeviceFramework** forwards debug output into its main log stream). +- **`ARDUINOHA_DEBUG`** — enables ArduinoHA logging by default and sets the initial maximum verbosity to `Debug`. Without this flag, structured logs are compiled in but remain disabled until you call `arduinoHASetLogEnabled(true)`. + +Structured logging is available through: + +```cpp +arduinoHASetLogEnabled(true); +arduinoHASetLogLevel(ArduinoHALogLevel::Trace); + +class MyLogSink : public ArduinoHALogSink { +public: + void log(const ArduinoHALogMessage& msg) override { + Serial.print("["); + Serial.print(arduinoHALogLevelTag(msg.level)); + Serial.print("][aha."); + Serial.print(msg.subsystem); + Serial.print("] "); + Serial.println(msg.text); + } +}; +``` + +`arduinoHALog(...)` and `arduinoHALogf(...)` support subsystem-tagged messages such as `mqtt`, `discovery`, `availability`, `serializer`, `entity`, and `device`. `DeviceFramework` installs a structured sink so ArduinoHA messages follow the same main log stream as the rest of the firmware. + +Optional transport context for diagnostics (registered automatically by **DeviceFramework**): **`arduinoHASetNetworkStatusFn`** (for example returning `WiFi.status()` so publish failure lines can include `wifi=`). **Exclude unused device types** (saves flash from vtables), e.g.: diff --git a/src/ArduinoHA.h b/src/ArduinoHA.h index 4b7e831..970786d 100644 --- a/src/ArduinoHA.h +++ b/src/ArduinoHA.h @@ -1,6 +1,8 @@ #ifndef AHA_ARDUINOHA_H #define AHA_ARDUINOHA_H +#include "ArduinoHALog.h" +#include "ArduinoHALogTemplates.h" #include "HADevice.h" #include "HAMqtt.h" #include "device-types/HABinarySensor.h" diff --git a/src/ArduinoHADefines.h b/src/ArduinoHADefines.h index 686bc94..8f925f3 100644 --- a/src/ArduinoHADefines.h +++ b/src/ArduinoHADefines.h @@ -37,15 +37,17 @@ #if defined(ARDUINOHA_DEBUG) #include - #define ARDUINOHA_DEBUG_INIT() do { if (!arduinoHAGetLogSink()) { Serial.begin(115200); } } while(0) - #define ARDUINOHA_DEBUG_PRINTLN(x) do { \ - if (arduinoHAGetLogSink()) { arduinoHAGetLogSink()->println(String(x)); } \ - else { Serial.println(x); } \ - } while(0) - #define ARDUINOHA_DEBUG_PRINT(x) do { \ - if (arduinoHAGetLogSink()) { arduinoHAGetLogSink()->print(String(x)); } \ - else { Serial.print(x); } \ + #define ARDUINOHA_DEBUG_INIT() do { \ + if (!arduinoHAGetLogSink()) { Serial.begin(115200); } \ + arduinoHASetLogEnabled(true); \ + arduinoHASetLogLevel(ArduinoHALogLevel::Debug); \ } while(0) + /** @deprecated Prefer arduinoHALog / arduinoHALogf; each macro emits one structured line. */ + #define ARDUINOHA_DEBUG_PRINTLN(x) \ + arduinoHALog(ArduinoHALogLevel::Debug, "aha", String(x)) + /** @deprecated Prefer arduinoHALog / arduinoHALogf; each macro emits one structured line. */ + #define ARDUINOHA_DEBUG_PRINT(x) \ + arduinoHALog(ArduinoHALogLevel::Debug, "aha", String(x)) #else #define ARDUINOHA_DEBUG_INIT() #define ARDUINOHA_DEBUG_PRINTLN(x) diff --git a/src/ArduinoHALog.cpp b/src/ArduinoHALog.cpp index ef7c253..5cb5340 100644 --- a/src/ArduinoHALog.cpp +++ b/src/ArduinoHALog.cpp @@ -1,6 +1,15 @@ #include "ArduinoHALog.h" static ArduinoHALogSink* g_arduinoHALogSink = nullptr; +static ArduinoHANetworkStatusFn g_networkStatusFn = nullptr; + +#ifdef ARDUINOHA_DEBUG +static bool g_logEnabled = true; +static ArduinoHALogLevel g_logLevelMax = ArduinoHALogLevel::Debug; +#else +static bool g_logEnabled = false; +static ArduinoHALogLevel g_logLevelMax = ArduinoHALogLevel::Info; +#endif void arduinoHASetLogSink(ArduinoHALogSink* sink) { g_arduinoHALogSink = sink; @@ -9,3 +18,80 @@ void arduinoHASetLogSink(ArduinoHALogSink* sink) { ArduinoHALogSink* arduinoHAGetLogSink() { return g_arduinoHALogSink; } + +void arduinoHASetLogEnabled(bool enabled) { + g_logEnabled = enabled; +} + +bool arduinoHAIsLogEnabled() { + return g_logEnabled; +} + +void arduinoHASetLogLevel(ArduinoHALogLevel level) { + g_logLevelMax = level; +} + +ArduinoHALogLevel arduinoHAGetLogLevel() { + return g_logLevelMax; +} + +void arduinoHASetNetworkStatusFn(ArduinoHANetworkStatusFn fn) { + g_networkStatusFn = fn; +} + +int arduinoHANetworkStatusOptional(void) { + if (!g_networkStatusFn) { + return -1; + } + return g_networkStatusFn(); +} + +const char* arduinoHALogLevelTag(ArduinoHALogLevel level) { + switch (level) { + case ArduinoHALogLevel::Error: + return "ERROR"; + case ArduinoHALogLevel::Warn: + return "WARN"; + case ArduinoHALogLevel::Info: + return "INFO"; + case ArduinoHALogLevel::Debug: + return "DEBUG"; + case ArduinoHALogLevel::Trace: + return "TRACE"; + default: + return "?"; + } +} + +void arduinoHALog( + ArduinoHALogLevel level, + const char* subsystem, + const String& text +) { + if (!g_logEnabled) { + return; + } + + if (static_cast(level) > static_cast(g_logLevelMax)) { + return; + } + + const char* sub = (subsystem && subsystem[0] != '\0') ? subsystem : "aha"; + + ArduinoHALogMessage msg; + msg.level = level; + msg.subsystem = sub; + msg.text = text; + + if (g_arduinoHALogSink) { + g_arduinoHALogSink->log(msg); + return; + } + + Serial.print(F("[")); + Serial.print(arduinoHALogLevelTag(level)); + Serial.print(F("][aha.")); + Serial.print(sub); + Serial.print(F("] ")); + Serial.println(text); +} diff --git a/src/ArduinoHALog.h b/src/ArduinoHALog.h index e96b90b..2364533 100644 --- a/src/ArduinoHALog.h +++ b/src/ArduinoHALog.h @@ -4,17 +4,62 @@ #include /** - * Optional sink for ArduinoHA debug output (ARDUINOHA_DEBUG). - * When set, ARDUINOHA_DEBUG_* macros route here; otherwise Serial is used. + * Log severity for ArduinoHA. Numeric order is used for filtering: only messages with + * level <= the configured maximum (see arduinoHASetLogLevel) are emitted. + */ +enum class ArduinoHALogLevel : uint8_t { + Error = 1, + Warn, + Info, + Debug, + Trace, +}; + +struct ArduinoHALogMessage { + ArduinoHALogLevel level; + const char* subsystem; + String text; +}; + +/** + * Structured log sink (mirrors WiFiManager-style log callbacks). + * Install with arduinoHASetLogSink; when null, arduinoHALog writes to Serial if enabled. */ class ArduinoHALogSink { public: - virtual void print(const String& s) = 0; - virtual void println(const String& s) = 0; + virtual void log(const ArduinoHALogMessage& msg) = 0; virtual ~ArduinoHALogSink() = default; }; void arduinoHASetLogSink(ArduinoHALogSink* sink); ArduinoHALogSink* arduinoHAGetLogSink(); +void arduinoHASetLogEnabled(bool enabled); +bool arduinoHAIsLogEnabled(); + +/** + * Maximum verbosity to print: Error..Trace. Messages with level <= this value are shown. + */ +void arduinoHASetLogLevel(ArduinoHALogLevel level); +ArduinoHALogLevel arduinoHAGetLogLevel(); + +void arduinoHALog( + ArduinoHALogLevel level, + const char* subsystem, + const String& text +); + +const char* arduinoHALogLevelTag(ArduinoHALogLevel level); + +/** + * Optional hook for transport diagnostics (e.g. return WiFi.status()). + * When unset, publish failure logs omit network fields. + */ +typedef int (*ArduinoHANetworkStatusFn)(void); + +void arduinoHASetNetworkStatusFn(ArduinoHANetworkStatusFn fn); + +/** Returns -1 when no hook is installed. */ +int arduinoHANetworkStatusOptional(void); + #endif diff --git a/src/ArduinoHALogTemplates.h b/src/ArduinoHALogTemplates.h new file mode 100644 index 0000000..61e78b9 --- /dev/null +++ b/src/ArduinoHALogTemplates.h @@ -0,0 +1,58 @@ +#ifndef ARDUINOHA_LOG_TEMPLATES_H +#define ARDUINOHA_LOG_TEMPLATES_H + +#include "ArduinoHALog.h" +#include + +inline String ahaLogStringifyArg(const __FlashStringHelper* v) { + return String(v); +} + +inline String ahaLogStringifyArg(const IPAddress& v) { + return v.toString(); +} + +template +inline String ahaLogStringifyArg(const T& v) { + return String(v); +} + +template +inline void arduinoHALogf( + ArduinoHALogLevel level, + const char* subsystem, + T&& text +) { + arduinoHALog(level, subsystem, ahaLogStringifyArg(text)); +} + +template +inline void arduinoHALogf( + ArduinoHALogLevel level, + const char* subsystem, + T&& a, + U&& b +) { + arduinoHALog( + level, + subsystem, + ahaLogStringifyArg(a) + ahaLogStringifyArg(b) + ); +} + +template +inline void arduinoHALogf( + ArduinoHALogLevel level, + const char* subsystem, + T&& a, + U&& b, + V&& c +) { + arduinoHALog( + level, + subsystem, + ahaLogStringifyArg(a) + ahaLogStringifyArg(b) + ahaLogStringifyArg(c) + ); +} + +#endif diff --git a/src/HAMqtt.cpp b/src/HAMqtt.cpp index d05836b..7df1ef2 100644 --- a/src/HAMqtt.cpp +++ b/src/HAMqtt.cpp @@ -7,12 +7,19 @@ #include #endif +#include "ArduinoHALog.h" +#include "ArduinoHALogTemplates.h" #include "HADevice.h" #include "device-types/HABaseDeviceType.h" #include "mocks/PubSubClientMock.h" #include "utils/HADictionary.h" #include "utils/HASerializer.h" +namespace { +constexpr char kMqtt[] = "mqtt"; +constexpr char kDiscovery[] = "discovery"; +} // namespace + #define HAMQTT_INIT \ _device(device), \ _messageCallback(nullptr), \ @@ -35,6 +42,11 @@ _lastWillMessage(nullptr), \ _lastWillRetain(false), \ _currentState(StateDisconnected), \ + _lastLoopOkAt(0), \ + _lastMessageAt(0), \ + _lastPublishAt(0), \ + _lastDisconnectAt(0), \ + _lastDisconnectReason(DiagnosticDisconnectReason::None), \ _messageDispatchDepth(0), \ _deferredQueue{}, \ _deferredHead(0), \ @@ -96,6 +108,49 @@ HAMqtt::~HAMqtt() _instance = nullptr; } +const char* HAMqtt::diagnosticDisconnectReasonText(DiagnosticDisconnectReason reason) +{ + switch (reason) { + case DiagnosticDisconnectReason::None: + return "none"; + case DiagnosticDisconnectReason::LoopReturnedFalse: + return "loop_false"; + case DiagnosticDisconnectReason::DeferredBeginPublishFailed: + return "deferred_begin_publish"; + case DiagnosticDisconnectReason::DeferredEndPublishFailed: + return "deferred_end_publish"; + case DiagnosticDisconnectReason::NotConnectedDuringDeferredFlush: + return "deferred_not_connected"; + case DiagnosticDisconnectReason::UnderlyingPubSubStateChanged: + return "pubsub_state"; + case DiagnosticDisconnectReason::ExplicitDisconnect: + return "explicit"; + default: + return "?"; + } +} + +int HAMqtt::getPubSubState() const +{ + return _mqtt->state(); +} + +String HAMqtt::formatDirectPublishFailureDiagnostics(bool hamqttConnectedBefore, int pubsubStateBefore) const +{ + const bool hamqttConnectedAfter = isConnected(); + const int pubsubStateAfter = getPubSubState(); + String d = String(F(" hamqttConnBefore=")) + String(hamqttConnectedBefore ? 1 : 0) + + F(" hamqttConnAfter=") + String(hamqttConnectedAfter ? 1 : 0) + + F(" pubsubBefore=") + String(pubsubStateBefore) + + F(" pubsubAfter=") + String(pubsubStateAfter); + const int wifi = arduinoHANetworkStatusOptional(); + if (wifi >= 0) { + d += F(" wifi="); + d += String(wifi); + } + return d; +} + bool HAMqtt::begin( const IPAddress serverIp, const uint16_t serverPort, @@ -103,18 +158,16 @@ bool HAMqtt::begin( const char* password ) { - ARDUINOHA_DEBUG_PRINT(F("AHA: init server ")) - ARDUINOHA_DEBUG_PRINT(serverIp) - ARDUINOHA_DEBUG_PRINT(F(":")) - ARDUINOHA_DEBUG_PRINTLN(serverPort) + arduinoHALogf(ArduinoHALogLevel::Info, kMqtt, F("init server "), serverIp); + arduinoHALogf(ArduinoHALogLevel::Info, kMqtt, F("init port "), serverPort); if (_device.getUniqueId() == nullptr) { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: init failed. Missing device unique ID")) + arduinoHALog(ArduinoHALogLevel::Error, kMqtt, F("init failed: missing device unique ID")); return false; } if (_initialized) { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: already initialized")) + arduinoHALog(ArduinoHALogLevel::Warn, kMqtt, F("begin ignored: already initialized")); return false; } @@ -144,18 +197,16 @@ bool HAMqtt::begin( const char* password ) { - ARDUINOHA_DEBUG_PRINT(F("AHA: init server ")) - ARDUINOHA_DEBUG_PRINT(serverHostname) - ARDUINOHA_DEBUG_PRINT(F(":")) - ARDUINOHA_DEBUG_PRINTLN(serverPort) + arduinoHALogf(ArduinoHALogLevel::Info, kMqtt, F("init server "), serverHostname); + arduinoHALogf(ArduinoHALogLevel::Info, kMqtt, F("init port "), serverPort); if (_device.getUniqueId() == nullptr) { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: init failed. Missing device unique ID")) + arduinoHALog(ArduinoHALogLevel::Error, kMqtt, F("init failed: missing device unique ID")); return false; } if (_initialized) { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: already initialized")) + arduinoHALog(ArduinoHALogLevel::Warn, kMqtt, F("begin ignored: already initialized")); return false; } @@ -184,7 +235,9 @@ bool HAMqtt::disconnect() return false; } - ARDUINOHA_DEBUG_PRINTLN(F("AHA: disconnecting")) + _lastDisconnectReason = DiagnosticDisconnectReason::ExplicitDisconnect; + _lastDisconnectAt = millis(); + arduinoHALog(ArduinoHALogLevel::Info, kMqtt, F("disconnect requested")); clearDeferredBuilder(); _initialized = false; @@ -201,16 +254,50 @@ void HAMqtt::loop() } bool result = _mqtt->loop(); - if (_currentState != _mqtt->state()) { - setState(static_cast(_mqtt->state())); + const int rawState = _mqtt->state(); + + if (result) { + _lastLoopOkAt = millis(); + } + + if (_currentState != rawState) { + setState(static_cast(rawState)); } if (!result) { + _lastDisconnectReason = DiagnosticDisconnectReason::LoopReturnedFalse; + const uint32_t now = millis(); + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("loop returned false pubsub=")) + String(rawState) + + F(" deferred=") + String(_deferredCount) + + F(" depth=") + String(_messageDispatchDepth) + + F(" sinceLastMsgMs=") + + String(_lastMessageAt ? (now - _lastMessageAt) : static_cast(0)) + + F(" sinceLastPubMs=") + + String(_lastPublishAt ? (now - _lastPublishAt) : static_cast(0)) + ); connectToServer(); } if (_messageDispatchDepth == 0 && isConnected()) { - flushDeferredPublishes(); + const uint8_t before = _deferredCount; + const bool ok = flushDeferredPublishes(); + if (!ok) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("deferred flush failed queue=")) + String(_deferredCount) + + F(" reason=") + diagnosticDisconnectReasonText(_lastDisconnectReason) + ); + } else if (before > 0) { + arduinoHALog( + ArduinoHALogLevel::Debug, + kMqtt, + String(F("deferred flush ok count=")) + String(before) + ); + } } } @@ -258,12 +345,19 @@ bool HAMqtt::publish(const char* topic, const char* payload, bool retained) const uint16_t payloadLength = static_cast(len); - ARDUINOHA_DEBUG_PRINT(F("AHA: publishing ")) - ARDUINOHA_DEBUG_PRINT(topic) - ARDUINOHA_DEBUG_PRINT(F(", len: ")) - ARDUINOHA_DEBUG_PRINTLN(payloadLength) + arduinoHALog( + ArduinoHALogLevel::Debug, + kMqtt, + String(F("publish topic=")) + topic + F(" len=") + String(payloadLength) + ); if (isProcessingMessage()) { + arduinoHALog( + ArduinoHALogLevel::Trace, + kMqtt, + String(F("queue publish during callback topic=")) + topic + + F(" len=") + String(payloadLength) + ); return enqueueDeferredPublish( topic, reinterpret_cast(payload), @@ -272,9 +366,32 @@ bool HAMqtt::publish(const char* topic, const char* payload, bool retained) ); } - _mqtt->beginPublish(topic, payloadLength, retained); + const bool connBeforePub = isConnected(); + const int psBeforePub = getPubSubState(); + if (!_mqtt->beginPublish(topic, payloadLength, retained)) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("beginPublish failed topic=")) + topic + F(" len=") + String(payloadLength) + + formatDirectPublishFailureDiagnostics(connBeforePub, psBeforePub) + ); + return false; + } _mqtt->write(reinterpret_cast(payload), payloadLength); - return _mqtt->endPublish(); + const bool connBeforeEnd = isConnected(); + const int psBeforeEnd = getPubSubState(); + const bool ok = _mqtt->endPublish(); + if (!ok) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("endPublish failed topic=")) + topic + + formatDirectPublishFailureDiagnostics(connBeforeEnd, psBeforeEnd) + ); + } else { + _lastPublishAt = millis(); + } + return ok; } bool HAMqtt::beginPublish( @@ -283,17 +400,30 @@ bool HAMqtt::beginPublish( bool retained ) { - ARDUINOHA_DEBUG_PRINT(F("AHA: begin publish ")) - ARDUINOHA_DEBUG_PRINT(topic) - ARDUINOHA_DEBUG_PRINT(F(", len: ")) - ARDUINOHA_DEBUG_PRINTLN(payloadLength) + arduinoHALog( + ArduinoHALogLevel::Debug, + kMqtt, + String(F("beginPublish topic=")) + (topic ? topic : "") + + F(" len=") + String(payloadLength) + ); if (!isConnected() || !topic) { return false; } if (!isProcessingMessage()) { - return _mqtt->beginPublish(topic, payloadLength, retained); + const bool connBefore = isConnected(); + const int psBefore = getPubSubState(); + const bool ok = _mqtt->beginPublish(topic, payloadLength, retained); + if (!ok) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("beginPublish failed topic=")) + topic + F(" len=") + String(payloadLength) + + formatDirectPublishFailureDiagnostics(connBefore, psBefore) + ); + } + return ok; } if (_deferredBuilder.active) { @@ -367,7 +497,20 @@ void HAMqtt::writePayload(const __FlashStringHelper* src) bool HAMqtt::endPublish() { if (!isProcessingMessage()) { - return _mqtt->endPublish(); + const bool connBefore = isConnected(); + const int psBefore = getPubSubState(); + const bool ok = _mqtt->endPublish(); + if (ok) { + _lastPublishAt = millis(); + } else { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("endPublish failed (direct)")) + + formatDirectPublishFailureDiagnostics(connBefore, psBefore) + ); + } + return ok; } if (!_deferredBuilder.active || @@ -383,24 +526,32 @@ bool HAMqtt::endPublish() _deferredBuilder.expectedLength, _deferredBuilder.retained ); + if (ok) { + arduinoHALog( + ArduinoHALogLevel::Trace, + kMqtt, + String(F("queued deferred built publish len=")) + String(_deferredBuilder.expectedLength) + ); + } clearDeferredBuilder(); return ok; } bool HAMqtt::subscribe(const char* topic) { - ARDUINOHA_DEBUG_PRINT(F("AHA: subscribing ")) - ARDUINOHA_DEBUG_PRINTLN(topic) - + arduinoHALog(ArduinoHALogLevel::Debug, kMqtt, String(F("subscribe ")) + (topic ? topic : "")); return _mqtt->subscribe(topic); } void HAMqtt::processMessage(const char* topic, const uint8_t* payload, uint16_t length) { - ARDUINOHA_DEBUG_PRINT(F("AHA: received call ")) - ARDUINOHA_DEBUG_PRINT(topic) - ARDUINOHA_DEBUG_PRINT(F(", len: ")) - ARDUINOHA_DEBUG_PRINTLN(length) + _lastMessageAt = millis(); + arduinoHALog( + ArduinoHALogLevel::Debug, + kMqtt, + String(F("rx topic=")) + (topic ? topic : "") + F(" len=") + String(length) + + F(" depth=") + String(_messageDispatchDepth) + F(" deferred=") + String(_deferredCount) + ); _messageDispatchDepth++; @@ -415,7 +566,22 @@ void HAMqtt::processMessage(const char* topic, const uint8_t* payload, uint16_t _messageDispatchDepth--; if (_messageDispatchDepth == 0) { - flushDeferredPublishes(); + const uint8_t before = _deferredCount; + const bool ok = flushDeferredPublishes(); + if (!ok) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("deferred flush failed after rx queue=")) + String(_deferredCount) + + F(" reason=") + diagnosticDisconnectReasonText(_lastDisconnectReason) + ); + } else if (before > 0) { + arduinoHALog( + ArduinoHALogLevel::Debug, + kMqtt, + String(F("deferred flush ok after rx count=")) + String(before) + ); + } } } @@ -426,11 +592,18 @@ void HAMqtt::connectToServer() return; } - _lastConnectionAttemptAt = millis(); + const uint32_t now = millis(); + const uint32_t sinceLastAttempt = (_lastConnectionAttemptAt > 0) ? (now - _lastConnectionAttemptAt) : 0; + _lastConnectionAttemptAt = now; setState(StateConnecting); - ARDUINOHA_DEBUG_PRINT(F("AHA: MQTT connecting, client ID: ")) - ARDUINOHA_DEBUG_PRINTLN(_device.getUniqueId()) + arduinoHALog( + ArduinoHALogLevel::Info, + kMqtt, + String(F("connect attempt clientId=")) + (_device.getUniqueId() ? _device.getUniqueId() : "") + + F(" sincePrevAttemptMs=") + String(sinceLastAttempt) + + F(" reconnectIntervalMs=") + String(_reconnectInterval) + ); _mqtt->connect( _device.getUniqueId(), @@ -446,7 +619,11 @@ void HAMqtt::connectToServer() if (isConnected()) { setState(StateConnected); } else { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: failed to connect")) + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("connect failed pubsub=")) + String(_mqtt->state()) + ); } } @@ -574,7 +751,16 @@ bool HAMqtt::publishDeviceDiscovery() strcat_P(topic, HASerializerSlash); strcat_P(topic, HAConfigTopic); + const bool discConnBefore = isConnected(); + const int discPsBefore = getPubSubState(); if (!_mqtt->beginPublish(topic, payloadLength, true)) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kDiscovery, + String(F("device discovery beginPublish failed topic=")) + topic + + F(" len=") + String(payloadLength) + + formatDirectPublishFailureDiagnostics(discConnBefore, discPsBefore) + ); for (uint8_t i = 0; i < componentSerializerCount; i++) { delete componentSerializers[i]; } @@ -615,7 +801,11 @@ bool HAMqtt::publishDeviceDiscovery() writePayload(AHATOFSTR(HASerializerJsonDataSuffix)); writePayload(AHATOFSTR(HASerializerJsonDataSuffix)); - return endPublish(); + const bool published = endPublish(); + if (!published) { + arduinoHALog(ArduinoHALogLevel::Warn, kDiscovery, F("device discovery endPublish failed")); + } + return published; } void HAMqtt::setState(ConnectionState state) @@ -623,16 +813,40 @@ void HAMqtt::setState(ConnectionState state) ConnectionState previousState = _currentState; _currentState = state; - ARDUINOHA_DEBUG_PRINT(F("AHA: MQTT state changed to ")) - ARDUINOHA_DEBUG_PRINT(_currentState) - ARDUINOHA_DEBUG_PRINT(F(", previous state: ")) - ARDUINOHA_DEBUG_PRINTLN(previousState) + arduinoHALog( + ArduinoHALogLevel::Info, + kMqtt, + String(F("mqtt state ")) + String(static_cast(previousState)) + + F(" -> ") + String(static_cast(_currentState)) + + F(" pubsub=") + String(_mqtt->state()) + ); if (_currentState == StateConnected) { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: MQTT connected")) + _lastDisconnectReason = DiagnosticDisconnectReason::None; + arduinoHALog(ArduinoHALogLevel::Info, kMqtt, F("connected")); onConnectedLogic(); } else if (previousState == StateConnected && _currentState != StateConnected) { - ARDUINOHA_DEBUG_PRINTLN(F("AHA: MQTT disconnected")) + const uint32_t now = millis(); + _lastDisconnectAt = now; + if (_lastDisconnectReason == DiagnosticDisconnectReason::None) { + _lastDisconnectReason = DiagnosticDisconnectReason::UnderlyingPubSubStateChanged; + } + + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("disconnect ahaState=")) + String(static_cast(_currentState)) + + F(" pubsub=") + String(_mqtt->state()) + + F(" reason=") + diagnosticDisconnectReasonText(_lastDisconnectReason) + + F(" deferred=") + String(_deferredCount) + + F(" depth=") + String(_messageDispatchDepth) + + F(" sinceLastMsgMs=") + + String(_lastMessageAt ? (now - _lastMessageAt) : static_cast(0)) + + F(" sinceLastPubMs=") + + String(_lastPublishAt ? (now - _lastPublishAt) : static_cast(0)) + + F(" sinceLastLoopOkMs=") + + String(_lastLoopOkAt ? (now - _lastLoopOkAt) : static_cast(0)) + ); if (_disconnectedCallback) { _disconnectedCallback(); @@ -652,6 +866,13 @@ bool HAMqtt::enqueueDeferredPublish( ) { if (!topic || _deferredCount >= DeferredQueueCapacity) { + if (topic && _deferredCount >= DeferredQueueCapacity) { + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("deferred queue full; drop topic=")) + topic + F(" len=") + String(length) + ); + } return false; } @@ -724,7 +945,17 @@ bool HAMqtt::flushDeferredPublishes() while (_deferredCount > 0) { DeferredPublishMessage& msg = _deferredQueue[_deferredHead]; + const bool defConnSnap = isConnected(); + const int defPsSnap = getPubSubState(); if (!isConnected()) { + _lastDisconnectReason = DiagnosticDisconnectReason::NotConnectedDuringDeferredFlush; + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("deferred flush: not connected topic=")) + + (msg.topic ? msg.topic : "") + F(" queue=") + String(_deferredCount) + + formatDirectPublishFailureDiagnostics(defConnSnap, defPsSnap) + ); #ifdef ARDUINOHA_TEST _deferredFlushFailedForTest = true; _lastDeferredFlushErrorForTest = DeferredFlushErrorNotConnected; @@ -732,7 +963,17 @@ bool HAMqtt::flushDeferredPublishes() return false; } + const bool defBpConnBefore = isConnected(); + const int defBpPsBefore = getPubSubState(); if (!_mqtt->beginPublish(msg.topic, msg.length, msg.retained)) { + _lastDisconnectReason = DiagnosticDisconnectReason::DeferredBeginPublishFailed; + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("deferred beginPublish failed topic=")) + + (msg.topic ? msg.topic : "") + F(" len=") + String(msg.length) + + formatDirectPublishFailureDiagnostics(defBpConnBefore, defBpPsBefore) + ); #ifdef ARDUINOHA_TEST _deferredFlushFailedForTest = true; _lastDeferredFlushErrorForTest = DeferredFlushErrorBeginPublish; @@ -744,7 +985,16 @@ bool HAMqtt::flushDeferredPublishes() _mqtt->write(msg.payload, msg.length); } + const bool defEpConnBefore = isConnected(); + const int defEpPsBefore = getPubSubState(); if (!_mqtt->endPublish()) { + _lastDisconnectReason = DiagnosticDisconnectReason::DeferredEndPublishFailed; + arduinoHALog( + ArduinoHALogLevel::Warn, + kMqtt, + String(F("deferred endPublish failed topic=")) + (msg.topic ? msg.topic : "") + + formatDirectPublishFailureDiagnostics(defEpConnBefore, defEpPsBefore) + ); #ifdef ARDUINOHA_TEST _deferredFlushFailedForTest = true; _lastDeferredFlushErrorForTest = DeferredFlushErrorEndPublish; @@ -752,6 +1002,7 @@ bool HAMqtt::flushDeferredPublishes() return false; } + _lastPublishAt = millis(); clearDeferredMessage(msg); _deferredHead = static_cast((_deferredHead + 1) % DeferredQueueCapacity); _deferredCount--; diff --git a/src/HAMqtt.h b/src/HAMqtt.h index 6c27171..a317512 100644 --- a/src/HAMqtt.h +++ b/src/HAMqtt.h @@ -37,6 +37,22 @@ using namespace arduino; class HAMqtt { public: + /** + * Best-effort classification of the last disconnect or transport failure + * (for diagnostics; not an MQTT DISCONNECT reason code). + */ + enum class DiagnosticDisconnectReason : uint8_t { + None = 0, + LoopReturnedFalse, + DeferredBeginPublishFailed, + DeferredEndPublishFailed, + NotConnectedDuringDeferredFlush, + UnderlyingPubSubStateChanged, + ExplicitDisconnect, + }; + + static const char* diagnosticDisconnectReasonText(DiagnosticDisconnectReason reason); + enum ConnectionState { StateConnecting = -5, StateConnectionTimeout = -4, @@ -194,6 +210,26 @@ public: inline ConnectionState getState() const { return _currentState; } + inline uint8_t getDeferredQueueCount() const + { return _deferredCount; } + + inline uint32_t getLastLoopOkAt() const + { return _lastLoopOkAt; } + + inline uint32_t getLastMessageAt() const + { return _lastMessageAt; } + + inline uint32_t getLastPublishAt() const + { return _lastPublishAt; } + + inline uint32_t getLastDisconnectAt() const + { return _lastDisconnectAt; } + + inline DiagnosticDisconnectReason getLastDisconnectReason() const + { return _lastDisconnectReason; } + + int getPubSubState() const; + /** * Sets parameters of the MQTT connection using the IP address and port. * The library will try to connect to the broker in first loop cycle. @@ -526,6 +562,11 @@ private: */ bool flushDeferredPublishes(); + /** + * PubSubClient snapshot when a direct publish step fails (header or endPublish). + */ + String formatDirectPublishFailureDiagnostics(bool hamqttConnectedBefore, int pubsubStateBefore) const; + #ifdef ARDUINOHA_TEST PubSubClientMock* _mqtt; #else @@ -598,6 +639,12 @@ private: /// The last known state of the MQTT connection. ConnectionState _currentState; + uint32_t _lastLoopOkAt; + uint32_t _lastMessageAt; + uint32_t _lastPublishAt; + uint32_t _lastDisconnectAt; + DiagnosticDisconnectReason _lastDisconnectReason; + /// Nesting depth for inbound message dispatch (processMessage). uint8_t _messageDispatchDepth;