mirror of
https://github.com/cozystack/cozystack.git
synced 2026-11-03 10:37:21 +09:00
Aleksei Sviridkin
e80b8e370f
The failure snapshot selected pods by their STATUS column, so a pod whose container runs while its readiness probe never passes -- STATUS Running, READY 0/1 -- was dropped from the report entirely. That is a common way for a suite to time out: the replica never joins, its owning HelmRelease sits in InProgress, and the artifact carries no trace of the pod the run died on. Select on the READY column instead, which also covers the partially ready multi-container case, and keep every phase that was collected before. On one degraded cluster that is four of the seven broken pods the old filter reported nothing about. The VMI and VM sections had the same blind spot and now share one selector that reads READY as the last field, because a Pending object prints fewer columns than a Running one and the two kinds differ only in how many columns precede READY. READY counts ready containers rather than the pod's Ready condition, so a pod held back by an unsatisfied readiness gate is out of scope; a test pins that rather than leaving it to be found in an empty directory. Logs are requested for every container of a selected pod rather than skipped for Pending ones, and the per-pod collection moved into a helper so it can be driven against a stub kubectl. kubectl's refusal is the finding, and an empty result is ambiguous on its own: a read against an unscheduled pod exits 0 having printed nothing, which is what a container that started and stayed quiet also leaves. Every site that classifies a failed read now orders its branches the same way, naming the timeout first where both a cutoff and an uncapturable stderr apply. The CRD gate in the summary had no such branch at all: it returned in silence, which is byte-identical to the CRD being absent, so every section behind that gate vanished from a report whose only real problem was that the machine writing it had nowhere to put a temp file. Collection used to stop silently. A walk that hit its cap said so in the job log and nowhere in the artifact. Now the pod walk leaves COLLECTION-TRUNCATED.txt when it stops at COZY_REPORT_PODS_MAX or COZY_REPORT_PODS_BUDGET, CONTAINER-LOGS-TRUNCATED.txt on a pod cut off part way through, COLLECTION-FAILED.txt when the pod list never came back rather than the empty tree a healthy cluster produces, and COLLECTION-UNBOUNDED.txt when timeout is missing locally, which is a fact about the machine writing the report and not about the cluster. Tenant namespaces are collected first, so a cap that only bites on a broadly degraded cluster is not spent on platform pods while the pod the suite died on falls off the end. Container logs are read with --tail=2000 where they were previously read whole, and every bounded file states the bound it was written under, because --tail drops the oldest lines and nothing else in the output would say so. COZY_REPORT_POD_TAIL=-1 restores the complete log. The bounded whole-object read no longer merges stderr into pod.yaml, vm.yaml and vmi.yaml, which are read by yq rather than by eye: a warning on an otherwise complete read left an unparseable file. stderr goes to a scratch file and is copied in only when kubectl returned no object, and the truncation markers those files carry are written as YAML comments, since a bare marker line after a complete mapping is a second top-level node. Six latent faults surfaced while making these reads report. The kamaji module was gated on the LINSTOR controller, so a cluster without LINSTOR got no kamaji evidence at all, which is what a tenant-kubernetes bootstrap timeout needs most. The Flux sources section nested one jsonpath filter inside another, which kubectl rejects outright, so it printed nothing on every report ever taken and read as "all sources Ready". The HelmRelease listing took a single field as STATUS where STATUS is the Ready condition's whole message, so every failed release rendered as one word. The services section filtered for a pending LoadBalancer address on the CLUSTER-IP column, which never carries that value. The cozystack module read its image from a Deployment the installer stopped shipping when it moved to the operator, putting kubectl's NotFound in the first file of the report. And the cozystack apps section gated all three of its kinds on a CRD in an aggregated API group, so it never ran once; two of those names were wrong, and both are collected again. The tests avoid EXIT-trap cleanup, and e2e-testing.md says why: a bats test that installs one and then fails prints no TAP line at all, so output grepped for `not ok` reads as green, while hack/cozytest.sh reports the same failure correctly. A guard enforces that over a named list of files rather than a glob with exceptions, because a list of exceptions is the same claim written so that forgetting to shorten it makes it false. Assisted-By: Claude <noreply@anthropic.com> Signed-off-by: Aleksei Sviridkin <f@lex.la>
893 lines
41 KiB
Bash
893 lines
41 KiB
Bash
#!/usr/bin/env bats
|
|
# -----------------------------------------------------------------------------
|
|
# Unit tests for the pure selection helpers in
|
|
# hack/e2e-capture-previous-logs.sh -- the logic that decides WHICH restarted
|
|
# containers get their previous instance dumped, and in what order:
|
|
#
|
|
# - prevlog_filter_restarted -- keep only containers with restartCount > 0;
|
|
# - prevlog_prioritize -- put the failing test's namespace first;
|
|
# - prevlog_cap -- bound the dump so a wedged cluster cannot
|
|
# explode the catch;
|
|
# - prevlog_logfile_name -- per-container artifact filename.
|
|
#
|
|
# The `kubectl logs --previous` capture itself is not unit-testable (it needs a
|
|
# live cluster with a crash-looping pod); these tests pin the derivations that
|
|
# decide what is worth asking for at all. The restart filter is the one that
|
|
# matters most: without it every healthy container would be asked for a
|
|
# previous instance that does not exist, turning the catch into a page of noise.
|
|
#
|
|
# Strategy: the script is sourced once with E2E_CAPTURE_PREVLOGS_LIB set, which
|
|
# the script's sourcing guard honours by defining the helpers and returning
|
|
# before it touches $1 or runs any capture -- so no cluster is required. Each
|
|
# @test then calls the helpers directly and asserts with `[ ... ]`, matching this
|
|
# repo's plain-shell bats convention (no `run` helper). The whole-script tests at
|
|
# the end of this file work the other way round: they EXECUTE the script against
|
|
# a stub kubectl, because what they pin is the artifact it leaves behind.
|
|
#
|
|
# Title syntax constraints (inherited from cozytest.sh's awk parser):
|
|
# - Titles delimited by ASCII double quotes; embedded quotes truncate.
|
|
# - Only [A-Za-z0-9] from the title survives into the function name, so keep
|
|
# titles distinctive in their alphanumeric run.
|
|
#
|
|
# Run with: hack/cozytest.sh hack/capture-previous-logs.bats
|
|
# (or `bats hack/capture-previous-logs.bats` if the bats binary is
|
|
# installed; cozytest.sh is the CI path.)
|
|
# -----------------------------------------------------------------------------
|
|
|
|
HACK_DIR="$(cd "$(dirname "${BATS_TEST_FILENAME:-$0}")" && pwd)"
|
|
SCRIPT="$HACK_DIR/e2e-capture-previous-logs.sh"
|
|
|
|
# Load the pure helpers. The guard returns before the capture body, so this is
|
|
# side-effect-free and needs no cluster.
|
|
E2E_CAPTURE_PREVLOGS_LIB=1
|
|
# shellcheck source=/dev/null
|
|
. "$SCRIPT"
|
|
|
|
@test "filter restarted keeps only containers whose restart count is above zero" {
|
|
rows="$(printf '%s\n' \
|
|
'tenant-test|mariadb-test-0|mariadb|container|3' \
|
|
'tenant-test|mariadb-test-1|mariadb|container|0' \
|
|
'cozy-system|healthy|app|container|0' \
|
|
'tenant-test|mariadb-test-0|init-datadir|init|2')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ]
|
|
printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|mariadb|container|3$'
|
|
printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|init-datadir|init|2$'
|
|
# `! cmd` is vacuous under cozytest's `set -e` (errexit is suppressed for a
|
|
# `!`-negated pipeline), so a filter regression that let these rows through
|
|
# would not fail the test. Assert the absence via `if cmd; then ...; false`.
|
|
if printf '%s\n' "$out" | grep -q 'mariadb-test-1'; then echo "FAIL: must drop the zero-restart replica"; false; fi
|
|
if printf '%s\n' "$out" | grep -q 'cozy-system'; then echo "FAIL: must drop the zero-restart system pod"; false; fi
|
|
}
|
|
|
|
@test "filter restarted drops rows with a malformed or empty restart count" {
|
|
# A non-numeric count must be dropped rather than compared. The row would be
|
|
# skipped either way (`[ "<none>" -gt 0 ]` exits 2, which the filter's
|
|
# `|| continue` catches), so what this pins is the contract -- malformed rows
|
|
# never reach the capture -- not a crash.
|
|
rows="$(printf '%s\n' \
|
|
'tenant-test|pod-a|app|container|' \
|
|
'tenant-test|pod-b|app|container|<none>' \
|
|
'tenant-test|pod-c|app|container|-1' \
|
|
'tenant-test|pod-d|app|container|1')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 1 ]
|
|
printf '%s\n' "$out" | grep -q '^tenant-test|pod-d|'
|
|
}
|
|
|
|
@test "filter restarted drops rows missing a namespace pod or container field" {
|
|
rows="$(printf '%s\n' \
|
|
'|pod-a|app|container|4' \
|
|
'tenant-test||app|container|4' \
|
|
'tenant-test|pod-c||container|4' \
|
|
'tenant-test|pod-d|app|container|4')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 1 ]
|
|
printf '%s\n' "$out" | grep -q '^tenant-test|pod-d|'
|
|
}
|
|
|
|
@test "prioritize puts the failing test namespace ahead of everything else" {
|
|
rows="$(printf '%s\n' \
|
|
'cozy-linstor|satellite-x|linstor|container|5' \
|
|
'tenant-test|mariadb-test-0|mariadb|container|3' \
|
|
'cozy-cilium|agent-y|cilium|container|2' \
|
|
'tenant-test|mariadb-test-1|mariadb|container|1')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_prioritize tenant-test)"
|
|
|
|
# All four survive -- prioritisation reorders, it never drops.
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 4 ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "mariadb-test-0" ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "mariadb-test-1" ]
|
|
# Non-matching rows keep their relative input order behind the matches.
|
|
[ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "satellite-x" ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "agent-y" ]
|
|
}
|
|
|
|
@test "prioritize with an empty namespace passes every row through unchanged" {
|
|
rows="$(printf '%s\n' \
|
|
'cozy-linstor|satellite-x|linstor|container|5' \
|
|
'tenant-test|mariadb-test-0|mariadb|container|3')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_prioritize '')"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "satellite-x" ]
|
|
}
|
|
|
|
@test "prioritize treats the namespace as text and not as a pattern" {
|
|
# The namespace arrives from the caller, so a `.` in it must not match a namespace
|
|
# it does not name.
|
|
rows="$(printf '%s\n' \
|
|
'tenantXtest|pod-regex|app|container|1' \
|
|
'tenant.test|pod-literal|app|container|1' \
|
|
'cozy-system|pod-other|app|container|1')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_prioritize 'tenant.test')"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 3 ]
|
|
first=$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)
|
|
if [ "$first" != "pod-literal" ]; then
|
|
echo "FAIL: expected pod-literal first, got '$first' (namespace matched as a pattern)"
|
|
false
|
|
fi
|
|
}
|
|
|
|
@test "prioritize matches the namespace field only and not a pod name substring" {
|
|
# The match must anchor on the LEADING namespace field. The first row is the
|
|
# fixture that makes this test bite: a pod named exactly like the namespace,
|
|
# in a different namespace, so the row contains `tenant-test|` but does not
|
|
# start with it. Drop the `^` from prevlog_prioritize and that row is promoted
|
|
# ahead of the genuine namespace match below, flipping the first two
|
|
# assertions. (A pod merely named `tenant-test-runner` does NOT distinguish
|
|
# the two -- it lacks the trailing `|` and so matches neither form -- which is
|
|
# why it is kept only as the third row rather than carrying the test.)
|
|
# The second row is the other half of the anchor: a SIBLING NAMESPACE sharing
|
|
# the prefix, which nested tenants make routine. It pins the trailing `|` --
|
|
# drop that from the pattern and `tenant-test-child` is treated as the failing
|
|
# test's own namespace and promoted, which is how the cap would get spent on
|
|
# an unrelated tenant's restarts.
|
|
rows="$(printf '%s\n' \
|
|
'cozy-system|tenant-test|app|container|1' \
|
|
'tenant-test-child|neighbour|app|container|1' \
|
|
'cozy-system|tenant-test-runner|app|container|1' \
|
|
'tenant-test|real|app|container|1')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_prioritize tenant-test)"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 4 ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f1)" = "tenant-test" ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "real" ]
|
|
# Everything else keeps input order behind the single genuine match.
|
|
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "tenant-test" ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "neighbour" ]
|
|
[ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "tenant-test-runner" ]
|
|
}
|
|
|
|
@test "cap keeps at most the requested number of rows" {
|
|
rows="$(printf '%s\n' \
|
|
'ns|p1|c|container|1' 'ns|p2|c|container|1' 'ns|p3|c|container|1' \
|
|
'ns|p4|c|container|1' 'ns|p5|c|container|1')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_cap 3)"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 3 ]
|
|
printf '%s\n' "$out" | grep -q '^ns|p1|'
|
|
if printf '%s\n' "$out" | grep -q '^ns|p4|'; then echo "FAIL: cap must drop rows past the limit"; false; fi
|
|
}
|
|
|
|
@test "cap leaves a shorter input untouched" {
|
|
rows="$(printf '%s\n' 'ns|p1|c|container|1' 'ns|p2|c|container|1')"
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_cap 12)"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ]
|
|
}
|
|
|
|
@test "cap falls back to the default limit when given a malformed value" {
|
|
# COZY_PREVLOG_MAX is operator-supplied, so a typo must degrade to the default
|
|
# rather than make `head -n` fail and drop the whole capture.
|
|
rows="$(i=1; while [ "$i" -le 20 ]; do printf 'ns|p%s|c|container|1\n' "$i"; i=$((i + 1)); done)"
|
|
[ "$(printf '%s\n' "$rows" | grep -c .)" -eq 20 ]
|
|
|
|
out="$(printf '%s\n' "$rows" | prevlog_cap 'twelve')"
|
|
|
|
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 12 ]
|
|
}
|
|
|
|
@test "logfile name joins namespace pod and container with underscores" {
|
|
name="$(prevlog_logfile_name tenant-test mariadb-test-0 mariadb)"
|
|
|
|
[ "$name" = "tenant-test_mariadb-test-0_mariadb.log" ]
|
|
}
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# Whole-script runs against a stub kubectl. Everything above pins a pure #
|
|
# helper; these pin the artifact the script leaves behind, which is what a #
|
|
# reader of the uploaded report actually gets. The script's own explanations of #
|
|
# why a capture is short -- the cap, an unreachable API -- used to exist only on #
|
|
# the job log's stdout, so the report carried N dumps and no way to tell N from #
|
|
# "all of them". Each run below asserts the explanation is IN the output #
|
|
# directory. #
|
|
# #
|
|
# The stub answers `kubectl get` from PREVLOG_STUB_ROWS (or fails when #
|
|
# PREVLOG_STUB_LIST_FAIL is set) and `kubectl logs` with one line, so no cluster #
|
|
# is involved. #
|
|
# --------------------------------------------------------------------------- #
|
|
|
|
prevlog_stub_dir() {
|
|
_sd="$1"
|
|
cat > "$_sd/kubectl" <<'STUB'
|
|
#!/bin/sh
|
|
case "$1" in
|
|
get) if [ -n "${PREVLOG_STUB_LIST_FAIL:-}" ]; then
|
|
# A failing cluster-wide list is preceded by one klog discovery-retry
|
|
# line per attempt, each long enough to survive a 200-character trim.
|
|
i=1
|
|
while [ "$i" -le 3 ]; do
|
|
echo 'E0728 11:51:48.306797 82827 memcache.go:265] "Unhandled Error" err="couldn'"'"'t get current server API group list: Get \"https://192.0.2.1:6443/api?timeout=32s\": dial tcp: lookup timed out after some considerable number of characters"' >&2
|
|
i=$((i + 1))
|
|
done
|
|
echo 'Error from server (Forbidden): pods is forbidden' >&2
|
|
exit 1
|
|
fi
|
|
printf '%s\n' "${PREVLOG_STUB_ROWS:-}" ;;
|
|
logs)
|
|
case "${PREVLOG_STUB_LOG_MODE:-}" in
|
|
# Killed mid-line, which is the normal shape of a SIGKILLed stream: the last
|
|
# line has no terminating newline. The script keeps such a capture, so any
|
|
# note appended to it must start a line of its own.
|
|
partial) printf 'first line\nthe decisive partial line'; exit 124 ;;
|
|
# Partial output followed by a NON-timeout failure. kubectl can write some of
|
|
# the stream and then die on its own terms -- a connection reset mid-read --
|
|
# with no clock having run out, so a marker naming the timeout would put a
|
|
# cause in the artifact that was never observed.
|
|
# A refusal with a message, used to prove the reason is lost only when the
|
|
# scratch file cannot be created -- not because the stub stayed quiet.
|
|
# Exits 0, writes NO log, and still emits a warning. The shape where dropping
|
|
# the message costs most: the script would otherwise report "produced no
|
|
# output", a claim about the container made while kubectl was speaking.
|
|
warned_empty)
|
|
echo 'Warning: results are partial, 3 of 7 shards answered' >&2
|
|
exit 0 ;;
|
|
norefusal)
|
|
echo 'Error from server (BadRequest): previous terminated container "postgres" not found' >&2
|
|
exit 1 ;;
|
|
# Cold discovery: one klog retry line per attempt, then kubectl's actual
|
|
# reason. The first line names the retry; the cause is last.
|
|
noisy_refusal)
|
|
i=1
|
|
while [ "$i" -le 3 ]; do
|
|
echo 'E0728 11:51:48.306797 82827 memcache.go:265] "Unhandled Error" err="couldn'"'"'t get current server API group list: dial tcp: lookup timed out"' >&2
|
|
i=$((i + 1))
|
|
done
|
|
echo 'Error from server (BadRequest): previous terminated container "postgres" in pod "db-0" not found' >&2
|
|
exit 1 ;;
|
|
# Returns the log AND writes two warnings: kubectl does this for deprecation
|
|
# notices and partial results, and both are evidence.
|
|
warned)
|
|
printf 'stub previous-instance line\n'
|
|
echo 'Warning: v1 is deprecated in this build' >&2
|
|
echo 'Warning: results are partial, 3 of 7 shards answered' >&2 ;;
|
|
partial_reset)
|
|
printf 'first line\nthe decisive partial line'
|
|
echo 'error: unexpected EOF from the server' >&2
|
|
exit 1 ;;
|
|
# SIGKILLed part way through: 137, output kept. Our own `-k` grace produces
|
|
# this, and so does anything else that kills the read.
|
|
partial9) printf 'first line\nthe decisive partial line'; exit 137 ;;
|
|
*) printf 'stub previous-instance line\n' ;;
|
|
esac ;;
|
|
esac
|
|
exit 0
|
|
STUB
|
|
chmod +x "$_sd/kubectl"
|
|
# Stub `timeout` too. Without it these tests need GNU coreutils on PATH, and a
|
|
# host lacking it does not merely fail — a missing `timeout` makes the script
|
|
# exit 127, which reaches the SAME "could not list pods" branch the
|
|
# unreachable-API test asserts on, so that test would pass without its stub
|
|
# doing anything. A guard that can pass for the wrong reason is not a guard.
|
|
cat > "$_sd/timeout" <<'STUB'
|
|
#!/bin/sh
|
|
if [ "$1" = "-k" ]; then shift 2; fi
|
|
shift
|
|
exec "$@"
|
|
STUB
|
|
chmod +x "$_sd/timeout"
|
|
}
|
|
|
|
@test "an unreachable api leaves the reason in the output directory" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_LIST_FAIL=1 sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# Without a note the reader sees an absent directory, which reads exactly like
|
|
# "nothing crash-looped" -- the opposite of what happened.
|
|
[ -f "$out/capture-notes.txt" ]
|
|
grep -q 'could not list pods' "$out/capture-notes.txt"
|
|
# kubectl's reason is the finding. "could not list pods (kubectl exit 1)" names
|
|
# no cause, and this is the read every later line depends on -- if it fails,
|
|
# nothing is captured at all.
|
|
grep -q 'Forbidden' "$out/capture-notes.txt"
|
|
# The reason is the LAST stderr line: a failing cluster-wide list is preceded by
|
|
# one klog discovery-retry line per attempt, long enough to survive trimming.
|
|
if grep -q 'Unhandled Error' "$out/capture-notes.txt"; then echo "FAIL: quoted the discovery noise instead of the reason"; false; fi
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a cluster where nothing restarted says so in the output directory" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
rows='cozy-system|healthy-0|app|container|0'
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
[ -f "$out/capture-notes.txt" ]
|
|
grep -q 'no container has restarted' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "the inner read budgets stay under the backstop the callers wrap this in" {
|
|
# Three comment blocks state this arithmetic in prose -- the script header,
|
|
# hack/cozytest.sh and hack/e2e-chainsaw/.chainsaw.yaml -- and nothing enforced
|
|
# it, so raising a per-read timeout (or adding a `-k` grace, which counts towards
|
|
# the same ceiling) silently moved the worst case past the backstop. Overrunning
|
|
# it is not a slow capture: the backstop SIGKILLs the process group, so
|
|
# capture-notes.txt ends short and the line explaining why reaches the job log
|
|
# only, which is the failure these notes exist to prevent.
|
|
# Read from the resolved bound, not from a literal on the call line: the list
|
|
# read now goes through $PREVLOG_LIST_BOUND so that a host without `timeout`
|
|
# falls back instead of exiting 127. The numbers moved to the assignment; the
|
|
# arithmetic they feed did not.
|
|
list="$(sed -n 's/^ PREVLOG_LIST_BOUND="timeout -k \([0-9]*\) .*"/\1/p' "$SCRIPT") $(sed -n 's/^PREVLOG_LIST_TIMEOUT=\([0-9]*\)/\1/p' "$SCRIPT")"
|
|
read_="$(sed -n 's/^PREVLOG_READ_GRACE=\([0-9]*\)/\1/p' "$SCRIPT") $(sed -n 's/^PREVLOG_READ_TIMEOUT=\([0-9]*\)/\1/p' "$SCRIPT")"
|
|
cap=$(sed -n 's/^MAX="${COZY_PREVLOG_MAX:-\([0-9]*\)}"/\1/p' "$SCRIPT")
|
|
[ -n "$list" ] && [ -n "$read_" ] && [ -n "$cap" ]
|
|
|
|
list_ceiling=$(( $(echo "$list" | cut -d' ' -f1) + $(echo "$list" | cut -d' ' -f2) ))
|
|
read_ceiling=$(( $(echo "$read_" | cut -d' ' -f1) + $(echo "$read_" | cut -d' ' -f2) ))
|
|
worst=$(( list_ceiling + cap * read_ceiling ))
|
|
|
|
# The message that reports a cut-off must quote the budget that produced it,
|
|
# otherwise it names a number no read ever used. Two bounds exist -- the list
|
|
# read is wrapped in its own, larger one -- so what has to hold is the PAIRING:
|
|
# every call passes the seconds belonging to the bound it also passes. Getting
|
|
# that wrong is silent, and it puts a number in the artifact that no read used.
|
|
pairs=$(grep -o 'prevlog_cutoff_desc "[^"]*" "\$[A-Z_]*" "\$[A-Z_]*"' "$SCRIPT" |
|
|
sed 's/.*"\(\$[A-Z_]*\)" "\(\$[A-Z_]*\)"/\1 \2/' | LC_ALL=C sort -u)
|
|
[ -n "$pairs" ] || { echo "FAIL: no cut-off description is derived from a bound"; false; }
|
|
printf '%s\n' "$pairs" | while read -r secs bound; do
|
|
case "$secs $bound" in
|
|
'$PREVLOG_READ_TIMEOUT $PREVLOG_BOUND') ;;
|
|
'$PREVLOG_LIST_TIMEOUT $PREVLOG_LIST_BOUND') ;;
|
|
*) echo "FAIL: $secs is quoted for a read bounded by $bound"; exit 1 ;;
|
|
esac
|
|
done
|
|
|
|
for caller in "$HACK_DIR/cozytest.sh" "$HACK_DIR/e2e-chainsaw/.chainsaw.yaml"; do
|
|
backstop=$(sed -n 's/.*timeout -k [0-9]* \([0-9]*\) .*e2e-capture-previous-logs\.sh.*/\1/p' "$caller" | head -n 1)
|
|
[ -n "$backstop" ]
|
|
if [ "$worst" -gt "$backstop" ]; then
|
|
echo "FAIL: worst case ${worst}s (list ${list_ceiling}s + ${cap} x ${read_ceiling}s) exceeds the ${backstop}s backstop in $caller"
|
|
false
|
|
fi
|
|
done
|
|
}
|
|
|
|
@test "an unwritable temp dir does not become a claim about the cluster" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
# A path that does not exist, not one that is unwritable: root holds
|
|
# CAP_DAC_OVERRIDE and mktemp would succeed inside a 0500 directory, so the test
|
|
# would pass without entering the fallback. ENOENT is refused for everyone.
|
|
PATH="$stub:$PATH" TMPDIR="$tmp/gone" \
|
|
PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# With a predictable "$$" scratch path the redirect targets a file under a TMPDIR
|
|
# that is not there, the read never runs, and the capture reports that no previous
|
|
# instance was retrieved -- a statement about the cluster caused entirely by the
|
|
# local filesystem. mktemp fails too, but a failed command substitution already
|
|
# yields an empty string here, and `${err:-/dev/null}` then keeps the read alive.
|
|
if grep -q 'no previous instance retrieved' "$out/capture-notes.txt" 2>/dev/null; then
|
|
echo "FAIL: blamed the cluster for an unwritable TMPDIR"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
[ "$(ls "$out" | grep -c '\.log$')" -eq 1 ]
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "hitting the container cap records the overflow next to the captured logs" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
rows="$(printf '%s\n' \
|
|
'tenant-test|db-0|postgres|container|4' \
|
|
'tenant-test|db-1|postgres|container|3' \
|
|
'cozy-system|other-0|app|container|2')"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" COZY_PREVLOG_MAX=1 \
|
|
sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
[ -f "$out/capture-notes.txt" ]
|
|
grep -q 'COZY_PREVLOG_MAX=1 cap' "$out/capture-notes.txt"
|
|
grep -q '2 more restarted container(s) NOT captured' "$out/capture-notes.txt"
|
|
# The cap still applied: one dump, not three.
|
|
[ "$(ls "$out" | grep -c '\.log$')" -eq 1 ]
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a missing timeout is named as a local dependency, not as a cluster failure" {
|
|
tmp="$(mktemp -d)"
|
|
bin="$tmp/bin"; mkdir -p "$bin"
|
|
out="$tmp/previous-logs"
|
|
# A PATH with everything the script needs EXCEPT timeout. Not a blanket empty
|
|
# PATH: that would also remove the interpreter and the script would die before
|
|
# its own fallback, passing for the wrong reason.
|
|
for b in sh mktemp grep sed awk cat rm mkdir tail head cut ls date printf; do
|
|
p=$(command -v "$b" 2>/dev/null) && ln -sf "$p" "$bin/$b"
|
|
done
|
|
cat > "$bin/kubectl" <<'STUB'
|
|
#!/bin/sh
|
|
exit 0
|
|
STUB
|
|
chmod +x "$bin/kubectl"
|
|
|
|
PATH="$bin" sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# Without the fallback every `timeout` call exits 127, and the script reports
|
|
# "could not list pods (kubectl exit 127): timeout: command not found" --
|
|
# attributing to kubectl a failure in which kubectl never ran, inside the
|
|
# artifact rather than only the job log.
|
|
[ -f "$out/capture-notes.txt" ]
|
|
if grep -q 'kubectl exit 127' "$out/capture-notes.txt"; then
|
|
echo "FAIL: a missing local binary is reported as a kubectl failure"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
grep -q 'timeout is not on PATH' "$out/capture-notes.txt"
|
|
grep -q 'not a statement about the cluster' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a missing kubectl leaves a note rather than an empty directory" {
|
|
tmp="$(mktemp -d)"
|
|
bin="$tmp/bin"; mkdir -p "$bin"
|
|
out="$tmp/previous-logs"
|
|
# A PATH carrying only what the script needs before the kubectl check, so the
|
|
# check is the only thing that fails. Blanking PATH outright would also take
|
|
# away the interpreter and mkdir, and the script would die before its own
|
|
# guard -- passing the test for the wrong reason.
|
|
ln -s "$(command -v mkdir)" "$bin/mkdir"
|
|
|
|
# One caller pre-gates on kubectl, the other does not. A silent exit here
|
|
# leaves the artifact carrying an empty directory, which reads as "looked,
|
|
# found no crash-loops".
|
|
PATH="$bin" /bin/sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
[ -f "$out/capture-notes.txt" ]
|
|
grep -q 'kubectl is not on PATH' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "each captured log says which tail bound it was written under" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# `--tail` drops the OLDEST lines and nothing in the output says so, so a file
|
|
# beginning mid-stream is indistinguishable from a whole one. This is the case
|
|
# where that matters most: the previous instance is already gone from the
|
|
# cluster, so this file is the only copy, and the bound here is ten times
|
|
# tighter than the per-pod one. Naming it in the job log is not enough -- the
|
|
# job log expires and is not in the tarball at all.
|
|
# Beside the log, not inside it: a log read in full is a complete artifact and
|
|
# these controllers log JSON per line, so a trailing prose line breaks every
|
|
# parser that could read the file before.
|
|
if grep -q 'holds at most the last' "$file"; then
|
|
echo "FAIL: the bound note is inside a successfully captured log"
|
|
false
|
|
fi
|
|
if ! grep -q 'holds at most the last 200 lines' "$out/capture-notes.txt"; then
|
|
echo "FAIL: the captured log does not name the tail bound it was written under"
|
|
cat "$file"
|
|
false
|
|
fi
|
|
# The bound named is the one that was applied, not the default echoed back.
|
|
rm -rf "$out"
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
COZY_PREVLOG_TAIL=7 sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
grep -q 'last 7 lines' "$out/capture-notes.txt"
|
|
grep -q 'COZY_PREVLOG_TAIL=7' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a warning alongside a captured log is kept whole, not dropped" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=warned sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# The log itself stays clean: it was returned in full, and these controllers
|
|
# log JSON per line. But "not in the log" and "not in the artifact" are
|
|
# different outcomes, and only the first is intended.
|
|
if grep -q 'deprecated' "$file"; then
|
|
echo "FAIL: the warning is inside the log"; false
|
|
fi
|
|
# Both lines, not just the last: with no klog preamble to skip, each is a
|
|
# warning of its own and picking one drops the other.
|
|
grep -q 'v1 is deprecated' "$out/capture-notes.txt" || {
|
|
echo "FAIL: the first warning was dropped"; cat "$out/capture-notes.txt"; false
|
|
}
|
|
grep -q 'results are partial' "$out/capture-notes.txt" || {
|
|
echo "FAIL: the second warning was dropped"; cat "$out/capture-notes.txt"; false
|
|
}
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a clean read that logged nothing keeps what kubectl said about it" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=warned_empty sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# kubectl exited 0, returned no log, and still spoke. Gating the warning copy on
|
|
# the log being non-empty drops the message entirely, and the next line then
|
|
# reports "produced no output" -- a positive statement about the container,
|
|
# manufactured while kubectl was in the middle of contradicting it.
|
|
grep -q 'results are partial' "$out/capture-notes.txt" || {
|
|
echo "FAIL: kubectl spoke on an empty read and the message was dropped"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
}
|
|
# And the two lines must agree: no bare claim of silence beside a quoted message.
|
|
if grep -q 'produced no output' "$out/capture-notes.txt"; then
|
|
echo "FAIL: reported silence in the same file that quotes what kubectl said"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a partial capture still records the tail bound it was read under" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=partial sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# The cut took the newest lines, `--tail` took the oldest, and only the cut was
|
|
# recorded. A reader then treats the first line of the file as the first line
|
|
# the container wrote.
|
|
grep -q 'holds at most the last' "$out/capture-notes.txt" || {
|
|
echo "FAIL: a partial capture does not record its tail bound"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
}
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "the tail bound is stated once for the run, not once per container" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4
|
|
tenant-test|db-0|sidecar|container|2
|
|
cozy-system|api-0|app|container|1' \
|
|
sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# The bound is identical for every log the capture writes, so repeating it per
|
|
# container put up to COZY_PREVLOG_MAX copies of one sentence into the file a
|
|
# reader holding only the artifact opens FIRST -- the same file that has to make
|
|
# a short capture's reasons findable. Three containers, one statement.
|
|
n=$(grep -c 'holds at most the last' "$out/capture-notes.txt" || true)
|
|
if [ "$n" -ne 1 ]; then
|
|
echo "FAIL: expected exactly one tail-bound note for the run, found $n"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
# Still says which bound, and still applies to the whole directory rather than
|
|
# to one named file, or the reader cannot tell which logs it covers.
|
|
grep -q 'every previous-instance log in this directory holds at most the last 200 lines' \
|
|
"$out/capture-notes.txt"
|
|
# Three captures really did happen, so the single note is not an artefact of the
|
|
# walk having stopped after one.
|
|
[ "$(grep -c . "$out/capture-notes.txt")" -gt 1 ]
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "the tail note starts a line of its own after a killed stream" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=partial sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# A killed read drops the NEWEST lines; --tail drops the OLDEST. They are not
|
|
# interchangeable, and the tail note alone is worse here than no note at all: it
|
|
# gives the reader a confident explanation of why the beginning is missing while
|
|
# saying nothing about the missing end, so a log cut off mid-stream reads as a
|
|
# complete-to-the-last-line window. The TRUNCATED line reaches capture-notes.txt,
|
|
# but a reader standing in the .log is not looking there.
|
|
if ! grep -q '^\[capture-previous-logs\] TRUNCATED: this log ends here' "$file"; then
|
|
echo "FAIL: a killed read is not marked as cut off inside the log itself"
|
|
cat "$file"
|
|
false
|
|
fi
|
|
# And it must NOT claim the file is a clean tail window, which is the false half.
|
|
if grep -q 'holds at most the last' "$file"; then
|
|
echo "FAIL: a truncated capture claims to be a complete tail window"
|
|
cat "$file"
|
|
false
|
|
fi
|
|
# The marker starts a line of its own: a read killed mid-stream leaves a partial
|
|
# final line, so appending blind would glue the marker onto it, corrupting the
|
|
# decisive last line and making a start-of-line grep miss it.
|
|
grep -q '^the decisive partial line$' "$file"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a partial capture that was not a timeout does not claim to be one" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=partial_reset sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# kubectl can write part of the stream and then fail on its own terms, with no
|
|
# clock having run out. Naming the read timeout there states a cause that was
|
|
# never observed -- the same defect as a tail note on a truncated file, in the
|
|
# other direction: a confident explanation that happens to be false.
|
|
if grep -qE 'its own [0-9]+s timeout|SIGKILL' "$file"; then
|
|
echo "FAIL: a non-timeout failure is reported as the read timeout"
|
|
cat "$file"
|
|
false
|
|
fi
|
|
grep -q '^\[capture-previous-logs\] TRUNCATED: this log ends here because kubectl exited 1' "$file"
|
|
# kubectl's own reason survives into the file rather than only the exit code.
|
|
grep -q 'unexpected EOF' "$file"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a capture killed by a signal does not assert whose signal it was" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=partial9 sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# 137 is 128+SIGKILL. Our own `-k` grace produces it, and so does the OOM killer
|
|
# on a loaded runner or a teardown signalling the process group -- the exit
|
|
# status does not say which. The cut-off branch is right either way, since the
|
|
# capture ends before the log did; "timed out after 18s" is not, and a read
|
|
# killed at second two then reads as one that waited the full eighteen.
|
|
grep -q '^\[capture-previous-logs\] TRUNCATED: this log ends here' "$file"
|
|
grep -q 'SIGKILL' "$file"
|
|
grep -q 'does not tell apart' "$file"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a capture that ran out its own clock says so without a disjunction" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=partial sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# The converse, and why the hedge is written per status rather than over both:
|
|
# 124 comes from `timeout` and from nothing else, so hedging it too would trade
|
|
# one false note for a vague one everywhere.
|
|
grep -q 'its own 18s timeout' "$file"
|
|
if grep -q 'SIGKILL' "$file"; then
|
|
echo "FAIL: hedged a 124, which only timeout produces"
|
|
cat "$file"
|
|
false
|
|
fi
|
|
# capture-notes.txt describes the SAME read and has to agree with the marker in
|
|
# the log. Asserting only on the .log left the notes free to call a 124 "kubectl
|
|
# exit 124" -- a status this script's own clock produced, attributed to kubectl,
|
|
# in the file a reader opens first.
|
|
grep -q 'cut off by' "$out/capture-notes.txt" || {
|
|
echo "FAIL: the notes describe a timeout as a plain kubectl exit"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
}
|
|
if grep -q 'TRUNCATED (kubectl exit' "$out/capture-notes.txt"; then
|
|
echo "FAIL: the notes and the log disagree about the same read"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "an unusable output directory is not reported as kubectl failing" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
# A FILE where the parent directory should be, so `mkdir -p` fails for every
|
|
# uid. A chmod-based fixture would pass for root, which is how CI runs this.
|
|
: > "$tmp/blocked"
|
|
out="$tmp/blocked/previous-logs"
|
|
|
|
run_out="$(PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
sh "$SCRIPT" "$out" tenant-test 2>&1 || true)"
|
|
|
|
# A redirection that cannot open its target fails before kubectl runs, and the
|
|
# shell status lands in the branch that names kubectl. Once per container, the
|
|
# report then blames the cluster for a directory the caller got wrong.
|
|
if printf '%s\n' "$run_out" | grep -q 'kubectl exit'; then
|
|
echo "FAIL: a local filesystem condition is reported as kubectl failing"
|
|
printf '%s\n' "$run_out"
|
|
false
|
|
fi
|
|
printf '%s\n' "$run_out" | grep -q 'cannot write to'
|
|
printf '%s\n' "$run_out" | grep -q 'says nothing about whether anything crash-looped'
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a zero tail is refused rather than turned into a claim about the cluster" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
COZY_PREVLOG_TAIL=0 sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# `--tail=0` returns nothing and kubectl still exits 0, so the empty-output
|
|
# branch would delete the capture and report that the previous instance
|
|
# "produced no output" -- a positive statement about the cluster produced
|
|
# entirely by a typo, which also discards the only remaining copy of a log the
|
|
# kubelet has already collected.
|
|
if grep -q 'produced no output' "$out/capture-notes.txt"; then
|
|
echo "FAIL: a zero tail was reported as the container having logged nothing"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
grep -q "ignoring COZY_PREVLOG_TAIL='0'" "$out/capture-notes.txt"
|
|
# The fallback applied, so the capture is there and names the bound that was used.
|
|
grep -q 'last 200 lines' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a tail of -1 claims no bound, because none was applied" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
COZY_PREVLOG_TAIL=-1 sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
file="$(ls "$out"/*.log)"
|
|
# -1 is the documented spelling for "the whole log". A note reading "holds at
|
|
# most the last -1 lines" would describe a bound that was never applied, which
|
|
# is the same class as claiming a truncated file is complete: a statement about
|
|
# the artifact that the artifact does not support.
|
|
if grep -q 'holds at most' "$file"; then
|
|
echo "FAIL: an unbounded read claims a tail bound"
|
|
cat "$file"
|
|
false
|
|
fi
|
|
# And -1 is not treated as malformed: it is a supported request, not a typo.
|
|
if grep -q 'ignoring COZY_PREVLOG_TAIL' "$out/capture-notes.txt"; then
|
|
echo "FAIL: -1 was rejected as malformed"
|
|
false
|
|
fi
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "an oversized knob falls back instead of silently losing every row" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
huge=999999999999999999999999999999
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
COZY_PREVLOG_MAX="$huge" sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# A digits-only value that `test` and `head` cannot compute with does not merely
|
|
# fail to cap -- under dash `[ -eq ]` errors and `head` rejects the count, so
|
|
# prevlog_cap emits nothing and the caller reports zero containers kept "because
|
|
# the cap was reached". The cap that broke collection would be named as the
|
|
# reason collection found nothing.
|
|
grep -q "ignoring COZY_PREVLOG_MAX='$huge'" "$out/capture-notes.txt"
|
|
# The fallback applied, so the row survived rather than being lost to the knob.
|
|
[ "$(ls "$out" | grep -c '\.log$')" -eq 1 ]
|
|
if grep -q 'capturing previous-instance logs for 0 of' "$out/capture-notes.txt"; then
|
|
echo "FAIL: an unusable cap was reported as having capped everything away"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "an uncapturable reason is not reported as no message from kubectl" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
# mktemp fails, so the stderr scratch file never exists and $reason stays empty.
|
|
# `${reason:-no message from kubectl}` then states a fact about kubectl that was
|
|
# never observed.
|
|
PATH="$stub:$PATH" TMPDIR=/nonexistent-prevlog-probe \
|
|
PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=norefusal sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
[ -f "$out/capture-notes.txt" ] || { echo "FAIL: no notes written at all"; false; }
|
|
if grep -q 'no message from kubectl' "$out/capture-notes.txt"; then
|
|
echo "FAIL: an uncapturable message is reported as kubectl having sent none"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "the reason quoted is kubectl's, not the klog retry line above it" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS='tenant-test|db-0|postgres|container|4' \
|
|
PREVLOG_STUB_LOG_MODE=noisy_refusal sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# A read against cold discovery is preceded by one klog retry line per attempt,
|
|
# and kubectl's actionable message comes last. Taking the first line names the
|
|
# retry instead of the cause -- and since this value now reaches the artifact
|
|
# rather than only the job log, the artifact would ship the wrong cause. Every
|
|
# other stderr quote in these scripts already takes the last line; this one did
|
|
# not, and nothing pinned which end it used.
|
|
if grep -q "couldn't get current server API group list" "$out/capture-notes.txt"; then
|
|
echo "FAIL: quoted the klog retry line instead of kubectl's reason"
|
|
cat "$out/capture-notes.txt"
|
|
false
|
|
fi
|
|
grep -q 'previous terminated container' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|
|
|
|
@test "a second capture run into the same directory is separated from the first" {
|
|
tmp="$(mktemp -d)"
|
|
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
|
|
out="$tmp/previous-logs"
|
|
rows='cozy-system|healthy-0|app|container|0'
|
|
|
|
PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
PATH="$stub:$PATH" PREVLOG_STUB_LIST_FAIL=1 sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
|
|
|
|
# Notes are appended, so without a separator one run's "nothing restarted"
|
|
# sits flush against the next run's "could not list pods" and the file stops
|
|
# being able to explain either.
|
|
grep -q -- '--- new capture run ---' "$out/capture-notes.txt"
|
|
grep -q 'no container has restarted' "$out/capture-notes.txt"
|
|
grep -q 'could not list pods' "$out/capture-notes.txt"
|
|
rm -rf "$tmp"
|
|
}
|