Skip to content

Commit a97bc4a

Browse files
committed
test(e2e): capture the tenant worker guest serial console
The tenant Kubernetes suites fail the node-Ready budget with zero Nodes registered, and the time is lost inside the guest between the worker VMI reaching Running and Talos requesting its apid certificate. Nothing collected today covers that window: the existing in-guest capture drives talosctl, so it needs the very apid the worker never reached, and on the management side there is neither a Node nor a certificate request to read. Turn on the guest console log for the suite's node group and collect each virt-launcher's guest-console-log container from the management cluster. Reads start at the beginning of the stream rather than tailing it, so a guest that repaints its console cannot push the boot output out of the window; every read is bounded, and the walk stops at a cap that records both counts, so the collector cannot become the unbounded term in a failure path that already runs several others under one deadline. A read that returns no console is not filed as a quiet guest. Three outcomes get three labels, because only one of them says anything about the guest: the read failed and returned nothing, the read succeeded and returned nothing, or it broke off part way. Each read's stderr is kept beside the capture rather than inside it, since kubectl's own "container is not valid for pod" would otherwise fill the file and a console that never started would read as one that had spoken. That case is the headline one here, so the Pod state and events that explain it are collected alongside, once for the whole selector: several silent workers are one finding. The capture runs only when node-join fails, so the passing path checks separately that the container attached at all. Otherwise the suite would first learn the setting was inert in the one run that needed the console, when it can no longer be recovered. That check keeps three outcomes apart too: a read that did not answer, a selector that matched no Pod, and Pods that matched and carry nothing. It reads the Pod name alongside the container names so the last two cannot collapse, and both container lists so a future move of the container cannot fail a run over a diagnostic. It runs last, after everything the suite exists to prove, because a debugging aid must not preempt the assertions that cover the cluster. The capture runs before the talosctl one because it is the only of the two that can describe a worker which never reached apid, the shape this failure keeps taking. kubectl reports a warning and an empty result alike, on stderr with a zero status, so the exit status decides which artifact its output lands in. Assisted-By: Claude <[email protected]> Signed-off-by: Aleksei Sviridkin <[email protected]>
1 parent c20d47a commit a97bc4a

4 files changed

Lines changed: 1028 additions & 6 deletions

File tree

‎hack/e2e-chainsaw/_lib/run-kubernetes.sh‎

Lines changed: 274 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -553,6 +553,242 @@ cozy_capture_tenant_talos_node() {
553553
"${output_dir}/kubelet.log" logs kubelet --tail=500 || true
554554
}
555555

