Repository navigation
fix(e2e): bound the dataplane capture collector by wall clock - #4640
Conversation
|
Navigate logical layers of code changes, visualize relationships, and explore their blast radius. No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Repository: cozystack/cozystack/.coderabbit.yaml Review profile: CHILL Plan: Advanced Run ID: 📒 Files selected for processing (2)
🚧 Files skipped from review as they are similar to previous changes (1)
Included review availability: This review used your included allowance. Your plan provides up to 8 included reviews per hour; 7 remain after this review. 📝 WalkthroughPriority: ⬇️ Low Change: Bug fix Merge Risk: ⚪ Minimal · up to This update adjusts the data-plane capture tests and documentation for the new wall-clock budget. No concrete defects were identified, so it is ready to merge. One test may occasionally fail on a one-second timing margin; this was already noted and is non-blocking. Security Architecture ReviewSecurity architecture risk: 🔵 Low · up to The change improves failure containment without introducing a production-facing interface or changing tenant permissions. Risk remains low because these diagnostics collect host-cluster network information, while report access controls and concurrent standalone execution have not been established. Retained concerns Security review detailsSecurity Blast Radius
Trust Boundaries and Controls
Resilience and Maintainability Implications
🚥 Pre-merge checks | ✅ 3 | ❌ 2❌ Failed checks (2 warnings)
✅ Passed checks (3 passed)
Full details: Linked Issues checkExplanation The PR implements the coding objectives for [ Resolution Add a mutation test for [ Full details: Docstring CoverageExplanation Docstring coverage is 76.00% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 25 functions across 3 files. (1 skipped: 1 unsupported.)
✨ Finishing Touches 💡 1📝 Generate docstrings 💡
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
myasnikovdaniil
left a comment
There was a problem hiding this comment.
Approve, nothing blocks. All non-blocking, the flaky test inline too.
COZY_DATAPLANE_LB_RESERVE=03 at hack/capture-dataplane.bats:3173 doesn't test leading zero strip, because 03 is valid octal and 08 is not (without the strip dash aborts with exit 2). Also default DP_LB_RESERVE=90 is not pinned by any test, with default 0 whole suite stays green.
| SHIM | ||
| chmod +x "$d/bin/kubectl" "$d/bin/timeout" | ||
| rc=0 | ||
| PATH="$d/bin:$PATH" COZY_DATAPLANE_LIST_TIMEOUT=3 COZY_DATAPLANE_BUDGET=94 COZY_DATAPLANE_LB_RESERVE=90 \ |
There was a problem hiding this comment.
Non-blocking. This test has one second of margin. Pod section is 4s (94 - 90) and list bound is 3s, so if the clock ticks to the next second between DP_T0 and first dp_run, bound reaches the deadline and the collector blames the budget. It is right to do so, and test fails.
Window is about 6-10 ms, so up to 1% of runs. Shifting first date +%s one second back reproduces it. With COZY_DATAPLANE_LIST_TIMEOUT=2 and own 2s timeout in the assertion margin is 2 seconds.
There was a problem hiding this comment.
Fixed in 57b5c83: the pod section is now 10s against the same 3s list bound, so a one-second tick can't reach the deadline anymore. With DP_T0 shifted one second back the old test goes red and the new one stays green. The push dropped your approval, so I need a re-approval.
The per-pod capture file joined namespace and pod name with a hyphen, which both may contain, so a-b/c and a/b-c wrote the same file and the second capture silently replaced the first. An underscore can appear in neither, so it keeps every pod apart. The file was also truncated on each run while capture-notes.txt beside it accumulates, leaving notes from two runs next to evidence from one. It now appends with the same run separator the notes use. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
…bles POSIX sh has no local scope, so every assignment in a function lands in the caller. capture_node wrote `node`, the variable of the loop that calls it, and capture_lb_node wrote the LB loop's _lbip, _np, _epip and _of. Both stayed harmless only because each caller passed what it already held; any other argument would have made the rest of the iteration read another node's pods and file them under the right name. Both functions now use their own prefix, like the newer helpers in the file, and a static test fails when a function assigns a name that a `read -r` loop or another scope also owns. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
`cilium-dbg bpf lb list` ran only inside the LoadBalancer path, which is entered only when a LoadBalancer IP fails its probe. The map describes every service translation on the node, so a pod that cannot reach a ClusterIP left no record of which backend the VIP resolved to or whether a backend that stopped answering was still in the map. It now runs unfiltered in the per-node capture, which runs for the node of each affected pod the collector reaches. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
Three collector tests shrank both per-read bounds to one second to make the read under test fail fast. The same bounds also cover the reads that must answer, so on a loaded machine the service, endpointslice or pod list is cut instead, the collector correctly takes another branch, and the test fails as if the code under test had regressed. A `timeout` shim on PATH now cuts only the reads whose argv the test names and runs the rest unbounded against the instant stub, so the cut is the input rather than a race. A cut read that bypasses `timeout` still reaches the stub's sleep and runs into the test's own backstop. The tests also assert the collector finished on its own and the decision line it logs, not only that a file exists. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The fan-out caps counted pods and LoadBalancers while both callers' backstops count seconds, and a single affected pod's worst case already ran past the 300s Chainsaw one. No count could be made to fit, and a cut-off run lost whatever came last, which was always the LoadBalancer capture. Every kubectl call now goes through dp_run, which clips the call's bound to what is left of a run-wide budget sized under the smaller backstop and starts nothing once it is spent. The pod section stops a reserve short of the end so the LoadBalancer section always gets time to start. A read cut by a clipped bound quotes the bound it ran under, a read never started says so instead of naming a timeout, and a section that runs out of budget names what it did not capture. Tests pin the budget against both callers' backstops, the behaviour on a cluster where every read hangs, and that no kubectl call bypasses dp_run, listing any that does by line. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
A call dp_run refuses for a spent budget returned silently, and every exec block swallows its status, so a capture the budget ran out in the middle of kept only section headers. A header with nothing under it reads as a command that found nothing, and the notes said nothing either, because the loops only decline whole pods and LBs. The refusal now goes to stderr, which lands in the block it emptied, and capture-notes.txt gets one line per run. The OVS interface lookup also stops calling a failed, cut or refused lookup an absent interface. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The per-node lookup memo keeps a cutoff so a hung lookup is not paid for twice. Once bounds are clipped to the budget, a lookup can be cut after a second or two because the pod section's deadline arrived, and caching that made the LoadBalancer section report the component as unknown for the node while its reserve still had time to ask. A cutoff is now cached only when the lookup ran under its full bound. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The per-LB capture and its two tcpdump files joined namespace and Service name with a hyphen, which both may contain, so a-b/c and a/b-c wrote the same files, and each run truncated them while the notes beside them accumulate. They now use the separator and the run marker the per-pod files use. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The pod section stops a reserve short of the end of the budget and the LoadBalancer section keeps starting calls after it, but a refusal was reported as the whole run's budget running out, which the LB capture written below it contradicts. The note was also deduplicated once per run, so the LB section running out later left no line of its own. Refusals now name their section, and the note is written once per section. Both budget knobs are also read as decimal: shell arithmetic took a leading zero for octal, so 08 aborted the run before it wrote a note and 010 meant 8. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
…ackstop The collector's default budget is sized under the 300s Chainsaw backstop. The cozytest.sh caller allows 600s, and on the default it would give up more than half of that window, so it passes a budget matching its own backstop. The budget test reads each caller's override and fails when a budget leaves more of its backstop unused than the backstop's kill grace. The Chainsaw call-site comment still described the fan-out caps as the bound, and the e2e testing guide described an EndpointSlice exception to the notes contract that the code does not have; both now describe what the collector does. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
…topped The budget can run out inside one capture rather than between them. A node lookup refused by dp_run was then written up as a lookup that did not answer, an LB probe whose cni-server lookup was refused as the same, and a probe exec refused, or cut by a bound the deadline had shortened, as a node with no cni-server or no probe client. Each names a cause that never happened. The lookup's own status now reaches its callers, the node capture says the lookup was not asked, and the probe reports a "spent" outcome that the decision weighs like an unrun probe and the reason line attributes to the section's budget. A reserve at least as large as the budget is also named, since the pod section then starts no call at all. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
A few reads that go through dp_run still failed or fell back without a trace. A speaker log read that failed looked like a speaker that never announced the address; it now writes a note. The endpoint tcpdump's fallback to the geneve interface is stated in the LB capture. The node capture now carries the run separator the pod and LB files use, through one helper. Two budget interactions named a cause that never happened. A per-read timeout knob of zero made every read look refused by the budget, and a value timeout cannot parse failed every read with 125, reported as kubectl failing; both knobs are now validated like the budget ones. An LB probe whose cni-server lookup the deadline cut was reported as a second, unanswered lookup; it now counts as stopped by the budget. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
Once bounds are clipped to the budget, a cutoff has two meanings: the call's own bound fired, or the deadline shortened it. Node lookups cut the second way were still written up as lookups that did not answer, a cause about the cluster that nothing observed. And the section note was written only when a call was refused, so when the deadline cut a section's last call the truncated capture carried no word about the budget at all. A lookup cut under a bound the deadline shortened now names the budget in the node capture, the endpoint interface lookup and the LB probe, decided from the bound it ran under rather than from the clock when its status is read. A call the deadline cuts also writes the section note, as a refusal does. The heavy-capture line also stops claiming every probe failed when some of them were stopped by the budget. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
…early The pod walk can now also stop when the pod section's share of the budget runs out, as it already could at the pod cap. Both exits name what they left behind, and the line after them still announced the capture as complete. It now says the walk stopped early. The helper comment about the run separator also named every capture file, while the OVN dump and the speaker logs are still replaced on each run; it now lists the files it covers. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The LoadBalancer walk can stop on the budget, as the pod walk can, and still closed on "capture complete" right under the line naming what it did not probe. Both walks also called themselves complete when they ended on their own after the deadline had cut a call inside their last item. Each walk now closes as stopped early when it broke out of the loop, and as cut short by the budget when this run's section note says a call was cut or refused; the note's own text is the evidence, since the clock read after the loop can pass the deadline without any call having been cut. The LB cap break, which shares that closing line, closes the same way. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
A walk the budget cut short closed on "see the section line above", but that line goes only to capture-notes.txt, while the closing line also reaches the job log, where nothing sits above it to see. It now names the file. The budget knob replacement and the run without a timeout binary had no test of their own; both are now pinned. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
dp_run credited a cutoff to the budget whenever the deadline had passed by the time the call returned. A call under its own, unshortened bound can fire, or come back from its kill grace, just past a deadline it never reached; the section note then said the budget cut a call, next to the read's own note naming its own timeout, and the walk closed as cut short by the budget. The bound alone is not enough either: a call killed early, as an OOM-killed remote process is, returns 137 under a bound cut to the deadline long before the deadline arrives. dp_run and pod_on_node now share one rule: a cutoff is the budget's only when the call's bound reached the deadline and the deadline has passed, and never when no timeout binary bounded the call at all. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
An exec block keeps whatever it printed before its bound fired, and nothing in the block said the bound had fired. The service map every affected node gets is the largest such block, and a truncated one answers the question it is there for, whether a backend is still in the map, wrongly while looking complete. dp_run now marks a cutoff where the call's output goes, as it already does a refusal: the deadline's own cut names the budget, any other names the call's bound. The section note also stops asserting that a call was cut when the budget only refused the next one. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
Once dp_run marked a deadline cut inside an exec block, the reads that report their own outcome still read the 124 their shortened bound produced and called it the read's own timeout, quoting a bound the deadline had chosen. A Ready-conditions block then gave two reasons for one cut, and every list and lookup note did the same beside the section line that blamed the budget. dp_run now returns a status of its own for a deadline cut, which the read notes, the node and interface lookups and the LB probe all report as the budget. pod_on_node takes it from dp_run instead of deciding it a second time. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The Ready-conditions and events reads share one block and added a line of their own when they failed, on top of what their stderr put into the block. Once dp_run marked every cut and refusal there, a cut read carried two lines for one event, and before the budget status existed the second named a timeout the first said the deadline had chosen. The two reads now send stderr to the scratch file and, after their output, write kubectl's stderr into the block whole, without dp_run's marker, plus one line naming the read when it failed. kubectl's message is kept as it came, since an error can follow lines of throttling notices on a degraded apiserver. Without a scratch file their stderr goes into the block directly. The probe comments also say what the "spent" outcome now covers. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
The test that a call cut by its own bound just past the deadline is not blamed on the budget ran a 3s bound inside a 4s pod section. A whole-second tick of date +%s between DP_T0 and the first call left the bound reaching the deadline, the collector then blamed the budget, as it should, and the test failed. The pod section is now 10s against the same 3s bound, so a tick cannot reach the deadline. Assisted-by: LLM Signed-off-by: Aleksei Sviridkin <[email protected]>
0cc3749 to
57b5c83
Compare
IvanHunters
left a comment
There was a problem hiding this comment.
LGTM. First-pass review. Everything I found sits in hack/ and docs/ and is MINOR or NIT, so none of it blocks the merge.
The collector logic holds up. I checked the budget arithmetic, the pod/LoadBalancer deadline split, and the deadline reset for the LoadBalancer section, and they are right. The new tests are real, not decorative: I injected a bypassing kubectl call and a cross-scope variable write and watched the #3694 and #3675 static guards go red under both the real bats and the cozytest.sh CI runner, and the collision test reddens the same way when the _-join fix is reverted. The if ... exit 1 form those guards use survives the runner's set -e plus return 0 wrapping, so CodeRabbit's worry about a missing mutation test for #3694 does not hold in practice. No inert ! cmd negative assertions in the suite, and no skip builtin either. The docs paragraph and the .chainsaw.yaml comments match the code: budget 570 under the 600s backstop, 270 under 300s, and <unknown> instead of <none> for an unread EndpointSlice.
One newly added test fails for me on a slower machine, every time. It is test-only and green on CI, so it does not block, but I would fix it before merge. Details inline.
Findings
(see inline comments)
Checked and correct
Static guards #3694 and #3675, verified by mutation on both runners. Budget and section-deadline arithmetic. The behavioural collision test reddening on revert. Docs and .chainsaw.yaml against the code. Across the two runners I saw 100 of 119 green under bats and 67 of 119 under cozytest.sh, zero failures other than the OVS-deadline test below, and both runs were cut by my own timeout cap on a loaded machine rather than by a hang.
| COZY_DATAPLANE_BUDGET=6 COZY_DATAPLANE_LB_RESERVE=3 \ | ||
| "$real_timeout" 60 "$SCRIPT" "$d/pod" >"$d/log" 2>&1 | ||
| f="$d/pod/pod-tenant-test_wedged.txt" | ||
| grep -q 'the OVS interface lookup for iface-id=wedged.tenant-test was cut off at the deadline: the pod section ran out of its share' "$f" |
There was a problem hiding this comment.
[MINOR] Timing-fragile test: fails deterministically on a slow/loaded machine
[MINOR] This test ("an OVS interface lookup the deadline cut names the budget on both paths") fails for me every time, 3 out of 3 in isolation and as not ok 88 in a full run. With the hardcoded COZY_DATAPLANE_BUDGET=6 COZY_DATAPLANE_LB_RESERVE=3 on line 2437 the pod section gets 3s, and the test assumes the OVS lookup STARTS inside that window and is then cut at the deadline. When the pod-section preamble takes longer than 3s, dp_run correctly REFUSES the lookup ((not started: ... budget already spent)) instead of cutting it, so the asserted cut off at the deadline string never appears.
The collector is fine; the test is what is fragile. Verified two ways: the failing run's artifact carries the not started message rather than the deadline one, and the same script run with COZY_DATAPLANE_BUDGET=12 produces exactly the asserted message. On a fast Linux CI runner the preamble fits in 3s and the test is green, but on a slower or loaded machine make bats-unit-tests goes red here, and a red checks cancels finalize and e2e. This is the same slow-machine class #3685 is about, just inverted. Suggest widening the margin (a larger budget) or accepting both valid outcomes (refused-when-spent OR cut-at-deadline).
There was a problem hiding this comment.
Confirmed: the grep only holds if the preamble fits in 3s, and a starved run here fails at the same line. Filed as #4745.
| @@ -1221,8 +1480,18 @@ capture_lb_datapath() { | |||
| # accepts, while reading as a closed gap. | |||
| printf '%s\n' "$_speakers" | while IFS='|' read -r _sp _spnode; do | |||
There was a problem hiding this comment.
[NIT] LoadBalancer reserve can be consumed by the section's own preamble
[NIT] capture_lb_datapath reads one kubectl logs per MetalLB speaker here, and the speaker set is a DaemonSet, so this is one bounded read per node with no count cap, all before the first LB probe. On a slow-but-alive apiserver with many nodes this can spend the 90s reserve before any heavy LoadBalancer capture runs, and each LB then falls into the budget is spent ... NOT probed branch. Not a regression (there was no reserve before this PR) and the reserve comment only promises the section STARTS, which it does. Noting for a future pass; a count cap on the speaker-log walk would bound it.
There was a problem hiding this comment.
Real, though not a regression. Added to #4629 with the other collector leftovers.
| # time between calls; that gap is a handful of awk and printf invocations. | ||
| DP_BUDGET="${COZY_DATAPLANE_BUDGET:-270}" | ||
| DP_LB_RESERVE="${COZY_DATAPLANE_LB_RESERVE:-90}" | ||
| case "$DP_BUDGET" in '' | *[!0-9]*) DP_BUDGET_BAD=$DP_BUDGET; DP_BUDGET=270 ;; *) DP_BUDGET_BAD="" ;; esac |
There was a problem hiding this comment.
[NIT] Budget knob validation misses integer overflow
[NIT] The *[!0-9]* check rejects non-digits and the sed below strips leading zeros, but neither catches an all-digit value that overflows shell arithmetic. A 20-digit COZY_DATAPLANE_BUDGET aborts the script under dash (Illegal number) before mkdir, and a 19-digit value wraps DP_DEADLINE negative on line 465 so every call is refused. Low practical risk, but it is the one remaining class next to the non-integer and leading-zero handling you already added.
There was a problem hiding this comment.
Reproduced: dash stops with Illegal number and bash wraps the deadline negative. Added to #4629.
| } | ||
| dp_note_spent() { | ||
| _dns_note=$(dp_spent_note) | ||
| if ! grep -qxF "$_dns_note" "$NOTES" 2>/dev/null; then |
There was a problem hiding this comment.
[NIT] dp_note_spent is check-then-append (duplicate note lines)
[NIT] The two background tcpdump subshells plus the foreground probe can call dp_run concurrently, and if the deadline passes in that window up to three of them miss this grep -qxF and append the same line to capture-notes.txt. Cosmetic only: dp_walk_end still matches, so the effect is duplicate note lines, not a wrong verdict.
There was a problem hiding this comment.
Yes, the two background tcpdump execs can both miss the grep. Cosmetic, but added to #4629 so it does not get lost.
What this PR does
The e2e data-plane collector limited itself by counting pods and LoadBalancers, but both of its callers stop it by the clock.
hack/cozytest.shgives it 600s and the Chainsaw catch gives it 300s. One affected pod could already run past the smaller limit, and the LoadBalancer capture, which runs last, was the part that got lost. I moved the collector to a wall-clock budget and fixed the other issues filed against it.dp_run. It cuts the call's timeout to what is left ofCOZY_DATAPLANE_BUDGETand starts nothing once the budget is spent. The default is 270s, andcozytest.shpasses 570s. The pod section stops 90s early, so the LoadBalancer section always gets time to start. A call the deadline cut says so, a call cut by its own bound names that bound, and a refused call says it was not started and names its section; exec blocks carry that line inside the block. The node capture and the LoadBalancer probe used to blame an unanswered lookup or a missing cni-server when the budget stopped a call. Now they name the budget (e2e: the dataplane LB fan-out caps are measured in work, not wall-clock, and overrun both backstops #3671).dp_runand lists the lines. It matches by command position, so a call inside a double-quoted$(...)is still checked (test(e2e): no guard keeps every kubectl read in e2e-capture-dataplane.sh wall-clock bounded #3694)._, which neither can contain. A second run into the same directory appends, with the run separatorcapture-notes.txtalready uses (test(e2e): per-pod capture filenames can collide and silently overwrite each other #3679).capture_nodeandcapture_lb_nodeno longer write their callers' loop variables. A static test fails when a function assigns a name that aread -rloop or another scope owns (test(e2e): capture_node writes unprefixed node/nf and can clobber its caller's loop variable #3675).timeoutshim decides by argv, so a slow machine can't cut a read the test needs answered (test(e2e): the LB not-recorded-as-reachable test races the machine instead of the collector's decision #3685).cilium-dbg bpf lb listruns unfiltered in every affected node's capture, not only for a failing LoadBalancer (test(e2e): cilium-dbg bpf lb list runs only when a LoadBalancer Service is broken, so a ClusterIP failure never gets the one table that would explain it #3689).The call-site comment in
.chainsaw.yamland the collector paragraph indocs/agents/e2e-testing.mdnow match the code. Every behaviour change has a test inhack/capture-dataplane.batsthat failed on the code before it.Two parts of the issues live elsewhere. The runner stopping a bats file at its first failing test is #4620, and a conntrack read filtered by service VIP is #4623.
From #4629 I fixed the items on lines this PR already changes: the node capture now gets the run separator, a failed speaker log read writes a note, the endpoint tcpdump says when it falls back to the geneve interface, and the per-read timeout knobs are validated (a zero there would otherwise look like a spent budget). The rest of #4629 stays open:
ovn-lflows.txtandlb-speaker-logs.txtare still replaced on each run, and two comments still describe older behaviour.Screenshots
Not a UI change.
Downstream repositories
Release note
Summary by CodeRabbit