Repository navigation
port(upstream#1897): stop watchdog force-reconnect racing paho's retry loop - #29
Conversation
…pa-clawbot#1897) Relates to Kpa-clawbot#1335, which was already closed by PR Kpa-clawbot#1336 shipping the naive `client.Disconnect(250); client.Connect()` force-reconnect. That fix has its own bug: liveness.IsConnectedFn (paho's IsConnected()) reports true for the entire time paho is actively retrying, not just when genuinely connected, so the watchdog's stall check cannot tell a half-open TCP socket (the original Kpa-clawbot#1335 case) from a broker that paho is already correctly reconnecting to. Unconditionally calling Disconnect(250) then Connect() on that second, transitional case races paho's status machine and permanently kills its retry loop, requiring another watchdog trigger to recover, sometimes compounding into 100+ minute outages. This is a different failure mode from Kpa-clawbot#1749/PR Kpa-clawbot#1853: that bug is a blocking log.Print() write freezing the entire watchdog loop before ForceReconnectFn is ever called. This bug only manifests once ForceReconnectFn does fire, so the two fixes are independent and touch disjoint files. buildForceReconnectFn now gates Disconnect() on IsConnectionOpen() (true only when status is strictly connected) so it only tears down a genuinely open connection, and logs Connect()'s error token instead of discarding it. (cherry picked from commit 647841c) Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Måling mod en rigtig broker — PR'ens kernepåstand er bekræftet, og effekten er storBranchen er synkroniseret med master Verifikationen er kørt mod en in-process MQTT-broker med den rigtige paho-klient, så den gamle og den nye Det afgørende A/B: broker nede, paho retry'er allerede, watchdoggen udløser
Med realistiske produktions-timings er det endnu skarpere: 40 s efter force-reconnect er den gamle kode DEAD med 0 CONNECT-pakker udstedt. Det er præcis den fejlmekanisme, PR-teksten beskriver — og den er nu observeret, ikke udledt: det gamle Den sag, rettelsen stadig skal kunne klare, er uændret
Identisk. Rettelsen ofrer ikke den case, den blev lavet for. Diskriminatoren holderPåstand (a) og (b) er dermed bekræftet med 0 falske positiver ud af 400 målinger. Påstand (c) ligeledes: 5 s efter Én påstand i kommentaren er for bred — måltKommentaren siger, at Men ikke i tilstanden Den nye kode logger derfor Status på reviewet — ærligtDet uafhængige review blev afbrudt af en ugentlig rate-limit, ikke af et fund. Harnessen nåede at blive skrevet og de ovenstående målinger at blive kørt; jeg har selv kørt dem igen og rapporterer dem her. Det, der ikke nåede at blive afsluttet:
Alle reviewerens probe-filer er fjernet igen; Hvorfor denne PR er PARKERET, ikke mergetOpgavens regler kræver staging før merge for MQTT-/reconnect-ændringer, og det er en race mod paho's baggrundsløkke og en rigtig broker. Staging kan ikke nås herfra: docker-dæmonen kører ikke, Konkret testplan ligger i 🤖 Generated with Claude Code |
Tillæg: storm-raten er nu målt — opgavens eksplicitte kravA/B-kørslen blev færdig. To tilføjelser til tallene ovenfor. Storm-rate, udløst hvert 200. ms i ~10 s mod en nedlagt broker:
Den nye kode rammer paho's egen naturlige retry-kadence præcist — 0,99 mod 1,00 CONNECT/s. Ingen storm: force-reconnect lægger reelt intet oven i det, paho ville gøre alligevel, selv når watchdoggen udløser 50 gange. Og den gamle kode stormer heller ikke — den gør det modsatte: 23 udløsninger gav nul forbindelsesforsøg, fordi retry-løkken allerede var revet ned. Prod-timings, Case B (fuld
Det er den 100+ minutters reconnect-fejl, PR-teksten beskriver, reproduceret i lille skala: uden rettelsen kommer klienten aldrig tilbage af sig selv. 🤖 Generated with Claude Code |
PARKERET — uafhængigt review fandt en BLOCKER på testdækningenImplementeringen er korrekt og en stor, målt forbedring. Men den egenskab, PR'en findes for at beskytte, er ikke pinned af nogen test — og det var netop den gate, denne runde skulle lukke. BlockerenEn compile-valid mutant (M18) holder go func(){ time.Sleep(50*time.Millisecond); client.Disconnect(250) }()Det er den nærliggende "lad os ikke blokere watchdoggen på Disconnect"-refaktorering. Resultat:
Altså: mutanten genskaber præcis den Kpa-clawbot#1897-produktionsfejl, PR'en retter, og ingen test siger fra. M15 er værre: 8 af 18 mutanter overlever, alle compile-valide (alle 19 bestod både Hvorfor testene ikke fanger detDe asserterer en kaldsekvens mod en fake, hvilket er strukturelt. Alt, der bevarer Jeg kørte selv fire mutationer først (fjern garden, invertér den, fjern Hvad der lukker denÉn integrationstest med en rigtig paho-klient mod en in-process broker, der asserterer: efter én force-reconnect mod en nedlagt broker bliver der ved med at komme CONNECT-pakker, og klienten selvhelbreder når brokeren vender tilbage — uden et andet trigger. Den ene test dræber M1, M2, M9, M15 og M18. Der findes ingen in-process broker-helper i repoet i dag (~250 linjer), men der er præcedens for rigtige paho-tests i Implementeringen selv er bekræftet godAlt det adfærdsmæssige består — målt mod en rigtig broker, og i overensstemmelse med min egen uafhængige kørsel:
Hver bærende påstand i PR-kommentaren er efterprøvet mod paho v1.5.0-kildekoden og holder. Revieweren rapporterede i øvrigt selv en fejl i sit eget harness: sekventielle kørsler viste først "3,00× storm", men omvendt rækkefølge inverterede resultatet — det var paho's backoff-vækst hen over vinduet, ikke koden. Det parrede design fjerner artefakten. Øvrige fund (ikke-blokerende)
StatusPARKERET. Integrationssporet fortsætter uden #29 i rækkefølgen 🤖 Generated with Claude Code |
…-1897-watchdog-reconnect-race
…t a real paho client The fake-client tests only assert the IsConnectionOpen/Disconnect/Connect call sequence. A Disconnect moved into a goroutine keeps that sequence and still kills paho's retry loop (review mutants M15/M18), and CI runs the ingestor suite without -race, so nothing caught it. New tests drive the production watchdog action (maybeForceReconnect -> buildForceReconnectFn) against a real paho client built by buildMQTTOpts and a small in-test MQTT broker, counting CONNECT packets at the broker: - broker down, paho retrying, watchdog fires three times: CONNECTs keep arriving and the client reconnects on its own when the broker returns; - half-open socket (IsConnectionOpen true, broker silent): the old socket is dropped and a new session comes up; - paho stopped (disconnected, Kpa-clawbot#1749 escalation): force-reconnect starts a fresh connect without blocking while the broker is down. CI: add a separate -race pass for the ForceReconnect tests only; the full ingestor suite stays without -race. Fork guards untouched. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_0133zLreBhuYtXESMXVBfqno
Review feedback addressed (commit
|
| Mutant | Before (old tests) | After, new tests only, without -race | After, all ForceReconnect tests |
|---|---|---|---|
review M18: else { go func(){ time.Sleep(50ms); Disconnect(250) }() } |
survives (whole suite, 116 s) | killed (retry loop + bug(mqtt): watchdog goroutine goes completely silent — 3 sources stalled 75 min, zero WATCHDOG log lines, no force-reconnect Kpa-clawbot/CoreScope#1749) | killed |
review M15, variant: else { go func(){ Disconnect(250) }() } |
survives (whole suite) | killed | killed |
review M15, literal: go func(){ Disconnect(250) }() unconditionally |
killed by fake (order) | killed (all 3 tests) | killed |
Wait() before Error() |
survives (whole suite) | killed (bug(mqtt): watchdog goroutine goes completely silent — 3 sources stalled 75 min, zero WATCHDOG log lines, no force-reconnect Kpa-clawbot/CoreScope#1749: fn blocks) | killed |
Disconnect(0) |
survives (whole suite) | killed (half-open: dead client) | killed |
pre-fix: stop watchdog force-reconnect from racing paho's own retry loop Kpa-clawbot/CoreScope#1897 code / no guard / || true / IsConnected() as guard |
killed by fake | killed (retry loop dies) | killed |
| invert guard, drop Disconnect, drop Connect, Connect only in guard, guarded Disconnect async | killed by fake | killed | killed |
| drop error log / log without tag | killed by fake | survives (not behavioural) | killed by fake |
| whole body async / Connect async | killed by fake | survives (equivalent) | killed by fake |
Disconnect(5000) |
survives | survives | survives: equivalent |
Totals: 5 of 19 survived before, 1 of 19 after. The one left, Disconnect(5000), is equivalent: Disconnect returns as soon as the disconnect is done (from connected that is immediate), so quiesce only caps the worst case, and the watchdog already runs the function in a goroutine. Every kill of M15, M18, the pre-fix: stop watchdog force-reconnect from racing paho's own retry loop Kpa-clawbot/CoreScope#1897 code, Disconnect(0) and Wait() was repeated 5/5.
With -race the old fake tests do catch M15/M18 here (5–8 DATA RACE on fakeClient.callOrder), but CI didn't run -race for the ingestor.
Stability (correct code): -count=20 without -race: 60/60 PASS. -count=10 with -race: 30/30 PASS, 0 DATA RACE. -count=5 in parallel with the whole suite: 15/15 PASS. The whole cmd/ingestor suite: ok (115.7 s). go vet: clean.
CI change (.github/workflows/deploy.yml): new step Race-check Go ingestor force-reconnect right after the ingestor test step. It runs go test -race -count=1 -timeout 5m -run 'ForceReconnect' ./... in cmd/ingestor, which covers 10 tests and takes about 6 s locally. The full ingestor suite still runs without -race. Fork guards are untouched.
The PR stays non-draft and is neither marked ready nor merged.
Generated by Claude Code
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
3 participants
Split out of #25 (commit
43863a09there). This branch holds exactly one upstream change plus behavioural tests for it, so it can be reviewed, tested and reverted on its own.Upstream
Kpa-clawbot/CoreScope#1897byJonher937, merged 2026-09-02.647841c99033c3574897f288b144f5e82721b4c4.git cherry-pick -xonto masterfda24ca5. Upstream authorship is kept, and the commit message carries the(cherry picked from commit …)line. The patch-id is identical to the upstream commit.Problem
The MQTT stall watchdog's forced reconnect did
client.Disconnect(250); client.Connect(). paho'sIsConnected()is also true while paho's own auto-reconnect loop is retrying, so the watchdog fires during normal retries too.Disconnectthen tears down paho's retry loop. The immediateConnect()runs while the client is stilldisconnectingand fails, and that error was discarded. The source then has nothing retrying until the next watchdog trigger, which can repeat and compound into long outages.Change
buildForceReconnectFnonly callsDisconnect(250)whenclient.IsConnectionOpen()is true. That is status strictly connected, i.e. the genuine half-open-socket case.Connect()and logs a token error instead of discarding it.IsConnectionOpenexists in the pinnedpaho.mqtt.golang v1.5.0. The changed production lines are identical to upstream.Tests
cmd/ingestor/mqtt_force_reconnect_race_test.go(from upstream) checks the call sequence against a fake client.Disconnectinto a goroutine in the retry branch. It reproduces the fix: stop watchdog force-reconnect from racing paho's own retry loop Kpa-clawbot/CoreScope#1897 outage but stayed green, even under-race.cmd/ingestor/mqtt_force_reconnect_paho_test.go(commitcb7dc518) closes that gap. It drives a real paho client built withbuildMQTTOptsagainst a small in-test broker on127.0.0.1:0, and triggers through the watchdog's own path (maybeForceReconnect→buildForceReconnectFn). Its tests:Race-check Go ingestor force-reconnect, runsgo test -race -run 'ForceReconnect'for the ingestor. The full ingestor suite still runs without-race.Verification
Disconnect(5000)only raises a worst-case bound. The goroutine mutants are killed without-race, 5/5 deterministic.-count=2060/60;-count=10 -race30/30, 0 data races; 15/15 while the full suite ran in parallelcb7dc518ok … 5.674s), Playwright E2E, local Docker build. GHCR login/push, release, staging deploy and badges skipped.An earlier A/B against a real broker showed the difference: the old code issued 0 CONNECTs after a forced reconnect and never recovered, while the new code tracks paho's own retry rate (0.99 vs 1.00 CONNECT/s) and recovered in about 19 s. The details are in the PR comments.
Scope against master
cmd/ingestor/main.go, the two test files above, and one added test step in.github/workflows/deploy.yml. Fork guards are untouched.Known follow-ups (not in this PR)
Connect()while the status isconnecting.mqtt_watchdog.go, recommended by the review as a separate issue.Review note
The behavioural tests were written in a separate session. The production change is an unchanged upstream cherry-pick. A post-merge review of the test commit is planned.
🤖 Generated with Claude Code