diff --git a/readme.md b/readme.md index beb82b9..36ee35c 100644 --- a/readme.md +++ b/readme.md @@ -137,7 +137,7 @@ An `ActionMapping` takes an optional third argument, the directive payload as JS Everything goes over MQTT (port 1883 of `alex2mqtt.stormysdream.club`); the library makes no HTTP requests. -- **Session.** `begin()` starts SNTP (`pool.ntp.org`, `time.nist.gov`) and returns; `loop()` opens the MQTT session once the clock is set, or after 5 s without an answer, and subscribes to `/discover` and `/+/alexaDirective`. `getState()` is `CONNECTED` when the broker has acknowledged both subscriptions. A sketch that sets the clock itself (its own `configTime()` with a time zone, an RTC) calls `alexClient.setTimeSource(false)` before `begin()`. +- **Session.** `begin()` starts SNTP (`pool.ntp.org`, `time.nist.gov`) and returns; `loop()` opens the MQTT session once the clock is set, or after 5 s without an answer, and subscribes to `/discover` and `/+/alexaDirective`. `getState()` is `CONNECTED` when the broker has acknowledged both subscriptions. A sketch that sets the clock itself (its own `configTime()` with a time zone, an RTC) calls `alexClient.setTimeSource(false)` before `begin()`. The board has to reach an NTP server: DNS for the two names and outbound UDP port 123. Without the time of day the session still opens, the reports carry a `timeOfSample` in 1970, and the library prints `[Alex2ESP] error: the clock is not set, ...` when it connects and then at most once a minute while reports are sent. - **Discovery.** On `/discover` the library answers with one discovery object per device on `/discover_r`. The backend accepts one endpoint object per message and collects everything that arrives within 1 s for Alexa's discovery answer (up to 5 s for its proactive AddOrUpdate push), so all devices are published back to back from the next `loop()`. Each object sits on the heap (about 1 KB) until the MQTT client has sent it; when the client cannot take another one (free heap under 4 KB), the library prints `[Alex2ESP] discovery deferred at ` and sends the rest from `loop()` as the queue drains, for up to 5 s after the request. `[Alex2ESP] error: discovery gave up: N device(s) not announced` means those devices missed this answer - on the backend's proactive discovery that can remove them from Alexa until the next one. - **Directives.** The directive arrives as JSON on `//alexaDirective`. A directive larger than one TCP segment arrives in fragments, which are put together in one heap block that exists only until `loop()` has parsed it. `loop()` then fires `ReportState` or `Event` (and `DirectiveReceived`, if registered) with the directive: `directive["header"]`, `directive["endpoint"]`, `directive["payload"]`. Every call of `loop()` handles one directive, in the order of arrival. Up to eight directives wait for it: Alexa sends a group command ("turn off the kitchen") as one directive per endpoint, and they arrive faster than a busy sketch calls `loop()`. A directive that arrives twice (a broker that mirrors its topics delivers every message twice) is handled once; the repeat is recognised while it arrives and takes no place among the waiting ones. - **Reports.** `send()` publishes the report on `//alexaResponce` at once. The backend waits 7 s for it, so answer from the event handler. Every property carries the board's UTC time as `timeOfSample`. @@ -244,7 +244,7 @@ For instance, to manually report the state of a PowerController, you can use the Behaviour changes: - Directives arrive over MQTT. The library subscribes to `/+/alexaDirective`, where Alex2MQTT has always published the whole directive, instead of fetching it over HTTP with the token from `//alexaDirective_e`. The HTTP detour dates from 2024, when a directive larger than one TCP segment reached the MQTT callback in pieces; the pieces are now put together by their offset and the total length, in one heap block that lives until `loop()` has parsed the directive. `loop()` no longer stalls for two HTTP round trips per directive. - Reports leave over MQTT. `send()` publishes on `//alexaResponce` at once, where 1.1.0 queued the report for an HTTP POST from a later `loop()`. It returns `false` when there is no session with the broker, when the MQTT client or the heap cannot take the report, or when the report is over 3071 bytes (`ALEX2ESP_MAX_MESSAGE`, by default 1024 more than the largest directive, so that every directive that is accepted can be answered); each case prints its reason. The 5-slot send queue is gone. -- `timeOfSample` is the board's own time in UTC, for example `2026-09-28T13:05:09Z`. 1.1.0 sent the placeholder `{REPLACE_WITH_DATETIME}`, which only the backend's HTTP route replaced. `begin()` starts SNTP (`pool.ntp.org`, `time.nist.gov`) and no longer connects itself: `loop()` opens the MQTT session once the clock is set, or after 5 s without an answer, so the session comes up a few seconds later than before. `alexClient.setTimeSource(false)` before `begin()` leaves the clock to the sketch. `AddContextProp()` fills `timeOfSample` in when the property has none or carries the old placeholder. +- `timeOfSample` is the board's own time in UTC, for example `2026-09-28T13:05:09Z`. 1.1.0 sent the placeholder `{REPLACE_WITH_DATETIME}`, which only the backend's HTTP route replaced. `begin()` starts SNTP (`pool.ntp.org`, `time.nist.gov`) and no longer connects itself: `loop()` opens the MQTT session once the clock is set, or after 5 s without an answer, so the session comes up a few seconds later than before. `alexClient.setTimeSource(false)` before `begin()` leaves the clock to the sketch. `AddContextProp()` fills `timeOfSample` in when the property has none or carries the old placeholder. The board needs an answer from an NTP server (DNS, outbound UDP port 123), which 1.1.0 did not: without one the reports carry a time in 1970, and the library says so when it connects and then at most once a minute while reports are sent. - A directive is parsed and handed to the sketch from `loop()`, one per call, in the order of arrival. Up to eight directives of 8188 bytes together wait for it on the heap (`ALEX2ESP_MAX_QUEUED_DIRECTIVES`, `ALEX2ESP_MAX_QUEUED_BYTES`; 1.1.0 queued five tokens), because Alexa sends a group command as one directive per endpoint. A directive that finds no place is dropped, as is one over 2047 bytes (`ALEX2ESP_MAX_DIRECTIVE`); both print an error. - A directive that arrives twice is handled once: the Alex2MQTT broker currently delivers every message twice through a mirror. The repeat is recognised while it arrives, by a hash of its bytes, and takes no place among the waiting directives; a directive that comes again with other bytes is recognised by its `messageId`. The last 16 directives are remembered; the repeat prints `repeated directive ... ignored`. - The subscription delivers the directives of every endpoint of the account. Those for endpoints of another board are recognised by their topic and neither buffered nor parsed. @@ -255,7 +255,7 @@ Behaviour changes: - New: `Alex2ESP::setLogLevel()`, `Alex2ESP::setTimeSource()`, `AlexaDevice::hasEndpointId()`, `AlexaLog`, `AlexaSendResult`. - Removed: the queues and buffers of `AlexaUtils` (`enqueue`, `dequeue`, `dequeueVals`, `enqueueReceive`, `dequeueReceive`, `isQueueEmpty`, `isQueueFull`, `isReceiveQueueEmpty`, `isReceiveQueueFull`, `receivePayload`, `nextMessageId`) and its `log`/`logln`, which printed nothing unless the library was edited; `AlexaUtils::printMemoryInfo()` stays. `MAX_STATUS_REPORT_SIZE` (the limit is `ALEX2ESP_MAX_MESSAGE`). The library no longer includes `ESP8266HTTPClient`. -Memory: `examples/basicLight.cpp` for a D1 mini takes 34,444 bytes of static RAM (1.1.0: 52,768) and 337,145 bytes of flash (1.1.0: 350,885), as PlatformIO reports them (espressif8266 4.2.1, Arduino core 3.1.2). The static RAM was the five 2 KB queue slots, three more 2 KB buffers and the two HTTP clients. SNTP and the time stamp are 1.8 KB of the flash figure. +Memory: `examples/basicLight.cpp` for a D1 mini takes 34,452 bytes of static RAM (1.1.0: 52,768) and 337,401 bytes of flash (1.1.0: 350,885), as PlatformIO reports them (espressif8266 4.2.1, Arduino core 3.1.2). The static RAM was the five 2 KB queue slots, three more 2 KB buffers and the two HTTP clients. SNTP and the time stamp are 1.8 KB of the flash figure. Tests: `pio test -e native` in the repository runs 41 host tests of the receive and publish logic (reassembly of fragments, the directives that wait for `loop()`, repeated directives, the size limits, a heap without room, topics, time stamps). No board is needed. diff --git a/src/Alex2ESP.cpp b/src/Alex2ESP.cpp index 5041aa5..7aeb9ee 100644 --- a/src/Alex2ESP.cpp +++ b/src/Alex2ESP.cpp @@ -38,6 +38,8 @@ Alex2ESP::Alex2ESP() disconnectReason(AsyncMqttClientDisconnectReason::TCP_DISCONNECTED), useSntp(true), beginTime(0), + clockWarned(false), + lastClockWarning(0), lastReconnectTime(0), discoverSubscription(0), directiveSubscription(0), @@ -160,7 +162,7 @@ void Alex2ESP::connectWhenClockIsSet() { return; } - ALEX2ESP_LOGE("clock not set after %lu ms: connecting, reports carry a wrong time until it is set", CLOCK_WAIT_MS); + warnAboutClock(); } state = Alex2ESPState::CONNECTING; @@ -438,7 +440,34 @@ AlexaSendResult Alex2ESP::publish(const char *topic, JsonDocument &doc) void Alex2ESP::timestamp(char *buffer, size_t size) { - AlexaBridgeLogic::formatTimestamp(time(nullptr), buffer, size); + time_t now = time(nullptr); + if (!AlexaBridgeLogic::clockIsSet(now)) + { + warnAboutClock(); + } + AlexaBridgeLogic::formatTimestamp(now, buffer, size); +} + +// The clock is asked for every property of every report: the line is printed when the session opens without the +// time of day and then once per CLOCK_WARNING_MS at most +void Alex2ESP::warnAboutClock() +{ + unsigned long now = millis(); + if (clockWarned && now - lastClockWarning < CLOCK_WARNING_MS) + { + return; + } + clockWarned = true; + lastClockWarning = now; + + if (useSntp) + { + ALEX2ESP_LOGE("the clock is not set, reports carry a time in 1970: no answer from %s or %s (DNS, outbound UDP port 123)", NTP_SERVER_1, NTP_SERVER_2); + } + else + { + ALEX2ESP_LOGE("the clock is not set, reports carry a time in 1970: setTimeSource(false) leaves the clock to the sketch"); + } } // Sends the document whole or not at all, and says which. The caller reports a refusal. diff --git a/src/Alex2ESP.h b/src/Alex2ESP.h index c101921..11b6588 100644 --- a/src/Alex2ESP.h +++ b/src/Alex2ESP.h @@ -73,6 +73,7 @@ public: private: static const unsigned long CLOCK_WAIT_MS = 5000; // How long the first connect waits for SNTP + static const unsigned long CLOCK_WARNING_MS = 60000; // How often an unset clock is reported while it is used static const unsigned long RECONNECT_INTERVAL_MS = 5000; static const unsigned long DISCOVERY_WINDOW_MS = 5000; // How long the backend keeps collecting a discovery answer static const unsigned long DISCOVERY_RETRY_MS = 20; // Pause before a refused discovery publish is tried again @@ -89,6 +90,8 @@ private: AsyncMqttClientDisconnectReason disconnectReason; bool useSntp; unsigned long beginTime; // millis() when begin() ran + bool clockWarned; // The unset clock has been reported + unsigned long lastClockWarning; // millis() of that report unsigned long lastReconnectTime; uint16_t discoverSubscription; // Packet ids of the two SUBSCRIBEs, to match their acknowledgements uint16_t directiveSubscription; @@ -113,6 +116,7 @@ private: //loop processing function void connectWhenClockIsSet(); + void warnAboutClock(); void handleMqttReconnection(); void continueDiscovery(); void publishDiscovery();