mirror of
https://github.com/alexhopeoconnor/arduino-home-assistant.git
synced 2026-10-04 02:48:13 +10:00
Refactor ArduinoHA logging and add MQTT diagnostics.
Move ArduinoHA to a structured, runtime-configurable log model and instrument HAMqtt with disconnect and publish failure telemetry so ESP8266 MQTT failures can be diagnosed without patching PubSubClient first.
This commit is contained in:
+24
-1
@@ -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.:
|
||||
|
||||
|
||||
@@ -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"
|
||||
|
||||
+10
-8
@@ -37,15 +37,17 @@
|
||||
#if defined(ARDUINOHA_DEBUG)
|
||||
#include <Arduino.h>
|
||||
|
||||
#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)
|
||||
|
||||
@@ -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<uint8_t>(level) > static_cast<uint8_t>(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);
|
||||
}
|
||||
|
||||
+49
-4
@@ -4,17 +4,62 @@
|
||||
#include <Arduino.h>
|
||||
|
||||
/**
|
||||
* 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
|
||||
|
||||
@@ -0,0 +1,58 @@
|
||||
#ifndef ARDUINOHA_LOG_TEMPLATES_H
|
||||
#define ARDUINOHA_LOG_TEMPLATES_H
|
||||
|
||||
#include "ArduinoHALog.h"
|
||||
#include <IPAddress.h>
|
||||
|
||||
inline String ahaLogStringifyArg(const __FlashStringHelper* v) {
|
||||
return String(v);
|
||||
}
|
||||
|
||||
inline String ahaLogStringifyArg(const IPAddress& v) {
|
||||
return v.toString();
|
||||
}
|
||||
|
||||
template<typename T>
|
||||
inline String ahaLogStringifyArg(const T& v) {
|
||||
return String(v);
|
||||
}
|
||||
|
||||
template<typename T>
|
||||
inline void arduinoHALogf(
|
||||
ArduinoHALogLevel level,
|
||||
const char* subsystem,
|
||||
T&& text
|
||||
) {
|
||||
arduinoHALog(level, subsystem, ahaLogStringifyArg(text));
|
||||
}
|
||||
|
||||
template<typename T, typename U>
|
||||
inline void arduinoHALogf(
|
||||
ArduinoHALogLevel level,
|
||||
const char* subsystem,
|
||||
T&& a,
|
||||
U&& b
|
||||
) {
|
||||
arduinoHALog(
|
||||
level,
|
||||
subsystem,
|
||||
ahaLogStringifyArg(a) + ahaLogStringifyArg(b)
|
||||
);
|
||||
}
|
||||
|
||||
template<typename T, typename U, typename V>
|
||||
inline void arduinoHALogf(
|
||||
ArduinoHALogLevel level,
|
||||
const char* subsystem,
|
||||
T&& a,
|
||||
U&& b,
|
||||
V&& c
|
||||
) {
|
||||
arduinoHALog(
|
||||
level,
|
||||
subsystem,
|
||||
ahaLogStringifyArg(a) + ahaLogStringifyArg(b) + ahaLogStringifyArg(c)
|
||||
);
|
||||
}
|
||||
|
||||
#endif
|
||||
+298
-47
@@ -7,12 +7,19 @@
|
||||
#include <PubSubClient.h>
|
||||
#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<ConnectionState>(_mqtt->state()));
|
||||
const int rawState = _mqtt->state();
|
||||
|
||||
if (result) {
|
||||
_lastLoopOkAt = millis();
|
||||
}
|
||||
|
||||
if (_currentState != rawState) {
|
||||
setState(static_cast<ConnectionState>(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<uint32_t>(0)) +
|
||||
F(" sinceLastPubMs=") +
|
||||
String(_lastPublishAt ? (now - _lastPublishAt) : static_cast<uint32_t>(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<uint16_t>(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<const uint8_t*>(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<const uint8_t*>(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<int>(previousState)) +
|
||||
F(" -> ") + String(static_cast<int>(_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<int>(_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<uint32_t>(0)) +
|
||||
F(" sinceLastPubMs=") +
|
||||
String(_lastPublishAt ? (now - _lastPublishAt) : static_cast<uint32_t>(0)) +
|
||||
F(" sinceLastLoopOkMs=") +
|
||||
String(_lastLoopOkAt ? (now - _lastLoopOkAt) : static_cast<uint32_t>(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<uint8_t>((_deferredHead + 1) % DeferredQueueCapacity);
|
||||
_deferredCount--;
|
||||
|
||||
@@ -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;
|
||||
|
||||
|
||||
Reference in New Issue
Block a user