556+
# Check that KubeVirt actually attached the guest console container, on the
557+
# path where the workers did boot. The capture below runs only when node-join
558+
# fails, so without this the suite would first learn that the node group's
559+
# logSerialConsole never took effect in the run that needed the console, when
560+
# it can no longer be recovered. The platform disables console logging
561+
# cluster-wide (see packages/system/kubevirt), so what this asks is whether
562+
# the per-VM override beat that on the KubeVirt version actually shipping.
563+
#
564+
# The read's own status is kept separate from the answer it returns, and the
565+
# two get different exit codes, because they are different claims. Piping
566+
# kubectl into grep would collapse them: a read that failed produces no output,
567+
# grep finds nothing, and an API blip would be reported as "the override did
568+
# not take effect" -- a cause that was never established, sending the next
569+
# reader at KubeVirt config instead of at the apiserver. A selector that
570+
# matched no Pod at all is the same trap one step further on, and is kept
571+
# apart from a Pod that matched and carries nothing -- the second is the
572+
# finding, the first is not a statement about any Pod.
573+
#
574+
# What it establishes is that SOME virt-launcher Pod in the namespace carries
575+
# the container, not that every one does. That is the direction worth erring
576+
# in for a check whose only job is to catch an inert setting: it can miss, but
577+
# it cannot fail a run over a Pod that is not this test's. The match runs over
578+
# the whole name=containers line, so a Pod named after the container would
579+
# satisfy it -- these names come from the Machine name, so that cannot happen
580+
# here, but a reader changing the format should know the glob spans both.
581+
#
582+
# 0 a Pod carries the container
583+
# 1 the read did not answer, or matched no Pod; not evidence either way
584+
# 2 Pods matched and none carries the container
585+
cozy_assert_guest_console_attached() {
586+
local init_names read_rc=0
587+
588+
# The Pod name is in the output for a reason that is not cosmetic: without
589+
# it, a Pod whose initContainers list is absent emits a bare newline, command
590+
# substitution strips it, and "Pods matched, none carries the container" is
591+
# byte-identical to "no Pod matched". Those two must not collapse -- the
592+
# first is the finding this whole check exists for, and on these workers it
593+
# is also the only shape it can take, since guest-console-log is the only
594+
# init container a DataVolume-booted virt-launcher Pod ever has.
595+
init_names=$(timeout -k 5 30 kubectl -n tenant-test get pods \
596+
-l kubevirt.io=virt-launcher \
597+
-o jsonpath='{range .items[*]}{.metadata.name}{"="}{.spec.initContainers[*].name}{" "}{.spec.containers[*].name}{"\n"}{end}' \
598+
--request-timeout=30s) || read_rc=$?
599+
if [ "${read_rc}" -ne 0 ]; then
600+
echo "could not read tenant virt-launcher Pods to verify the guest console container (exit ${read_rc})" >&2
601+
echo "this says nothing about logSerialConsole either way; continuing" >&2
602+
return 1
603+
fi
604+
605+
if [ -z "${init_names}" ]; then
606+
echo "no tenant virt-launcher Pod matched; nothing to verify about the guest console container" >&2
607+
echo "this says nothing about logSerialConsole either way; continuing" >&2
608+
return 1
609+
fi
610+
611+
case "${init_names}" in
612+
*guest-console-log*) return 0 ;;
613+
esac
614+
615+
echo "tenant worker virt-launcher Pods carry no guest-console-log container" >&2
616+
echo "the node group asked for logSerialConsole, so either the cluster-wide" >&2
617+
echo "disableSerialConsoleLog won the override or the field never reached the VM" >&2
618+
# Bounded like the read above, and for the same reason: these run on a path
619+
# that ends in exit 1, and a hang here would take the step's whole deadline
620+
# with it -- losing the tenant snapshot that the exit is supposed to reach.
621+
timeout -k 5 30 kubectl -n tenant-test get pods -l kubevirt.io=virt-launcher \
622+
-o jsonpath='{range .items[*]}{.metadata.name}{": "}{.spec.initContainers[*].name}{"\n"}{end}' \
623+
--request-timeout=30s || true
624+
timeout -k 5 30 kubectl -n tenant-test get virtualmachineinstances.kubevirt.io \
625+
-o jsonpath='{range .items[*]}{.metadata.name}{": logSerialConsole="}{.spec.domain.devices.logSerialConsole}{"\n"}{end}' \
626+
--request-timeout=30s || true
627+
return 2
628+
}
629+
630+
# Capture each tenant worker's guest serial console from the management
631+
# cluster. When a node group sets logSerialConsole, KubeVirt streams the
632+
# console into a guest-console-log container beside virt-launcher, and reading
633+
# it needs nothing from inside the guest: no talosctl, no client certificate,
634+
# no helper Pod, no reachable apid. That is the whole reason it exists. The
635+
# talosctl capture below can only describe a worker whose apid already answers,
636+
# so a worker that stalls earlier -- the case where no Node registers and no
637+
# certificate request is ever made -- is invisible to it by construction, and
638+
# the console is the only remaining surface.
639+
#
640+
# Reads start at the beginning of the stream rather than tailing it, because a
641+
# guest that repaints its console would push the boot output out of any tail
642+
# window while --limit-bytes truncates from the far end instead. That covers
643+
# only what kubectl returns: whatever the kubelet has already rotated out of
644+
# the container log (containerLogMaxSize, 10Mi x 5 by default) is gone before
645+
# the capture runs, and no read option recovers it.
646+
#
647+
# An absent guest-console-log container is the finding, not a gap: it says
648+
# console logging did not take effect on this run, which is a different fact
649+
# from a guest that printed nothing. kubectl's refusal is kept beside the
650+
# capture rather than inside it so the two stay distinguishable, and the
651+
# capture file says which of them happened.
652+
#
653+
# The Pod list is namespace-wide rather than scoped to one release. The two
654+
# virt-launcher captures immediately above the call site already select that
655+
# way, and suites run one at a time. Below the cap a Pod that does not belong
656+
# to this test costs one extra file named after itself and nothing else; at
657+
# the cap it can displace one of this suite's own, since kubectl returns the
658+
# list name-sorted. COLLECTION-TRUNCATED.txt is what keeps that visible.
659+
cozy_capture_tenant_serial_console() {
660+
local report_dir="${COZY_REPORT_DIR:-/workspace/_out/cozyreport}/snapshots/${COZY_SNAPSHOT_NAME:-kubernetes}/tenant-serial-console"
661+
local pods pod rc
662+
local list_rc=0
663+
local seen=0
664+
local silent=0
665+
local pod_err
666+
local max_pods=6
667+
local err_log="${report_dir}/setup-error.log"
668+
local warn_log="${report_dir}/READ-WARNINGS.txt"
669+
670+
mkdir -p "${report_dir}"
671+
# stderr goes to its own file rather than being folded into the captured
672+
# stdout: a warning kubectl prints on an otherwise successful call would
673+
# otherwise be read back as a Pod name. Which file it goes to is decided by
674+
# the exit status, not by the fact that something was written: an apiserver
675+
# Warning header or a deprecation notice arrives on stderr with a zero exit,
676+
# so a warning beside a healthy read belongs in READ-WARNINGS.txt as
677+
# elsewhere in this tree, while the stderr of a call that actually failed IS
678+
# the diagnosis and belongs in setup-error.log. The list is wrapped in
679+
# timeout for the same reason every read below it is: --request-timeout
680+
# bounds the HTTP request, not a client retrying against a wedged
681+
# apiserver, and a hang here would cost the whole
682+
# section rather than one Pod.
683+
pods=$(timeout -k 5 30 kubectl -n tenant-test get pods -l kubevirt.io=virt-launcher \
684+
-o jsonpath='{range .items[*]}{.metadata.name}{"\n"}{end}' \
685+
--request-timeout=30s 2>"${warn_log}") || list_rc=$?
686+
if [ "${list_rc}" -ne 0 ]; then
687+
echo "failed to list tenant virt-launcher Pods for serial console capture" >&2
688+
mv "${warn_log}" "${err_log}" 2>/dev/null || true
689+
printf '%s\n' \
690+
"failed to list tenant virt-launcher Pods for serial console capture (exit ${list_rc})" \
691+
>>"${err_log}"
692+
return 1
693+
fi
694+
[ -s "${warn_log}" ] || rm -f "${warn_log}"
695+
if [ -z "${pods}" ]; then
696+
echo "no virt-launcher Pod found for serial console capture" >&2
697+
printf '%s\n' 'no virt-launcher Pod found in namespace tenant-test' \
698+
>"${err_log}"
699+
return 1
700+
fi
701+
702+
# Cap the walk. Each read costs up to 35s (30s plus the kill grace) and the
703+
# pool can reach maxReplicas, so an uncapped loop is an unbounded term inside
704+
# a failure path that already spends ~12m on other collectors under one
705+
# chainsaw op timeout — and the bundle this exists to produce is what gets
706+
# truncated when that op is killed. A cap that fired is recorded with both
707+
# counts rather than leaving the shortfall implicit, since a short listing
708+
# otherwise reads as a small pool rather than a truncated walk.
709+
for pod in ${pods}; do
710+
seen=$((seen + 1))
711+
if [ "${seen}" -gt "${max_pods}" ]; then
712+
echo "--- guest serial console capture stopped at ${max_pods} Pods ---"
713+
printf 'capture stopped after %s Pods; %s matched in total\n' \
714+
"${max_pods}" "$(printf '%s\n' ${pods} | wc -l | tr -d ' ')" \
715+
>"${report_dir}/COLLECTION-TRUNCATED.txt"
716+
break
717+
fi
718+
echo "--- capturing guest serial console: ${pod} ---"
719+
rc=0
720+
# stderr goes beside the capture, not into it. Folded in, kubectl's own
721+
# "container guest-console-log is not valid for pod ..." would make the
722+
# file non-empty and the console would look like it had said something.
723+
# That error is the headline case here -- it is what a container wedged in
724+
# Init looks like -- so it has to stay separable from console bytes. Which
725+
# name it lands under is decided by the exit status, the same way the list
726+
# read above decides it: kubectl writes warnings on stderr with a zero
727+
# status too, and a warning beside a healthy capture is not an error.
728+
pod_err="${report_dir}/${pod}.read-error.log"
729+
timeout -k 5 30 kubectl -n tenant-test logs "${pod}" \
730+
-c guest-console-log --limit-bytes=1048576 \
731+
>"${report_dir}/${pod}.log" 2>"${pod_err}" || rc=$?
732+
if [ ! -s "${pod_err}" ]; then
733+
rm -f "${pod_err}"
734+
pod_err=
735+
elif [ "${rc}" -eq 0 ]; then
736+
mv "${pod_err}" "${report_dir}/${pod}.READ-WARNINGS.txt" 2>/dev/null || true
737+
pod_err=
738+
fi
739+
# Tested before the exit-code line is appended, or nothing is ever empty.
740+
# Three outcomes, three labels, because only one of them is a statement
741+
# about what the guest did.
742+
if [ ! -s "${report_dir}/${pod}.log" ] && [ "${rc}" -ne 0 ]; then
743+
silent=$((silent + 1))
744+
# timeout kills the child without a word, so a read can fail having
745+
# written nothing to either stream. Naming a file that was never created
746+
# sends the reader looking for evidence that does not exist.
747+
if [ -n "${pod_err}" ]; then
748+
printf '%s\n' \
749+
'the read returned no console at all; see read-error.log and POD-STATE.txt' \
750+
>>"${report_dir}/${pod}.log"
751+
else
752+
printf '%s\n' \
753+
'the read failed silently and returned no console at all; see POD-STATE.txt' \
754+
>>"${report_dir}/${pod}.log"
755+
fi
756+
elif [ ! -s "${report_dir}/${pod}.log" ]; then
757+
silent=$((silent + 1))
758+
printf '%s\n' \
759+
'the read succeeded and returned nothing; see POD-STATE.txt for whether the container started' \
760+
>>"${report_dir}/${pod}.log"
761+
elif [ "${rc}" -ne 0 ]; then
762+
silent=$((silent + 1))
763+
printf '%s\n' \
764+
'console output is truncated; see POD-STATE.txt for the Pod state' \
765+
>>"${report_dir}/${pod}.log"
766+
fi
767+
printf '\n[capture exit code: %s]\n' "${rc}" >>"${report_dir}/${pod}.log"
768+
done
769+
770+
# An empty console log has two causes that are indistinguishable in the log
771+
# itself: the guest printed nothing, or the container never started and there
772+
# was no stream to read. The second is what kubevirt/kubevirt#15989 produces,
773+
# and it is the reading that would otherwise be filed as a quiet guest --
774+
# silence reported as a result is the failure this collector exists to
775+
# prevent, so it is not allowed to produce one. The Pod's own state and its
776+
# events are what separate the two, and they are read once for the whole
777+
# selector rather than per Pod: several silent workers are one finding, and
778+
# paying per Pod would put back the unbounded term the cap removed.
779+
if [ "${silent}" -gt 0 ]; then
780+
{
781+
printf '=== describe pods -l kubevirt.io=virt-launcher ===\n'
782+
timeout -k 5 30 kubectl -n tenant-test describe pods \
783+
-l kubevirt.io=virt-launcher --request-timeout=30s 2>&1 || true
784+
printf '\n=== Pod events in tenant-test (not filtered to virt-launcher) ===\n'
785+
timeout -k 5 30 kubectl -n tenant-test get events \
786+
--field-selector involvedObject.kind=Pod \
787+
--sort-by=.lastTimestamp --request-timeout=30s 2>&1 || true
788+
} >"${report_dir}/POD-STATE.txt"
789+
fi
790+
}
791+
556792
# Collect the guest-side evidence requested by issue #3513. This runs only after
557793
# the 18-minute Ready deadline has already failed. VMIs without a reported IP
558794
# are recorded before any Certificate or Pod is created; when at least one IP is
@@ -728,6 +964,12 @@ ${ouroboros_addon}
728964
diskSize: 20Gi
729965
gpus: []
730966
instanceType: u1.medium
967+
# The failure this suite keeps hitting is a worker that stalls in the
968+
# guest before Talos apid answers, which leaves nothing to read on the
969+
# management side and nothing for talosctl to connect to. Turning this on
970+
# attaches KubeVirt's guest-console-log container, the only artifact that
971+
# covers that window.
972+
logSerialConsole: true
731973
maxReplicas: 10
732974
minReplicas: 2
733975
resources: {}
@@ -886,6 +1128,22 @@ EOF
8861128
kubectl -n tenant-test get pods -l kubevirt.io=virt-launcher -o wide || true
8871129
kubectl -n tenant-test describe pods -l kubevirt.io=virt-launcher || true
8881130

