otbr: poll for the persisted dataset instead of sampling it once #139

Merged
k.renner merged 1 commits from fix/otbr-dataset-check-race into master 2026-07-09 12:11:47 +00:00
Owner

The bug

otbr has had Thread disabled since 2026-06-27. Twelve days. Nothing alerted, because the pod is Running and its liveness probe only watches otbr-agent, not whether Thread is attached.

Live evidence from the running pod, before any restart today:

ot-ctl state      -> disabled
ot-ctl ifconfig   -> down
ot-ctl br state   -> stopped
ot-ctl partitionid-> 0

ot-ctl dataset active
  Active Timestamp: 1654276248
  Network Name: NEST-PAN-339C     <- the dataset was there all along
ot-ctl rcp version
  OPENTHREAD/1.3.0.1; CC13XX_CC26XX   <- radio is fine

The pod's own log, from its single boot:

otbr: no persisted dataset; awaiting bootstrap Job

But otbr-dataset-bootstrap Completed 61 days ago. And restartCount: 0, so the container never got a second chance to notice.

Root cause

The entrypoint waits for ot-ctl state to answer, then samples the dataset once:

for i in $(seq 1 45); do ot-ctl state >/dev/null 2>&1 && break; sleep 2; done
if ot-ctl dataset active 2>&1 | grep -qE "Active Timestamp|Network Name"; then
  ot-ctl ifconfig up; ot-ctl thread start
else
  echo "otbr: no persisted dataset; awaiting bootstrap Job"
fi

otbr-agent answers ot-ctl state as soon as its control socket exists — which is before it has restored the persisted dataset from /var/lib/thread. The check races the restore and loses. The else branch is a dead end: the seed Job only activates Thread on a clean install, so once you land there, nothing ever calls thread start again.

Reproduced today. I restarted otbr (for an unrelated reason — see below) and it printed the identical line, with the dataset present in the pod moments later.

Meanwhile a Nest hub has been serving the mesh's OMR prefix (fdd5:9722:62a8:1::/64, learned by RA from fe80::9558:…), which is presumably why nobody noticed the border router was down.

Fix

Poll the dataset check for up to 60s rather than sampling once. Then poll ot-ctl state after thread start and log the attach result — thread start returns before MLE has attached, so its exit code proves nothing, and a silent disabled is exactly the failure this block exists to prevent.

Two shell details worth calling out, because the script runs under set -euo pipefail:

  • STATE=$(ot-ctl state ... || true) — a failing command inside $( ) would otherwise abort.
  • the final check is a case, not [ … ] && [ … ] && echo. A bare failing test as the last statement of the block would kill the container instead of logging a warning. (I wrote it the wrong way first.)

Verification

  • bash -n clean on the extracted 113-line script.
  • kubectl kustomize kubernetes/apps/otbr builds.
  • Merging this restarts the pod, which is the actual test. Expect:
    otbr: persisted dataset found after N attempt(s); activating Thread
    otbr: Thread attached as <leader|router|child>
    
    and ot-ctl br state → running. If instead you see WARNING Thread not attached after 60s, the dataset restore is not the only problem and we look at the RCP/MLE path next.

Unrelated, confirmed in passing

Today's restart also migrated otbr onto the DHCP macvlan from #135/#137, and that part is clean:

net1 = 10.2.30.129 (DHCP lease)
ip -4 route show default -> default via 10.244.2.60 dev eth0   (exactly one)
ip rule                  -> 32765: from 10.2.30.129 lookup 100

Also verified on shelly-manager: sbr adds no IPv6 rule and moves no IPv6 route, so the fd5f::/64 OMR-route concern I raised in #137 does not apply — sbr only ever touched IPv4. That closes the open question from that PR.

Still open

cni-dhcp-daemon holds leases in memory (no leaseFile, no state dir, /var/lib/cni not mounted). A daemon restart very likely orphans the leases of already-attached pods — they keep the address, nobody renews, and at the 24h expiry the UDM may re-lease it. Mechanism confirmed by inspection; behaviour not yet observed, because renewal is due at T1 = 12h.

