Skip to content

port(upstream#2003): join the watchdog loop goroutine in tests - #48

Merged
adminopenclaw8-sketch merged 4 commits into
masterfrom
codex/port-upstream-2003-watchdog-test-join
Sep 18, 2026
Merged

adminopenclaw8-sketch merged 4 commits into
masterfrom
codex/port-upstream-2003-watchdog-test-join

Conversation

@adminopenclaw8-sketch

@adminopenclaw8-sketch adminopenclaw8-sketch commented Sep 13, 2026 •

Copy link
Copy Markdown
Collaborator

Split out of #25 (commit 6e4929b2 there), plus one follow-up commit from this fork. Scope: cmd/ingestor tests only; no production code changes.

Commits

  1. b2ad17a7: port of upstream Kpa-clawbot/CoreScope#2003 by @efiten (merged 2026-09-11, upstream commit 02feb2a88ef05284445f022eb87aca78273fbb4c). Applied with git cherry-pick -x onto master fda24ca5 with no conflicts. Authorship is kept and the patch-id matches the upstream commit.
  2. 3729e12a (new, this fork): a regression test for the helper, plus a correction to its comment. Details below.
  3. 29b3573e (new, this fork, MACMINI): TestStartWatchdogTestLoop_StopIsIdempotent — a different guarantee than commit 2's StopJoinsLoop (that one proves a single stop() waits for the loop to exit; this one proves a second stop() call does not hang). Rebuilt on top of commit 2 after it landed and changed this file's tail; not cherry-picked, no unrelated content carried over. Resolves the "Open point" below.

Problem

TestMQTTStallWatchdog_DisconnectedEscalationThrottled_1749 failed intermittently when run with the other watchdog tests. Those tests only asked their watchdog loop to stop (close(done)) and never waited for it to exit. A loop from an earlier test could therefore still be running when the next test restored livenessRegistry and registered its own sources.

Observed mechanism (corrects commit 1)

Commit 1's message and helper comment say two loops both read LastForceReconnectUnix as 0 before either wrote it. That is not what the local trace showed:

  1. The loop from TestMQTTStallWatchdog_EscalateOnPersistentDisconnect_1749 received its last tick, with a fabricated clock +420 s ahead, and its test returned without waiting for it.
  2. The throttle test registered its source, and its own loop forced a reconnect and stamped LastForceReconnectUnix.
  3. The old loop then ran. Its registry snapshot contained the new source, and it read the non-zero stamp. Measured against its own clock, 420 s ≥ forceReconnectThrottle (60 s) had elapsed, so it forced a second reconnect.

The throttle itself behaved correctly: it was given two clocks for one source. The "both read 0" ordering can also be forced with instrumentation, but it is not the failure that was caught. Commit 1 is left as is (no history rewrite). Commit 2 corrects the comment, and this description replaces the commit message's explanation.

Change

  • Commit 1: startWatchdogTestLoop returns a stop that closes done and waits for the loop goroutine to exit. The _1749 and _1810 watchdog tests now use it.
  • Commit 2:
    • Factors the stop closure into joiningWatchdogStop (behaviour unchanged) so the new test can hold done and exited.
    • Rewrites the helper comment to describe the observed mechanism.
    • Adds TestStartWatchdogTestLoop_StopJoinsLoop:
      • A stalled source makes the first tick call emit, and the callback blocks until the test releases it. This holds the loop inside a tick.
      • stop is called in a goroutine. The test waits until done is closed. That proves the stop goroutine has actually run stop, so "not returned yet" cannot just mean the goroutine was never scheduled.
      • While emit is still blocked, the test asserts that stop has not returned. A joining stop cannot return at this point at all. A 100 ms window bounds only how long a broken close-only stop gets to reveal itself; it cannot fail the correct helper.
      • After release, the test asserts that the loop exits, that stop returns, and that exited was already closed when stop returned (a second check).
      • Ordering uses channels only. The time.After bounds are safety nets that turn a hang into a failure. Deferred cleanup releases emit, joins the stop goroutine, joins the loop and restores the registry on every path, including t.Fatal.

Evidence

Local (macOS arm64, go1.26.0)

Includes the causal diagnosis. It was instrumented only in scratch copies and was not committed.

  • Cause: an instrumented run of the watchdog family on master 693eb045 caught one failure with the event order above. Deterministic scratch probes then forced that order and reproduced it: 2 reconnects on master's harness, exactly 1 with this PR's harness.

  • Regression test, red/green. The mutation (removing <-exited from joiningWatchdogStop) was made only in a scratch copy.

    Variant normal -count=20 -race -count=20
    close-only stop (mutation) 20/20 FAIL at "stop returned while the loop was still blocked inside a tick" (0.00s: caught by the channel check, not by the time window) 20/20 FAIL, same assertion
    joining stop (this PR) 20/20 PASS 20/20 PASS

    An independent reviewer repeated the mutation (50/50 FAIL; 20/20 FAIL with -race -cpu 1) and ran 300 green runs with -race -cpu 1,2,8 -count=100.

  • On 3729e12a:

    • go vet clean.
    • gofmt -l clean on the touched files.
    • git diff --check clean.
    • Watchdog family (-run 'Watchdog|Liveness|StallWatchdog'): -count=20 PASS; -race -count=5 PASS.
    • Full cmd/ingestor (normal and -race): only the known baselines TestPruneOldNeighborMetrics and TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp fail, and both are fixed on current master.
    • Separately, -race reports a pre-existing data race in TestStatsFileWriter_SampledAtMatchesProcIOSampledAt. The stats writer goroutine is never stopped, and cleanup restores readProcSelfIOFn under it. It reproduces 8/30 with -run TestStatsFileWriter alone. It is in files that neither this PR nor current master changes, and it is not addressed here.
  • Scratch merge with current master 99d336e4 (clean merge, no watchdog overlap in master's drift): go vet clean; watchdog family -count=10 and -race -count=3 PASS; full cmd/ingestor PASS.

Linux / GitHub CI

Not instrumented. CI shows only whether the tests pass on Linux. It does not show why the earlier CI failures happened. The same mechanism is likely but was proven only locally.

Dependencies and merge order

  • Independent. No other PR from the split is needed.
  • Recommended position from the split: 22 of 24 (upstream merge order).

Open point (resolved)

Commit 3 (29b3573e) reconciles this. MACMINI's local ffe6b0c6 (on top of b2ad17a7) held the same TestStartWatchdogTestLoop_StopIsIdempotent test but no longer fast-forwarded onto commit 2's head; it was never pushed and stays local/unpushed (preserved under the local ref macmini/preserved-ffe6b0c6-stop-is-idempotent, not deleted). Commit 3 reauthors that same test directly on top of commit 2 as a fresh commit instead. e7f0635f (a diverged local prep-branch commit with ~1000 unrelated lines) was never a candidate for this PR and remains untouched, local, and unpushed. Verification for commit 3: both new tests together, the watchdog/liveness/asyncemit group at -count=5 (180/180 pass, 0 fail) both normal and -race, 0 data races, gofmt/git diff --check clean, no production code touched. The two known full-package baselines above were independently re-confirmed pre-existing on the clean commit-2 base with commit 3 stashed out (TestPruneOldNeighborMetrics 5/5 fail; TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp flaky, 2/5 fail) before commit 3 was added.

GitHub CI result

Run 35304301379 for 3729e12a (commit 2) was in progress at push time; the push then cancelled most of it, presumably via a concurrency group on the branch: final conclusion cancelled. ✅ Go Build & Test finished success before the cancellation; Playwright E2E, Docker Build & Publish, and Deploy Staging were cancelled; Release Artifacts was skipped. A new run started for 29b3573e (commit 3, current head); see that run for the current result.

🤖 Generated with Claude Code

…ng it to stop (Kpa-clawbot#2003)

Verified before merging: on upstream/master `go test ./cmd/ingestor -run TestMQTTStallWatchdog -count=20` fails; on this branch the same command passes. The flake blocked CI on Kpa-clawbot#2000.

(cherry picked from commit 02feb2a)
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@efiten

efiten commented Sep 14, 2026

Copy link
Copy Markdown

Why do I (and other contributors from the original repo) get a message every time you do something on your own repo?
We don't need a message every time you merge in a PR from upstream.

Dennis Jakobsen and others added 2 commits September 18, 2026 05:43
Add TestStartWatchdogTestLoop_StopJoinsLoop. It holds the watchdog loop
inside a tick with a blocking emit callback and checks that stop does not
return until the callback is released and the loop has exited. Ordering
uses channels only. The test waits for done to be closed, so "stop has not
returned" cannot just mean the stop goroutine was not scheduled yet. Every
goroutine is joined on every path, including failures. With a close-only
stop the test fails; with the join it passes.

Factor the stop closure into joiningWatchdogStop so the test can hold done
and exited. startWatchdogTestLoop behaves exactly as before.

Correct the helper comment. The previous commit message and comment said
two loops both read LastForceReconnectUnix as 0 before either wrote it.
The failure traced locally was different: the loop from
EscalateOnPersistentDisconnect_1749, whose clock was 420s ahead, was still
running when the throttle test started. It read the non-zero stamp that
the throttle test's own loop had just written, measured more than
forceReconnectThrottle against its own clock, and forced a second
reconnect.

Test-only. No production code changes.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…pa-clawbot#2003)

startWatchdogTestLoop's doc comment claims "It is safe to call more
than once". joiningWatchdogStop (factored out by the StopJoinsLoop
commit) guards close(done) with sync.Once, so a second call skips
that close and falls straight to <-exited, which returns immediately
once exited is closed. That claim was never exercised. Call stop()
twice and assert the second call returns within 1s, matching this
package's existing timeout/select idiom.

This is a different guarantee than TestStartWatchdogTestLoop_
StopJoinsLoop (previous commit): that test proves a single stop()
call waits for the loop to actually exit, not just for done to close.
This test proves a second, concurrent-or-sequential stop() call does
not hang. Independently authored, rebuilt on top of the StopJoinsLoop
commit after that commit landed and changed the tail of this file;
not cherry-picked, no unrelated changes carried over.

Verified: both new tests together, watchdog/liveness/asyncemit group
(count=5, 180/180 pass, 0 fail), same group under -race (count=5,
180/180 pass, 0 data races), gofmt clean, git diff --check clean,
no production code touched. Full cmd/ingestor package has two
pre-existing issues, independently reproduced on the clean base
(3729e12) with this change stashed out: TestPruneOldNeighborMetrics
fails 5/5 (dated-fixture time-bomb) and TestBackfillTxLastSeen_
ResolvesFromMaxObservationTimestamp is flaky, 2/5 fails with no
watchdog code involved (async-migration timing flake). Neither is
touched or caused by this commit.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
@adminopenclaw8-sketch

Copy link
Copy Markdown
Collaborator Author

MACMINI — reconciliation handoff: both watchdog tests now on this branch

Developer-authorized reconciliation of the two StartWatchdogTestLoop_Stop* tests that were about to collide (see the thread on this PR and cross-session coordination). Test-only. No production code changed.

Commits, in order

SHA Author What it proves
b2ad17a7 efiten (port of upstream Kpa-clawbot#2003) startWatchdogTestLoop's stop joins the loop instead of only asking it to stop
3729e12a Dennis Jakobsen / corescope-8c TestStartWatchdogTestLoop_StopJoinsLoop — a single stop() call does not return until the loop has actually exited (not just until done is closed); factors the closure into joiningWatchdogStop; corrects the historical comment (a 420s-ahead loop was still running, not "both read 0")
29b3573e MACMINI (this reconciliation) TestStartWatchdogTestLoop_StopIsIdempotent — a second, concurrent-or-sequential stop() call does not hang

These are genuinely different guarantees, not duplicates: one is about a single stop() actually joining; the other is about calling stop() twice being safe. Both exercise joiningWatchdogStop's sync.Once + closed-channel behaviour, from different angles.

Provenance of commit 3

Reauthored directly on top of 3729e12a, not cherry-picked from anyone's local work. MACMINI had an earlier local, unpushed commit (ffe6b0c6) with the same test content, built on the old head b2ad17a7; once 3729e12a landed and restructured the tail of the file (factoring out joiningWatchdogStop), ffe6b0c6 no longer applied cleanly. Rather than force it in, I preserved it under a local ref (macmini/preserved-ffe6b0c6-stop-is-idempotent, not deleted, not pushed) and wrote the same test fresh on top of the new head. No unrelated content from any local branch was carried in.

Fresh validation (this push)

  • Both new tests together, focused: PASS

  • Watchdog|Liveness|AsyncEmit group, -count=5: 180/180 PASS, 0 FAIL

  • Same group under -race, -count=5: 180/180 PASS, 0 FAIL, 0 data races

  • gofmt -l: clean · git diff --check: clean

  • git diff --stat b2ad17a7 <head>: 2 files (mqtt_watchdog_stop_join_test.go, mqtt_watchdog_testhelpers_test.go), both test files — confirms test-only scope end to end

  • Full cmd/ingestor package: two pre-existing, unrelated failures, independently reproduced on the clean 3729e12a base with commit 3 stashed out before it was written:

    • TestPruneOldNeighborMetrics — 5/5 fail ("expected 1 row pruned, got 2"), a dated-fixture time-bomb
    • TestBackfillTxLastSeen_ResolvesFromMaxObservationTimestamp — flaky, 2/5 fail with zero watchdog code involved

    Neither is touched by, or caused by, this reconciliation.

Push

Refetched immediately before pushing; remote was still exactly 3729e12a (parent of my commit), so this was a clean fast-forward (3729e12a..29b3573e), no force.

Deviations from the original plan

  • A CI run (35304301379) was in progress on 3729e12a when I pushed. I checked it read-only, confirmed it's keyed immutably to that SHA (a later fast-forward commit doesn't retarget or invalidate it — GitHub still reports it against 3729e12a specifically), and proceeded rather than block on an open-ended wait; a new run (35305214833) started for the new head as expected.
  • I also corrected this PR's description (Commits list, the "Open point" section, CI-result line) to reflect commit 3 landing — precise, reviewed edit; nothing else in the body was touched.

PR #48 is otherwise unchanged: same base, same first two commits, no merge/rebase/force-push/amend. Handing off to whatever review/merge gate this PR normally goes through next.

@adminopenclaw8-sketch

Copy link
Copy Markdown
Collaborator Author

Correction to my handoff comment above: I said run 35304301379 (on 3729e12a) was "unaffected" by the fast-forward push. That was wrong — I checked too early. Its final conclusion is cancelled: ✅ Go Build & Test finished success first, but Playwright E2E, Docker Build & Publish, and Deploy Staging were cancelled, and Release Artifacts was skipped, apparently by a concurrency group on the branch reacting to the new push. Thanks to corescope-8c for catching this. PR description's CI section corrected accordingly.

The comment claimed that losing the sync.Once guard would make a second
stop() call hang, so the test would catch it via the 1s timeout. Verified
by mutation: removing sync.Once instead makes the second close(done) call
panic with "close of closed channel", which fails the test immediately,
not by timing out. The 1s timeout only catches a regression in <-exited's
closed-channel read.

Also states plainly that the two stop() calls are sequential, from the
same goroutine, not concurrent.

Comment-only. No change to the test's assertions, to StopJoinsLoop, or to
production code.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
@adminopenclaw8-sketch
adminopenclaw8-sketch merged commit 37d82e8 into master Sep 18, 2026
6 checks passed
adminopenclaw8-sketch pushed a commit that referenced this pull request Sep 18, 2026
Brings in:
- #64: fix(nodes): separate advert timestamps from confirmed relay activity
- #48: test(ingestor): reconcile watchdog Stop-test coverage (StopJoinsLoop + StopIsIdempotent), fixing the CI watchdog flake this PR previously hit

No conflicts. PR #28's own change (public/rx-coverage.js) is untouched by this merge.
adminopenclaw8-sketch pushed a commit that referenced this pull request Sep 18, 2026
Brings in:
- #64: fix(nodes): separate advert timestamps from confirmed relay activity
- #48: test(ingestor): reconcile watchdog Stop-test coverage (StopJoinsLoop + StopIsIdempotent)

No conflicts. PR #50's own change (channel-rainbow.json, internal/channel/channel_rainbow_test.go) is untouched by this merge. Does not address the row-height test Kpa-clawbot#1122/Kpa-clawbot#1124 failure — that is investigated separately, unresolved.
@efiten

efiten commented Sep 18, 2026

Copy link
Copy Markdown

Please stop mentioning me in every pr you meege from upstream.

Erwin

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants