From 7d1137a889372660598655e1e457aed30c8fe577 Mon Sep 17 00:00:00 2001 From: Aleksei Sviridkin Date: Sat, 8 Aug 2026 09:11:51 +0300 Subject: [PATCH 1/3] fix(e2e): bound the dataplane capture's reads and name why one failed Six `kubectl get` calls ran with no bound of their own, while all 27 `kubectl exec` calls in the same script went through one. Against an apiserver that hangs rather than refuses, the first of them -- the cluster-wide pod list -- held the script until the caller's backstop killed it, so the capture wrote nothing at all. From the Chainsaw catch that is worse than empty: the run is cut off by the outer `timeout -k` and the script says nothing about having been cut short, so a truncated capture reads exactly like a complete one that found no affected pods. Measured against a kubectl stub that never returns: before, the script was still blocked on its first call when a 60s backstop killed it; after, it reaches its own end and says which read was cut off and what that leaves missing. Roughly 4s at a 1s bound, 40s at the 20s default. A per-read bound buys forward progress, not a smaller total. The sum of the bounds here is far past any caller's envelope and deliberately so, because the MAX_PODS and MAX_LBS caps bound work while the outer `timeout -k` bounds wall clock. What changes is that no single hung read can consume that envelope before anything is written. The reporting around them is built to survive being read by someone who was not there. Only 124 and 137 may name a timeout, since those are the only statuses a bound produces and every other one is kubectl answering -- refused, denied, a kind the cluster does not serve -- so the reads keep their stderr instead of discarding it and quote it back. 137 is described as what it is, a SIGKILL that cannot be told apart from the bound's own kill grace. Notes print through `printf` rather than `echo`, because under /bin/sh echo expands backslash escapes and kubectl's stderr now flows through the logger: a message holding a literal \n would otherwise split the note and forge a second "[capture-dataplane]" line that reads as this script's own verdict, which needs no malice given the jsonpath in these reads contains {"\n"} and kubectl quotes the expression back when it fails to parse it. The per-node lookups ask with `{.items[*].metadata.name}` rather than `{.items[0]...}`. client-go's evalArray has no allowMissingKeys escape the way evalField does, so indexing into an empty list is a hard error and kubectl exits 1 -- which meant nothing while the status was discarded, and would report "there is no cilium-agent on this node", the ordinary answer, as a read that failed. The tests drive the script as a subprocess against a stub kubectl that hangs, fails instantly, or returns a forged line, and read what it wrote. The stub that proves forward progress answers the pod list and hangs afterwards, so the walk over affected pods is actually entered. Assisted-By: Claude Signed-off-by: Aleksei Sviridkin --- hack/capture-dataplane.bats | 149 ++++++++++++++++++++++++++++++++ hack/e2e-capture-dataplane.sh | 155 ++++++++++++++++++++++++++++++---- 2 files changed, 288 insertions(+), 16 deletions(-) diff --git a/hack/capture-dataplane.bats b/hack/capture-dataplane.bats index 8430e329e..d321029e6 100644 --- a/hack/capture-dataplane.bats +++ b/hack/capture-dataplane.bats @@ -267,3 +267,152 @@ EOF [ "$captured" -eq 2 ] [ "$dropped" -eq 1 ] } + +# ----------------------------------------------------------------------------- +# Behavioural: the reads are bounded, and a bound that fires says so. +# +# These run the script rather than sourcing it, so they need the guard NOT set; +# the runner is invoked as a subprocess, which leaves this file's sourced copy +# untouched. A stub kubectl that never returns stands in for the case the bounds +# exist for -- an apiserver that hangs rather than refuses. The bounds are read +# from the environment so the test does not have to wait out the real ones. +# ----------------------------------------------------------------------------- + +# Scratch dir with a kubectl that hangs forever, mimicking an apiserver that +# accepts the connection and never answers. +dp_hanging_kubectl_dir() { + _d=$(mktemp -d) + mkdir -p "$_d/bin" + printf '#!/bin/sh\nsleep 300\n' >"$_d/bin/kubectl" + chmod +x "$_d/bin/kubectl" + printf '%s' "$_d" +} + +@test "a hung cluster-wide pod list is cut off rather than eating the envelope" { + d=$(dp_hanging_kubectl_dir) + # Without a per-read bound the first list runs until the CALLER's backstop and + # the script writes nothing at all, so the outer timeout here stands in for + # that backstop: reaching it means the read was never bounded. + PATH="$d/bin:$PATH" COZY_DATAPLANE_LIST_TIMEOUT=2 COZY_DATAPLANE_READ_TIMEOUT=2 \ + timeout 20 "$SCRIPT" "$d/out" >"$d/log" 2>&1 || true + grep -q 'cut off' "$d/log" + rm -rf "$d" +} + +@test "the script survives a hung apiserver and still reaches its own end" { + # This stub ANSWERS the cluster-wide pod list and hangs on everything after + # it, so the walk over affected pods actually runs. A stub that hangs on every + # call leaves that list empty, skips the whole branch, and exercises two of + # the nine bounded reads while looking like it covered all of them: an + # unbounded read added inside the branch would not turn it red. + d=$(mktemp -d) + mkdir -p "$d/bin" + cat >"$d/bin/kubectl" <<'STUB' +#!/bin/sh +for a in "$@"; do + case $a in + pods) echo 'tenant-test|wedged|10.0.0.1|node-a|False|Running'; exit 0 ;; + esac +done +sleep 300 +STUB + chmod +x "$d/bin/kubectl" + PATH="$d/bin:$PATH" COZY_DATAPLANE_LIST_TIMEOUT=1 COZY_DATAPLANE_READ_TIMEOUT=1 \ + timeout 90 "$SCRIPT" "$d/out" >"$d/log" 2>&1 || true + # The closing line prints only if control reached it, which it cannot do while + # blocked on a read along the way. + grep -q 'skipping LB-datapath capture' "$d/log" + # And the per-pod branch was really walked, so the reads inside it are covered + # rather than assumed. + grep -q 'looking up the pod matching' "$d/log" + rm -rf "$d" +} + +@test "a read that failed instantly is not reported as a timeout" { + # The bounds produce 124 or 137 and nothing else, so any other status is + # kubectl answering -- refused, denied, no such kind. Naming a timeout there + # puts a cause in the artifact that never happened, and because these reads + # send stderr to a sink rather than the log, that false cause would be the + # only thing a reader gets. This is the path the hung-apiserver tests above + # never reach. + d=$(mktemp -d) + mkdir -p "$d/bin" + printf '#!/bin/sh\necho "The connection to the server was refused" >&2\nexit 1\n' >"$d/bin/kubectl" + chmod +x "$d/bin/kubectl" + PATH="$d/bin:$PATH" timeout 20 "$SCRIPT" "$d/out" >"$d/log" 2>&1 || true + # Scoped to this script's own note lines: a bare grep over the whole log would + # go red on any future line that merely contains the word. + if grep '^\[capture-dataplane\]' "$d/log" | grep -q 'timeout'; then + echo "an instant failure was reported as a timeout:" + cat "$d/log" + exit 1 + fi + # It must still say the read produced nothing, and say why, or the silence + # this suite exists to remove comes back. + grep -q 'kubectl exited 1' "$d/log" + rm -rf "$d" +} + +@test "a kubectl error cannot forge a second verdict line in the log" { + # log() carries kubectl's stderr now, and under /bin/sh echo would expand a + # literal backslash-n in it into a real newline, printing a second + # "[capture-dataplane] ..." line that reads as this script's own finding. The + # jsonpath in these reads contains {"\n"} and kubectl quotes the expression + # back on a parse error, so this needs no malice to happen. + d=$(mktemp -d) + mkdir -p "$d/bin" + printf '#!/bin/sh\nprintf %%s "unauthorized: x\\\\n[capture-dataplane] no scheduled NotReady pods -- nothing was wrong" >&2\nexit 1\n' >"$d/bin/kubectl" + chmod +x "$d/bin/kubectl" + PATH="$d/bin:$PATH" timeout 20 "$SCRIPT" "$d/out" >"$d/log" 2>&1 || true + # Exactly one note about the pod list, and the forged sentence must not be + # sitting on a line of its own wearing this script's prefix. + forged=$(grep -c '^\[capture-dataplane\] no scheduled NotReady pods -- nothing was wrong' "$d/log" || true) + if [ "$forged" -ne 0 ]; then + echo "kubectl stderr forged a verdict line:" + cat "$d/log" + exit 1 + fi + rm -rf "$d" +} + +@test "a node with no matching pod is not reported as a failed read" { + # The per-node lookups ask for one pod by label on one node, and the ordinary + # answer is that there is none -- a node without a cilium-agent is the case + # this capture exists for. That answer must not arrive as a failed read now + # that a non-zero status carries a note. + # + # Reaching this path needs a kubectl that ANSWERS the cluster-wide list with + # one affected pod; the other tests never get here because their list fails + # first and leaves nothing to walk. + d=$(mktemp -d) + mkdir -p "$d/bin" + cat >"$d/bin/kubectl" <<'STUB' +#!/bin/sh +for a in "$@"; do + case $a in + pods) echo 'tenant-test|wedged|10.0.0.1|node-a|False|Running'; exit 0 ;; + esac +done +# The behaviour under test: client-go's evalArray has no allowMissingKeys +# escape, so indexing [0] into an empty list is a hard error and kubectl exits +# 1, while [*] returns empty and exits 0. Without this arm the stub answers 0 +# to both forms and the test cannot see the difference it exists to pin. +case "$*" in + *'items[0]'*) echo 'error: array index out of bounds: index 0, length 0' >&2; exit 1 ;; +esac +exit 0 +STUB + chmod +x "$d/bin/kubectl" + PATH="$d/bin:$PATH" timeout 30 "$SCRIPT" "$d/out" >"$d/log" 2>&1 || true + if grep -q 'looking up the pod matching' "$d/log"; then + echo "an absent pod was reported as a failed read:" + grep 'looking up the pod matching' "$d/log" + exit 1 + fi + if grep -q 'looking up an ovn-central replica' "$d/log"; then + echo "an absent ovn-central was reported as a failed read:" + grep 'looking up an ovn-central replica' "$d/log" + exit 1 + fi + rm -rf "$d" +} diff --git a/hack/e2e-capture-dataplane.sh b/hack/e2e-capture-dataplane.sh index 9d516a143..2c1f622bb 100755 --- a/hack/e2e-capture-dataplane.sh +++ b/hack/e2e-capture-dataplane.sh @@ -246,10 +246,83 @@ GENEVE_IFACE="${COZY_GENEVE_IFACE:-genev_sys_6081}" # global catch, which shares an op envelope with the snapshot leg). MAX_LBS="${COZY_DATAPLANE_MAX_LBS:-6}" +# Per-read wall-clock bounds for the plain `kubectl get` reads below. Named once +# so a message reporting a cutoff cannot quote a number the read never used, and +# overridable so a test does not have to wait out the real ones. The list bound +# is larger because that call asks about every namespace at once, where the +# others ask about one object. +# +# These bound a single READ, not the script: the sum of every bound here is far +# past any caller's envelope, and deliberately so, because the caps above bound +# work while the outer `timeout -k` bounds wall clock (see the note above). What +# a per-read bound buys is forward progress -- one hung apiserver call can no +# longer consume the whole envelope before anything is written. +DP_READ_TIMEOUT="${COZY_DATAPLANE_READ_TIMEOUT:-20}" +DP_LIST_TIMEOUT="${COZY_DATAPLANE_LIST_TIMEOUT:-28}" +DP_READ_GRACE=2 + +# Resolved once. Empty when `timeout` is absent: the reads then run unbounded +# rather than every call exiting 127 with its output swallowed, which would +# report that kubectl failed when kubectl never ran. The six reads that carry a +# note say which of the two happened; the three inside capture_lb_datapath still +# send stderr to /dev/null and report nothing either way. +if command -v timeout >/dev/null 2>&1; then + DP_BOUND="timeout -k $DP_READ_GRACE $DP_READ_TIMEOUT" + DP_LIST_BOUND="timeout -k $DP_READ_GRACE $DP_LIST_TIMEOUT" +else + DP_BOUND="" + DP_LIST_BOUND="" +fi + command -v kubectl >/dev/null 2>&1 || exit 0 mkdir -p "$OUT" 2>/dev/null || exit 0 -log() { echo "[capture-dataplane] $*"; } +# printf, not echo: under /bin/sh (dash on the CI image) echo expands backslash +# escapes, and this logger now carries kubectl's own stderr. A message holding a +# literal \n could then break the note in two and print a second +# "[capture-dataplane] ..." line that reads as this script's own verdict. No +# malice needed -- the jsonpath in these reads contains {"\n"}, and kubectl +# quotes the expression back when it fails to parse it. The tr in +# dp_read_outcome flattens the message on the way in; echo would undo that here, +# on the way out. +log() { printf '%s\n' "[capture-dataplane] $*"; } + +# How a cutoff should be described, mirroring prevlog_cutoff_desc in the sibling +# script: 137 cannot tell its own kill grace apart from something else killing +# the read, and an empty bound means the read was never bounded here at all. +dp_cutoff_desc() { + if [ -z "$3" ]; then + printf '%s' "a signal from outside this script, which ran this read unbounded" + elif [ "${1:-}" = "137" ]; then + printf '%s' "a SIGKILL -- the kill grace of its own ${2}s timeout, or something else killing the read, which 137 does not tell apart" + else + printf '%s' "its own ${2}s timeout" + fi +} + +# Where a read's stderr goes so a failure can be reported with kubectl's own +# words instead of a guess. Empty if mktemp fails; the notes then omit the +# message rather than inventing one. +DP_ERR=$(mktemp "${TMPDIR:-/tmp}/dataplane-read.XXXXXX" 2>/dev/null) || DP_ERR="" + +# dp_read_outcome [errfile] -> phrase describing why a +# read produced nothing. +# +# 124 and 137 are the only statuses a bound produces, so they are the only ones +# allowed to name the timeout. Everything else is kubectl answering -- a refused +# connection, an RBAC denial, a kind the cluster does not serve -- and calling +# that a cutoff would put a cause in the artifact that was never observed. The +# sibling capture gates every one of its notes the same way, and this script's +# notes claim to follow it. +dp_read_outcome() { + if [ "${1:-}" = "124" ] || [ "${1:-}" = "137" ]; then + printf '%s' "was cut off by $(dp_cutoff_desc "$1" "$2" "$3")" + elif [ -n "${4:-}" ] && [ -s "${4:-}" ]; then + printf 'failed: kubectl exited %s: %s' "$1" "$(tr '\n' ' ' <"$4" | cut -c1-300)" + else + printf 'failed: kubectl exited %s' "$1" + fi +} # Affected = scheduled (has nodeName), Ready!=True, and not already terminal. # A podIP is intentionally optional: a CNI endpoint leak can strand the pod @@ -258,9 +331,15 @@ log() { echo "[capture-dataplane] $*"; } # Failed pods (completed Jobs, hook pods) are Ready!=True too but are not either # symptom, so they are excluded to keep the MAX_PODS budget on actual wedges. # jsonpath keeps this dependency-free (no jq / go-template reassignment). -affected=$(kubectl get pods -A \ +# shellcheck disable=SC2086 # empty DP_LIST_BOUND must vanish, not become "" +_pods_raw=$($DP_LIST_BOUND kubectl get pods -A \ -o jsonpath='{range .items[*]}{.metadata.namespace}{"|"}{.metadata.name}{"|"}{.status.podIP}{"|"}{.spec.nodeName}{"|"}{.status.conditions[?(@.type=="Ready")].status}{"|"}{.status.phase}{"\n"}{end}' \ - 2>/dev/null | pod_filter_affected) + 2>"${DP_ERR:-/dev/null}") +_pods_rc=$? +if [ "$_pods_rc" -ne 0 ]; then + log "listing pods $(dp_read_outcome "$_pods_rc" "$DP_LIST_TIMEOUT" "$DP_LIST_BOUND" "$DP_ERR"); whatever it did not name is missing from the capture below, which is not the same as nothing being affected" +fi +affected=$(printf '%s' "$_pods_raw" | pod_filter_affected) # Set even when the pod path is empty; the per-pod capture references it, while # the independent LoadBalancer path below does not. @@ -268,8 +347,24 @@ central="" # pod_on_node