Report an unset clock when the session opens and once a minute while reports are sent

When no NTP server answers (DNS for the pool fails, outbound UDP port 123 is blocked) the bridge connects after 5 s and every report carries a timeOfSample in 1970 for as long as the board runs. The only trace was one line at boot. 1.1.0 did not need the time of day: the HTTP route of the backend stamped the reports.

Alex2ESP::timestamp() now checks the clock it reads. While it is not set, the line that says so is printed when the session opens and then at most once per 60 s while reports are built; timestamp() runs once per property, so the line is limited by time and not per call. The line names what to check: "the clock is not set, reports carry a time in 1970: no answer from pool.ntp.org or time.nist.gov (DNS, outbound UDP port 123)", or, after setTimeSource(false), that the clock is left to the sketch. It replaces "clock not set after 5000 ms: ...".

For a sketch: the reports are sent as before, with the time the clock has. The readme says in its Session paragraph that the board has to reach an NTP server.

Measured with the bridge built for the host against a fake MQTT client (not in the repository), clock never set, a report of two properties every 10 s for 300 s: 30 reports sent, the line printed once at the connect and 5 times in the 300 s; with the clock set, not at all.

Not checked here: what Alexa does with a report stamped 1970. That needs the board (TEST-PLAN 3.1, last row).

examples/basicLight.cpp for d1_mini, static RAM / flash in bytes: 34,444 / 337,145 -> 34,452 / 337,401, no warnings. 41 host tests pass.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
David 2026-09-28 15:58:49 +00:00
parent 6fe8311a6f
commit 39717d5287
3 changed files with 38 additions and 5 deletions

View file

@ -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 `<root>/discover` and `<root>/+/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 `<root>/discover` and `<root>/+/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 `<root>/discover` the library answers with one discovery object per device on `<root>/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 <endpointId>` 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 `<root>/<endpointId>/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 `<root>/<endpointId>/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 `<root>/+/alexaDirective`, where Alex2MQTT has always published the whole directive, instead of fetching it over HTTP with the token from `<root>/<endpointId>/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 `<root>/<endpointId>/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.

View file

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

View file

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