Directive 2: MQTT reconnect + re-subscribe compliance verifier
paho reconnects on its own but does not restore subscriptions. A client without an on_connect re-subscribe holds a live socket with no subscription and goes silently deaf -- no error, no log. That is how voice_bridge died on 2026-10-13. All in-scope .13 clients already re-subscribe on every connect and log it (voice_bridge, Jervis voice-agent, IUC control-service, IUC kids Android app). The Hub has no MQTT client, n8n nodes are publish-only, Home Assistant re-subscribes by design, and the ESP32 firmware is owned by Directive 3. Add: - docs/mqtt-reconnect-compliance.md: inventory with file:line evidence and the live verification result. - verify/mqtt_reconnect_check.sh: static source check plus an opt-in --live check that restarts the .13 broker and asserts re-subscribe within 60s. Live check 2026-10-14T00:01:18Z: .13 mosquitto restarted; voice_bridge and control-service re-subscribed and ESP32 reconnected within 3s. Co-Authored-By: Paperclip <noreply@paperclip.ing>
This commit is contained in:
Paperclip Builder
95
docs/mqtt-reconnect-compliance.md
Normal file
95
docs/mqtt-reconnect-compliance.md
Normal file
@@ -0,0 +1,95 @@
|
|||||||
|
# MQTT reconnect rule — compliance
|
||||||
|
|
||||||
|
Directive 2 of the Hub Fixes spec. Rule: **every MQTT client in the lab must
|
||||||
|
reconnect AND re-subscribe, and log the re-subscription.**
|
||||||
|
|
||||||
|
paho (and most MQTT libraries) reconnect automatically. They do **not** restore
|
||||||
|
subscriptions. The client then holds a live TCP socket with no subscription and
|
||||||
|
goes silently deaf — no error, no log. This is how `voice_bridge` died on
|
||||||
|
2026-10-13 and stayed dead for two days.
|
||||||
|
|
||||||
|
The rule is enforced by an `on_connect` (or equivalent) handler that re-subscribes
|
||||||
|
on **every** connect, not only the first one.
|
||||||
|
|
||||||
|
## Client inventory
|
||||||
|
|
||||||
|
| # | Client | Broker | Code (file:line) | Re-subscribe | Logs | Status |
|
||||||
|
|---|--------|--------|------------------|--------------|------|--------|
|
||||||
|
| 1 | `voice_bridge` (`Bridge_Voice`) | `.13:1883` | `voice_bridge/mqtt_audio_bridge.py:229-242`, registered at `:250` | yes | yes | OK |
|
||||||
|
| 2 | `voice_bridge` (`Bridge_HA`) | `.30:1883` | `voice_bridge/mqtt_audio_bridge.py:254-256` | n/a | n/a | publisher only |
|
||||||
|
| 3 | Jervis voice agent | `.30:1883` | `voice-agent/app.py:1190-1203`, registered at `:1214` | yes | yes | OK |
|
||||||
|
| 4 | IUC Control Service | `.13:8883` | `internet_use_control/internal/mqtt/link.go:156,222-246` | yes | yes | OK |
|
||||||
|
| 5 | IUC kids Android app | `.13:8883` | `.../kids/MqttController.kt:123,160-163,171-175` | yes | yes | OK |
|
||||||
|
| 6 | Home Assistant | `.30:1883` | HA core, not editable here | yes (by design) | HA core | not verifiable from `.13` |
|
||||||
|
| 7 | n8n MQTT nodes | `.13:1883` | workflow `front-door-cam` | n/a | n/a | publish only |
|
||||||
|
| 8 | Hub | none | `central_ai_llm_master/src` (no paho import) | n/a | n/a | no MQTT client |
|
||||||
|
| 9 | ESP32 voice assistant | `.13:1883` | `sam/voice_assistant` firmware | partial | no | Directive 3 |
|
||||||
|
| 10 | ESP32 front-door doorbell | `.13:1883` | `sam/front_door_cam_controller` | n/a | n/a | connect → publish → disconnect per event |
|
||||||
|
|
||||||
|
Notes:
|
||||||
|
|
||||||
|
- **Row 1** `_on_voice_connect` (`:229`) subscribes to `voice/audio_stream` and
|
||||||
|
`voice/status` (`:241`) and prints `[bridge] subscribed ...` (`:242`).
|
||||||
|
- **Row 3** re-subscribes both `homeassistant/voice/text` and
|
||||||
|
`homeassistant/voice/announce` and prints `[mqtt] subscribed ...`.
|
||||||
|
- **Row 4** `handleConnect` runs on every connect (`:222`), subscribes
|
||||||
|
`restrict/+/status` and `restrict/+/telemetry` (`:234`), and logs
|
||||||
|
`mqtt subscribed` (`:244`). It also logs `mqtt connection lost` (`:160`).
|
||||||
|
- **Row 5** sets `isAutomaticReconnect = true` (`:123`), subscribes in the
|
||||||
|
`connectComplete` callback on reconnects (`:171-175`), and logs both events.
|
||||||
|
- **Row 6** Home Assistant's MQTT integration re-subscribes internally. The HA
|
||||||
|
OS VM (`.30`) has no shell access from `.13`, so this row is not verified here.
|
||||||
|
- **Row 8** The Hub has no paho import and no `go.sum`; `/health` reports a
|
||||||
|
hardcoded `"mqtt":"unknown"`. Adding an MQTT client to the Hub is a new
|
||||||
|
feature and belongs in `central_ai_llm_master`.
|
||||||
|
- **Row 9** The firmware re-subscribe is not an `on_connect` handler, only
|
||||||
|
re-subscribes `TOPIC_STATUS`, and has no heartbeat. Owned by Directive 3
|
||||||
|
(AUD-93).
|
||||||
|
- **Row 10** connects, publishes one event, and disconnects. There is no
|
||||||
|
subscription to restore, so the silent-deafness failure mode does not apply.
|
||||||
|
It is also outside this project's scope (`sam/voice_assistant` only).
|
||||||
|
|
||||||
|
## Live verification — 2026-10-14T00:01:18Z
|
||||||
|
|
||||||
|
The `.13` `mosquitto` container was restarted. All in-scope `.13` clients were
|
||||||
|
back on the broker and re-subscribed within **3 seconds**.
|
||||||
|
|
||||||
|
Broker restart:
|
||||||
|
|
||||||
|
```
|
||||||
|
restart started: 2026-10-14T00:01:18Z
|
||||||
|
broker accepting connections again after ~2s
|
||||||
|
```
|
||||||
|
|
||||||
|
Client evidence (docker logs, UTC):
|
||||||
|
|
||||||
|
```
|
||||||
|
voice_bridge 2026-10-14T00:01:19.703Z [bridge] subscribed voice/audio_stream + voice/status
|
||||||
|
control-service 2026-10-14T00:01:18.702Z WARN mqtt connection lost ... err=EOF
|
||||||
|
control-service 2026-10-14T00:01:19.750Z INFO mqtt connected
|
||||||
|
control-service 2026-10-14T00:01:19.750Z INFO mqtt subscribed topic=restrict/+/status
|
||||||
|
control-service 2026-10-14T00:01:19.751Z INFO mqtt subscribed topic=restrict/+/telemetry
|
||||||
|
```
|
||||||
|
|
||||||
|
Broker log (epoch `1791936079` = 00:01:19Z):
|
||||||
|
|
||||||
|
```
|
||||||
|
1791936079: New client connected from 192.168.20.20:62320 as ESP32Mic
|
||||||
|
1791936079: New client connected from 192.168.20.13:36065 as Bridge_Voice
|
||||||
|
1791936079: New client connected from 172.18.0.1:41902 as control-service
|
||||||
|
```
|
||||||
|
|
||||||
|
Elapsed from restart start to every client re-subscribed: **~3 s** (limit 60 s).
|
||||||
|
|
||||||
|
## Re-run
|
||||||
|
|
||||||
|
```bash
|
||||||
|
# static check: source has an on_connect re-subscribe + log for every client
|
||||||
|
verify/mqtt_reconnect_check.sh
|
||||||
|
|
||||||
|
# live check: restart the broker and assert re-subscription within 60s
|
||||||
|
verify/mqtt_reconnect_check.sh --live
|
||||||
|
```
|
||||||
|
|
||||||
|
The live check restarts the shared `.13` broker. It briefly interrupts voice
|
||||||
|
intake and the kids' device control plane. Run it at a low-impact moment.
|
||||||
114
verify/mqtt_reconnect_check.sh
Executable file
114
verify/mqtt_reconnect_check.sh
Executable file
@@ -0,0 +1,114 @@
|
|||||||
|
#!/usr/bin/env bash
|
||||||
|
#
|
||||||
|
# Directive 2 — MQTT reconnect rule verifier (Hub Fixes).
|
||||||
|
#
|
||||||
|
# paho reconnects on its own but does NOT restore subscriptions. A client that
|
||||||
|
# has no on_connect re-subscribe handler holds a live socket with no
|
||||||
|
# subscription and goes silently deaf — no error, no log. See
|
||||||
|
# docs/mqtt-reconnect-compliance.md.
|
||||||
|
#
|
||||||
|
# Usage:
|
||||||
|
# verify/mqtt_reconnect_check.sh # static source check (safe)
|
||||||
|
# verify/mqtt_reconnect_check.sh --live # restart the .13 broker and
|
||||||
|
# # assert re-subscribe within 60s
|
||||||
|
#
|
||||||
|
# The --live run restarts the shared .13 mosquitto container. It briefly
|
||||||
|
# interrupts voice intake and the kids' device control plane. Run it at a
|
||||||
|
# low-impact moment. Every docker call is bounded with `timeout`.
|
||||||
|
set -u
|
||||||
|
|
||||||
|
BROKER_CONTAINER="${BROKER_CONTAINER:-mosquitto}"
|
||||||
|
VOICE_BRIDGE_CONTAINER="${VOICE_BRIDGE_CONTAINER:-voice_bridge}"
|
||||||
|
CONTROL_CONTAINER="${CONTROL_CONTAINER:-webrestrict-control}"
|
||||||
|
WINDOW="${WINDOW:-60}" # seconds allowed for re-subscribe
|
||||||
|
DOCKER_TIMEOUT="${DOCKER_TIMEOUT:-20}"
|
||||||
|
|
||||||
|
LIVE=0
|
||||||
|
[ "${1:-}" = "--live" ] && LIVE=1
|
||||||
|
|
||||||
|
# Client sources: name|path|on_connect pattern|subscribe pattern|log pattern
|
||||||
|
CLIENTS=(
|
||||||
|
"voice_bridge |/home/sam/voice_bridge/mqtt_audio_bridge.py|_on_voice_connect|client\\.subscribe\\(\\[\\(VOICE_TOPIC_AUDIO|\\[bridge\\] subscribed"
|
||||||
|
"voice-agent |/home/sam/voice-agent/app.py|def on_connect|client\\.subscribe\\(\\[\\(topic|\\[mqtt\\] subscribed"
|
||||||
|
"control-svc |/home/sam/paseo/projects/internet_use_control/internal/mqtt/link.go|SetOnConnectHandler|c\\.Subscribe\\(sub\\.topic|mqtt subscribed"
|
||||||
|
"kids-android |/home/sam/paseo/projects/internet_use_control/android/app/src/main/java/au/audasmedia/webrestrict/kids/MqttController.kt|connectComplete|isAutomaticReconnect|c\\.subscribe\\(prefs\\.deviceTopic|subscribed to"
|
||||||
|
)
|
||||||
|
|
||||||
|
status() { printf '%-14s %s\n' "$1" "$2"; }
|
||||||
|
|
||||||
|
static_check() {
|
||||||
|
echo "== static check: on_connect re-subscribe + log =="
|
||||||
|
local row name path onc sub log rc=0
|
||||||
|
for row in "${CLIENTS[@]}"; do
|
||||||
|
IFS='|' read -r name path onc sub log <<<"$row"
|
||||||
|
name="$(echo "$name" | xargs)"
|
||||||
|
if [ ! -f "$path" ]; then
|
||||||
|
status "$name" "SKIP (source not on this host: $path)"
|
||||||
|
continue
|
||||||
|
fi
|
||||||
|
local ok="ok"
|
||||||
|
grep -qE "$onc" "$path" || ok="MISSING on_connect"
|
||||||
|
grep -qE "$sub" "$path" || ok="MISSING subscribe"
|
||||||
|
grep -qE "$log" "$path" || ok="MISSING log"
|
||||||
|
if [ "$ok" = "ok" ]; then
|
||||||
|
status "$name" "OK $path"
|
||||||
|
else
|
||||||
|
status "$name" "FAIL $ok ($path)"
|
||||||
|
rc=1
|
||||||
|
fi
|
||||||
|
done
|
||||||
|
return $rc
|
||||||
|
}
|
||||||
|
|
||||||
|
broker_ready() {
|
||||||
|
timeout "$DOCKER_TIMEOUT" docker exec "$BROKER_CONTAINER" \
|
||||||
|
mosquitto_sub -h localhost -p 1883 -t '$SYS/broker/uptime' -C 1 -W 3 \
|
||||||
|
>/dev/null 2>&1
|
||||||
|
}
|
||||||
|
|
||||||
|
live_check() {
|
||||||
|
local t0 epoch i ready=0
|
||||||
|
t0="$(date -u +%Y-%m-%dT%H:%M:%SZ)"
|
||||||
|
epoch="$(date +%s)"
|
||||||
|
echo "== live check: restart $BROKER_CONTAINER at $t0 =="
|
||||||
|
|
||||||
|
timeout $((DOCKER_TIMEOUT + 20)) docker restart "$BROKER_CONTAINER" || {
|
||||||
|
echo "FAIL: could not restart $BROKER_CONTAINER"; return 1; }
|
||||||
|
|
||||||
|
for i in $(seq 1 15); do
|
||||||
|
if broker_ready; then ready=1; echo "broker back after ~$((i * 2))s"; break; fi
|
||||||
|
sleep 2
|
||||||
|
done
|
||||||
|
[ "$ready" = 1 ] || { echo "FAIL: broker did not come back within 30s"; return 1; }
|
||||||
|
|
||||||
|
local deadline=$(( $(date +%s) + WINDOW ))
|
||||||
|
local bridge=0 control=0 esp=0
|
||||||
|
while [ "$(date +%s)" -lt "$deadline" ]; do
|
||||||
|
[ "$bridge" = 0 ] && timeout "$DOCKER_TIMEOUT" docker logs "$VOICE_BRIDGE_CONTAINER" --since "$t0" 2>&1 \
|
||||||
|
| grep -q '\[bridge\] subscribed' && bridge=1
|
||||||
|
[ "$control" = 0 ] && timeout "$DOCKER_TIMEOUT" docker logs "$CONTROL_CONTAINER" --since "$t0" 2>&1 \
|
||||||
|
| grep -q 'mqtt subscribed' && control=1
|
||||||
|
[ "$esp" = 0 ] && timeout "$DOCKER_TIMEOUT" docker exec "$BROKER_CONTAINER" sh -c \
|
||||||
|
"awk -v t=$epoch -F: '/New client connected/ {if (\$1+0>=t) print}' /mosquitto/log/mosquitto.log" 2>/dev/null \
|
||||||
|
| grep -q 'ESP32Mic' && esp=1
|
||||||
|
[ "$((bridge + control + esp))" = 3 ] && break
|
||||||
|
sleep 2
|
||||||
|
done
|
||||||
|
|
||||||
|
local elapsed=$(( $(date +%s) - epoch ))
|
||||||
|
status "voice_bridge" "$([ "$bridge" = 1 ] && echo "OK re-subscribed" || echo "FAIL no re-subscribe")"
|
||||||
|
status "control-svc" "$([ "$control" = 1 ] && echo "OK re-subscribed" || echo "FAIL no re-subscribe")"
|
||||||
|
status "ESP32Mic" "$([ "$esp" = 1 ] && echo "OK reconnected (re-subscribe is Directive 3)" || echo "FAIL no reconnect")"
|
||||||
|
echo "elapsed: ${elapsed}s (window ${WINDOW}s)"
|
||||||
|
[ "$((bridge + control + esp))" = 3 ]
|
||||||
|
}
|
||||||
|
|
||||||
|
rc=0
|
||||||
|
static_check || rc=1
|
||||||
|
if [ "$LIVE" = 1 ]; then
|
||||||
|
echo
|
||||||
|
live_check || rc=1
|
||||||
|
fi
|
||||||
|
|
||||||
|
if [ "$rc" = 0 ]; then echo "RESULT: PASS"; else echo "RESULT: FAIL"; fi
|
||||||
|
exit "$rc"
|
||||||
Reference in New Issue
Block a user