## The bug **`otbr` has had Thread `disabled` since 2026-06-27.** Twelve days. Nothing alerted, because the pod is `Running` and its liveness probe only watches `otbr-agent`, not whether Thread is attached. Live evidence from the running pod, before any restart today: ``` ot-ctl state -> disabled ot-ctl ifconfig -> down ot-ctl br state -> stopped ot-ctl partitionid-> 0 ot-ctl dataset active Active Timestamp: 1654276248 Network Name: NEST-PAN-339C <- the dataset was there all along ot-ctl rcp version OPENTHREAD/1.3.0.1; CC13XX_CC26XX <- radio is fine ``` The pod's own log, from its single boot: ``` otbr: no persisted dataset; awaiting bootstrap Job ``` But `otbr-dataset-bootstrap` `Complete`d **61 days** ago. And `restartCount: 0`, so the container never got a second chance to notice. ## Root cause The entrypoint waits for `ot-ctl state` to answer, then samples the dataset **once**: ```sh for i in $(seq 1 45); do ot-ctl state >/dev/null 2>&1 && break; sleep 2; done if ot-ctl dataset active 2>&1 | grep -qE "Active Timestamp|Network Name"; then ot-ctl ifconfig up; ot-ctl thread start else echo "otbr: no persisted dataset; awaiting bootstrap Job" fi ``` `otbr-agent` answers `ot-ctl state` as soon as its **control socket** exists — which is *before* it has restored the persisted dataset from `/var/lib/thread`. The check races the restore and loses. The `else` branch is a dead end: the seed Job only activates Thread on a clean install, so once you land there, nothing ever calls `thread start` again. **Reproduced today.** I restarted `otbr` (for an unrelated reason — see below) and it printed the identical line, with the dataset present in the pod moments later. Meanwhile a Nest hub has been serving the mesh's OMR prefix (`fdd5:9722:62a8:1::/64`, learned by RA from `fe80::9558:…`), which is presumably why nobody noticed the border router was down. ## Fix Poll the dataset check for up to 60s rather than sampling once. Then poll `ot-ctl state` after `thread start` and log the attach result — `thread start` returns before MLE has attached, so its exit code proves nothing, and a silent `disabled` is exactly the failure this block exists to prevent. Two shell details worth calling out, because the script runs under `set -euo pipefail`: - `STATE=$(ot-ctl state ... || true)` — a failing command inside `$( )` would otherwise abort. - the final check is a `case`, not `[ … ] && [ … ] && echo`. A bare failing test as the last statement of the block would **kill the container** instead of logging a warning. (I wrote it the wrong way first.) ## Verification - `bash -n` clean on the extracted 113-line script. - `kubectl kustomize kubernetes/apps/otbr` builds. - **Merging this restarts the pod, which is the actual test.** Expect: ``` otbr: persisted dataset found after N attempt(s); activating Thread otbr: Thread attached as <leader|router|child> ``` and `ot-ctl br state` → `running`. If instead you see `WARNING Thread not attached after 60s`, the dataset restore is not the only problem and we look at the RCP/MLE path next. ## Unrelated, confirmed in passing Today's restart also migrated `otbr` onto the DHCP macvlan from #135/#137, and that part is clean: ``` net1 = 10.2.30.129 (DHCP lease) ip -4 route show default -> default via 10.244.2.60 dev eth0 (exactly one) ip rule -> 32765: from 10.2.30.129 lookup 100 ``` Also verified on `shelly-manager`: `sbr` adds **no IPv6 rule** and moves no IPv6 route, so the `fd5f::/64` OMR-route concern I raised in #137 does not apply — `sbr` only ever touched IPv4. That closes the open question from that PR. ## Still open `cni-dhcp-daemon` holds leases in memory (no `leaseFile`, no state dir, `/var/lib/cni` not mounted). A daemon restart very likely orphans the leases of already-attached pods — they keep the address, nobody renews, and at the 24h expiry the UDM may re-lease it. Mechanism confirmed by inspection; behaviour not yet observed, because renewal is due at T1 = 12h.
k.renner added 1 commit 2026-07-09 12:09:34 +00:00
otbr has had Thread `disabled` since 2026-06-27. `ot-ctl dataset active`
returns NEST-PAN-339C, the seed Job completed 61 days ago, the RCP answers
(OPENTHREAD/1.3.0.1; CC13XX_CC26XX) -- and the stack was simply never
brought up. The pod had 0 restarts, so it never got a second chance.

The entrypoint waits for `ot-ctl state` to answer, then checks for a
persisted dataset exactly once. otbr-agent answers `state` as soon as its
control socket exists, which is before it has restored the dataset from
/var/lib/thread. The check races the restore and loses:

  otbr: no persisted dataset; awaiting bootstrap Job

...after which nothing ever calls `ifconfig up` / `thread start`, because
the seed Job only activates Thread on a clean install. Reproduced exactly
on a restart today, before this fix.

Poll the dataset check for up to 60s instead. Then poll `ot-ctl state`
after `thread start` and log the attach result: `thread start` returns
before MLE has attached, so its exit code proves nothing, and a silent
`disabled` is precisely the failure this block exists to prevent.

Note the `|| true` and the `case` rather than a `[ ... ] && [ ... ] && echo`
chain: this script runs under `set -euo pipefail`, so a bare failing test as
the last statement would kill the container instead of logging a warning.

Verified: `bash -n` clean on the extracted script, `kubectl kustomize`
builds. Merging restarts the pod, which is the real test -- the entrypoint
should now log "persisted dataset found after N attempt(s); activating
Thread" followed by "Thread attached as <state>".

Unrelated but confirmed in passing on today's restart: otbr took its DHCP
lease cleanly under #135/#137 (net1=10.2.30.129, single v4 default via eth0,
sbr rule `from 10.2.30.129 lookup 100`).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
k.renner merged commit 4a481519e0 into master 2026-07-09 12:11:47 +00:00
Sign in to join this conversation.