From cfe7b15f0304345beef068707da9ec346b259e33 Mon Sep 17 00:00:00 2001 From: Paperclip Builder Date: Wed, 14 Oct 2026 11:03:33 +1100 Subject: [PATCH] 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 --- docs/mqtt-reconnect-compliance.md | 95 +++++++++++++++++++++++++ verify/mqtt_reconnect_check.sh | 114 ++++++++++++++++++++++++++++++ 2 files changed, 209 insertions(+) create mode 100644 docs/mqtt-reconnect-compliance.md create mode 100755 verify/mqtt_reconnect_check.sh diff --git a/docs/mqtt-reconnect-compliance.md b/docs/mqtt-reconnect-compliance.md new file mode 100644 index 0000000..f3a4617 --- /dev/null +++ b/docs/mqtt-reconnect-compliance.md @@ -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. diff --git a/verify/mqtt_reconnect_check.sh b/verify/mqtt_reconnect_check.sh new file mode 100755 index 0000000..649178c --- /dev/null +++ b/verify/mqtt_reconnect_check.sh @@ -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"