1131+
# (b1) Guest serial console, read from the management cluster. First of the
1132+
# in-guest captures because it is the only one that survives a worker which
1133+
# never reached apid — the dominant shape of this failure, where no Node
1134+
# registers and no certificate request is ever made. (b) below needs that
1135+
# same apid to answer, so it cannot describe this class at all.
1136+
# Two shapes of empty result are worth telling apart from a silent guest.
1137+
# A virt-launcher Pod still Pending has no containers at all yet, which is
1138+
# the ordinary shape of a worker that never booted. A Pod wedged in Init on
1139+
# guest-console-log is the opposite reading: the console container is what
1140+
# stopped it booting, and then neither a console nor an apid exists to
1141+
# explain anything else. The container being absent from a Running Pod is
1142+
# the rarest of the three, since the per-VM field outranks the cluster-wide
1143+
# disable by design and the green path asserts it attached.
1144+
echo "=== (b1) tenant worker guest serial console (management cluster, ns tenant-test) ==="
1145+
cozy_capture_tenant_serial_console || true
1146+
8891147
# (b) In-guest Talos kernel and kubelet logs. The tenant chart intentionally
8901148
# has no admin talosconfig, so mint a one-hour os:reader client from its
8911149
# existing cert-manager Issuer and run talosctl from a hardened Pod that can
@@ -1484,6 +1742,22 @@ EOF
14841742
exit 1
14851743
fi
14861744

1745+
# Last, after everything the suite exists to prove. This checks a debugging
1746+
# aid, not the product: a worker boots and serves either way, so letting it
1747+
# run first would let a KubeVirt-side change to a diagnostic preempt the
1748+
# assertions that actually cover the tenant cluster. It still runs on the
1749+
# passing path rather than beside the collector, because the collector only
1750+
# runs when node-join fails and would learn the setting was inert in the one
1751+
# run where the console can no longer be recovered. Exit 2 alone fails the
1752+
# suite; see cozy_assert_guest_console_attached for why its three outcomes
1753+
# are not interchangeable.
1754+
echo "» verifying the tenant worker guest console container attached"
1755+
attach_rc=0
1756+
cozy_assert_guest_console_attached || attach_rc=$?
1757+
if [ "${attach_rc}" -eq 2 ]; then
1758+
exit 1
1759+
fi
1760+
14871761
# Success: disarm the tenant-snapshot trap so it doesn't fire on the clean exit.
14881762
trap - EXIT
14891763
# Clean up: delete the test-scoped tenant API LoadBalancer (frees its MetalLB

‎hack/e2e-chainsaw/kubernetes-latest/chainsaw-test.yaml‎

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -19,9 +19,16 @@ spec:
1919
try:
2020
- script:
2121
# ~25m Kamaji bringup + worker join + LB/NFS/ouroboros assertions.
22-
# The failure path can spend ~5m10s in bounded guest Talos capture and
23-
# another 6m30s in its in-process tenant snapshot. Keep the outer op
24-
# above those inner budgets with useful scheduling/API-call slack.
22+
# The failure path can spend ~5m10s in bounded guest Talos capture,
23+
# 35s per virt-launcher Pod reading the guest serial console plus one
24+
# 35s list read, and when any read comes back silent two more 35s
25+
# reads for the Pod state that says whether the container started
26+
# (30s each plus the 5s kill grace, so ~1m45s at the pool's
27+
# minReplicas of 2 and ~5m15s at worst -- that walk is capped at 6
28+
# Pods and the Pod-state reads are taken once, so neither follows
29+
# maxReplicas), and another 6m30s in its in-process tenant snapshot.
30+
# Keep the outer op above those inner budgets with useful
31+
# scheduling/API-call slack.
2532
timeout: 50m
2633
# Co-locate the tenant crust-gather snapshot (captured by
2734
# run-kubernetes.sh on failure) under the same snapshots/<test>/ dir as

‎hack/e2e-chainsaw/kubernetes-previous/chainsaw-test.yaml‎

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -13,9 +13,16 @@ spec:
1313
- name: tenant-kubernetes-previous-version
1414
try:
1515
- script:
16-
# The failure path can spend ~5m10s in bounded guest Talos capture and
17-
# another 6m30s in its in-process tenant snapshot. Keep the outer op
18-
# above those inner budgets with useful scheduling/API-call slack.
16+
# The failure path can spend ~5m10s in bounded guest Talos capture,
17+
# 35s per virt-launcher Pod reading the guest serial console plus one
18+
# 35s list read, and when any read comes back silent two more 35s
19+
# reads for the Pod state that says whether the container started
20+
# (30s each plus the 5s kill grace, so ~1m45s at the pool's
21+
# minReplicas of 2 and ~5m15s at worst -- that walk is capped at 6
22+
# Pods and the Pod-state reads are taken once, so neither follows
23+
# maxReplicas), and another 6m30s in its in-process tenant snapshot.
24+
# Keep the outer op above those inner budgets with useful
25+
# scheduling/API-call slack.
1926
timeout: 50m
2027
# Co-locate the tenant crust-gather snapshot (captured by
2128
# run-kubernetes.sh on failure) under the same snapshots/<test>/ dir as

0 commit comments

Comments
 (0)