mirror of
https://github.com/cozystack/cozystack.git
synced 2026-11-13 08:05:19 +09:00
Assisted-By: GPT-5 <noreply@openai.com> Signed-off-by: Myasnikov Daniil <myasnikovdaniil2001@gmail.com>
704 lines
39 KiB
Bash
Executable File
704 lines
39 KiB
Bash
Executable File
#!/bin/sh
|
|
# e2e-capture-previous-logs.sh - dump the PREVIOUS container instance's logs for
|
|
# every container that has restarted.
|
|
#
|
|
# DIAGNOSTIC ONLY. This runs on an already-failed test, never mutates the
|
|
# cluster, and never changes the test's pass/fail outcome. Every failure is
|
|
# swallowed, and every kubectl call is individually time-boxed when `timeout` is
|
|
# on PATH -- when it is not, the reads run unbounded rather than not at all, a
|
|
# line says so, and the caller's outer backstop is what bounds them.
|
|
#
|
|
# Why this exists: when a pod crash-loops, the decisive evidence is almost
|
|
# always in the immediately preceding terminated instance -- the interrupted
|
|
# bootstrap, the assertion that killed the process, the config error that made
|
|
# the entrypoint exit. `kubectl logs <pod> -c <container>` only ever shows the
|
|
# CURRENT instance, which for a crash-looping container is the Nth restart: a
|
|
# fresh, uninformative replay of the same startup path. That instance is
|
|
# reachable only via `--previous`, and once the kubelet garbage-collects that
|
|
# dead container the evidence is gone for good.
|
|
#
|
|
# The Chainsaw suites capture current logs through the built-in `podLogs`
|
|
# collector, which has no `previous` option in chainsaw v0.2.15, so this
|
|
# closes that gap for every suite at once
|
|
# from the global catch rather than per-suite. The crust-gather snapshot does
|
|
# collect previous.log per container, but that is a whole archive to download
|
|
# and `crust-gather serve`; this puts the decisive lines directly in the failed
|
|
# job's log, and keeps them even when the snapshot is truncated.
|
|
#
|
|
# Selection is discovered at runtime, never hardcoded: any container (including
|
|
# init containers -- an interrupted bootstrap lives there) whose restartCount is
|
|
# greater than zero. Containers that never restarted are skipped, so the common
|
|
# healthy case costs one line saying nothing restarted, rather than a page of
|
|
# "previous terminated container not found" noise. That one line is written, not
|
|
# omitted: an absent capture-notes.txt is indistinguishable from a capture that
|
|
# never ran.
|
|
#
|
|
# Ordering, where the cap binds: the failing test's namespace first, and within
|
|
# each namespace group the most recent restart first (prevlog_sort_recent). The
|
|
# restarts alive on a cluster at any moment span days, and install-time restarts
|
|
# have a head start on every app suite that runs afterwards, so without a time
|
|
# key the cap was routinely spent on containers that had already stopped
|
|
# restarting before the failing test began. Nothing is dropped for being old --
|
|
# an install-time restart is the explanation when the install is what broke.
|
|
#
|
|
# Usage: e2e-capture-previous-logs.sh <output-dir> [preferred-namespace]
|
|
#
|
|
# Environment:
|
|
# COZY_PREVLOG_MAX max containers to dump (default 12); the overflow count
|
|
# goes to the job log and to <output-dir>/capture-notes.txt,
|
|
# never silently dropped. Raising it past ~13
|
|
# trades one bounded report for another: the callers wrap
|
|
# this script in a 300s backstop and the worst case is
|
|
# ~30s for the pod list plus 20s per container, so beyond
|
|
# that the backstop starts cutting the capture instead of
|
|
# the cap reporting it. Widen the callers' backstop too.
|
|
# COZY_PREVLOG_TAIL lines per container (default 200). The bound each capture
|
|
# was written under is named in capture-notes.txt beside the
|
|
# logs, not inside them: --tail drops the OLDEST lines and
|
|
# nothing in the output says so, but a log read in full is a
|
|
# complete artifact and a trailing prose line breaks every
|
|
# parser that could read it before. -1 asks for
|
|
# the whole log and suppresses that note, since no bound was
|
|
# applied. A malformed value, a zero, or a leading zero falls
|
|
# back to 200 and says so in capture-notes.txt: --tail=0 asks
|
|
# kubectl for nothing, which this script would otherwise
|
|
# report as the container having logged nothing, and a leading
|
|
# zero is octal to `$(( ))` and decimal to `[`.
|
|
|
|
# --------------------------------------------------------------------------- #
|
|
# Pure, side-effect-free helpers. #
|
|
# Each takes text on stdin / in args and emits text -- no kubectl, no globals #
|
|
# -- so hack/capture-previous-logs.bats can source this file (with #
|
|
# E2E_CAPTURE_PREVLOGS_LIB set, see the guard below) and unit-test the #
|
|
# restart filtering, namespace prioritisation, recency ordering and capping #
|
|
# against mock input #
|
|
# without a cluster. Keep them above the guard and free of any runtime state. #
|
|
# --------------------------------------------------------------------------- #
|
|
|
|
# prevlog_filter_restarted: stdin = `ns|pod|container|kind|restartCount|finishedAt`
|
|
# rows (one container per line, as emitted by the kubectl go-template in main).
|
|
# finishedAt is when the PREVIOUS instance terminated, and may be empty -- see
|
|
# prevlog_sort_recent.
|
|
# Emits only the rows whose restartCount parses as an integer greater than
|
|
# zero -- i.e. the containers that actually HAVE a previous instance to read.
|
|
# A row whose count is empty, non-numeric or zero is dropped: asking for
|
|
# `--previous` there is guaranteed to fail and would only add noise.
|
|
prevlog_filter_restarted() {
|
|
while IFS='|' read -r ns pod container kind restarts finished; do
|
|
[ -n "$ns" ] && [ -n "$pod" ] && [ -n "$container" ] || continue
|
|
# Reject anything that is not a bare non-negative integer before comparing.
|
|
# This is not load-bearing for control flow -- `[ "<none>" -gt 0 ]` exits 2,
|
|
# so the `|| continue` below would drop the row regardless. What it buys is
|
|
# silence: without it every malformed row also prints an "Illegal number"
|
|
# line to stderr, straight into the failing job's log.
|
|
case "$restarts" in
|
|
'' | *[!0-9]*) continue ;;
|
|
esac
|
|
[ "$restarts" -gt 0 ] || continue
|
|
printf '%s|%s|%s|%s|%s|%s\n' "$ns" "$pod" "$container" "$kind" "$restarts" "$finished"
|
|
done
|
|
}
|
|
|
|
# prevlog_sort_recent: stdin = rows, stdout = the same rows, newest previous
|
|
# instance first, rows carrying no timestamp last, ties left in input order.
|
|
#
|
|
# Why this exists. prevlog_prioritize below keeps the cap from being spent on
|
|
# containers unrelated to the failing test, and until now "unrelated" meant only
|
|
# "in another namespace". Time was not part of it, so a container that restarted
|
|
# once during cluster bring-up competed on equal footing with one that
|
|
# crash-looped during the test -- and won whenever the list happened to reach it
|
|
# first. Measured on a live stand, the restarts present at any moment span days
|
|
# (a nine-day spread, measured on a development cluster), and in CI the
|
|
# install-time restarts have that head start: they exist before the first app
|
|
# suite runs, so every failed test afterwards pays for them. A restart that
|
|
# finished before the test began cannot explain the test's failure.
|
|
#
|
|
# Ordering, not filtering, and deliberately so: an install-time restart IS the
|
|
# explanation when the install is what broke, and this capture has no reference
|
|
# point for "when the test began" that would make a cutoff honest. Sorting costs
|
|
# nothing when the cap does not bind and picks the right dozen when it does.
|
|
#
|
|
# Lexicographic sort over RFC3339 UTC is chronological: kubectl renders these as
|
|
# fixed-width Z-suffixed strings, so no date parsing is needed. Reverse puts the
|
|
# newest first and, because the empty string sorts below every timestamp, leaves
|
|
# the rows whose lastState has already been dropped by the kubelet at the end.
|
|
# -s keeps equal timestamps in input order, which a node reboot produces in
|
|
# bulk; without it the order of a dozen simultaneous restarts would vary between
|
|
# runs. Rows with no timestamp at all therefore pass through untouched, which is
|
|
# also what keeps this a no-op for callers that pass 5-field rows.
|
|
prevlog_sort_recent() {
|
|
# LC_ALL=C because the key is a fixed-format ASCII timestamp: collation buys
|
|
# nothing here and a locale that reorders punctuation could only surprise.
|
|
#
|
|
# Falls back to the input order rather than to nothing. The caller compares
|
|
# row counts to report the cap, so a sort that died would otherwise be
|
|
# indistinguishable from a cap overflow -- it would report "0 of N captured,
|
|
# N more not captured" and send the reader looking for a cap that never
|
|
# fired. Ordering is an optimisation over which dozen rows to keep; losing it
|
|
# must not lose the rows. `sort -s` and the per-key `r` are both extensions
|
|
# (GNU, BSD and busybox all carry them, which is why this is a fallback and
|
|
# not a reimplementation), so this is the branch a stricter POSIX sort takes.
|
|
# Anything in the timestamp column that is not shaped like one is treated as
|
|
# undated. Two reasons, and the second is why this is not redundant with the
|
|
# template guard above it: `<no value>` sorts ABOVE every digit, so a single
|
|
# such row would take the front of the queue from the newest real restart;
|
|
# and the header prints this field verbatim, so a non-timestamp there becomes
|
|
# a claim about a time nothing observed. Normalising to empty puts the row
|
|
# last and prints nothing, which are both already handled paths.
|
|
#
|
|
# Only when the field exists: setting $6 on a five-field row would append a
|
|
# separator and change its shape. The pattern is spelled out character by
|
|
# character rather than with an interval like {4}, which older mawk does not
|
|
# support and Ubuntu's default awk is mawk.
|
|
_psr_rows=$(awk -F'|' -v OFS='|' \
|
|
'{ if (NF >= 6 && $6 !~ /^[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T/) $6 = ""; print }')
|
|
[ -n "$_psr_rows" ] || return 0
|
|
if _psr_out=$(printf '%s\n' "$_psr_rows" | LC_ALL=C sort -s -t'|' -k6,6r 2>/dev/null); then
|
|
printf '%s\n' "$_psr_out"
|
|
else
|
|
echo "[capture-previous-logs] sort unavailable for recency ordering; keeping discovery order" >&2
|
|
printf '%s\n' "$_psr_rows"
|
|
fi
|
|
}
|
|
|
|
# prevlog_prioritize: stdin = filtered rows, $1 = the failing test's namespace.
|
|
# Emits the rows whose namespace matches $1 first, then everything else, each
|
|
# group ordered newest-restart-first by prevlog_sort_recent. On a broadly
|
|
# degraded cluster the container cap below would otherwise be spent on unrelated
|
|
# cozy-* restarts while the pod the test actually failed on -- the whole reason
|
|
# we are here -- falls off the end. Namespace stays the primary key and recency
|
|
# only breaks ties within a group: a stale restart in the failing test's own
|
|
# namespace is still likelier to be relevant than a fresh one three namespaces
|
|
# away. An empty $1 orders the whole input by recency.
|
|
prevlog_prioritize() {
|
|
_pp_ns="$1"
|
|
if [ -z "$_pp_ns" ]; then
|
|
prevlog_sort_recent
|
|
return 0
|
|
fi
|
|
# Buffer once, emit twice: stdin is consumable only once, and the two passes
|
|
# need the same rows.
|
|
# Compared, not matched: the namespace arrives from the caller and would otherwise
|
|
# be a basic regular expression, so a `.` in it would match namespaces it does not
|
|
# name. Field-scoped, so a pod merely named like the prefix is not promoted.
|
|
#
|
|
# Smaller residual, not none: `awk -v` expands backslash escapes in the value it
|
|
# assigns, so a namespace containing `\t` would arrive as a real tab. Namespaces
|
|
# are DNS labels, so it cannot happen here -- but the class is narrowed rather
|
|
# than closed, and a comment claiming otherwise is the kind of thing a later
|
|
# reader trusts instead of rechecking.
|
|
_pp_rows=$(cat)
|
|
printf '%s\n' "$_pp_rows" | awk -F'|' -v p="$_pp_ns" '$1 == p' | prevlog_sort_recent || true
|
|
printf '%s\n' "$_pp_rows" | awk -F'|' -v p="$_pp_ns" 'NF && $1 != p' | prevlog_sort_recent || true
|
|
}
|
|
|
|
# prevlog_cap: stdin = prioritised rows, $1 = max rows to keep. Emits at most $1
|
|
# rows. The caller compares the input and output counts to report the overflow;
|
|
# this helper stays pure so it can be tested without a cluster.
|
|
prevlog_cap() {
|
|
_pc_max="$1"
|
|
case "$_pc_max" in
|
|
'' | *[!0-9]*) _pc_max=12 ;;
|
|
esac
|
|
# A zero cap emits nothing; the caller still reports the full overflow count,
|
|
# so the drop stays visible. Handle it explicitly rather than via `head -n 0`:
|
|
# GNU head treats that as an empty result, but BSD/macOS head rejects it
|
|
# ("illegal line count -- 0"), which would abort a local run.
|
|
if [ "$_pc_max" -eq 0 ]; then
|
|
cat >/dev/null
|
|
else
|
|
head -n "$_pc_max"
|
|
fi
|
|
}
|
|
|
|
# prevlog_append_note <file> <text>
|
|
#
|
|
# Append a `[capture-previous-logs]` line, starting a new line first when the file
|
|
# does not already end in one. Mirrors cozyreport_append_note in hack/cozyreport.sh,
|
|
# and for the same reason: these reads are `timeout -k`-killable mid-stream, so a
|
|
# partial final line is the normal shape of a truncated capture, not an edge case.
|
|
# Appending blind glues the marker onto that line -- the last log line, which is
|
|
# the decisive one for a truncated read, is corrupted, a grep for the marker at
|
|
# start-of-line misses it, and in reverse a container whose own final write ended
|
|
# mid-sentence produces a line that reads as if the container emitted the marker
|
|
# itself.
|
|
prevlog_append_note() {
|
|
_pan_file=$1
|
|
_pan_text=$2
|
|
if [ -s "$_pan_file" ] && [ -n "$(tail -c 1 "$_pan_file" 2>/dev/null)" ]; then
|
|
printf '\n' >> "$_pan_file" || true
|
|
fi
|
|
printf '%s\n' "$_pan_text" >> "$_pan_file" || true
|
|
}
|
|
|
|
# prevlog_logfile_name: build the per-container artifact filename for a row's
|
|
# fields. Namespaces, pod names and container names are all DNS labels, so the
|
|
# only separator that needs normalising is the `|` we introduced.
|
|
prevlog_logfile_name() {
|
|
printf '%s_%s_%s.log\n' "$1" "$2" "$3"
|
|
}
|
|
|
|
# Sourcing guard: hack/capture-previous-logs.bats sets E2E_CAPTURE_PREVLOGS_LIB
|
|
# and sources this file purely to reach the helpers above; return before
|
|
# touching $1 or running any capture so the unit test never needs a cluster.
|
|
# The executing callers (the cozytest.sh failure hook and the Chainsaw global
|
|
# catch) never set it, so the guard is a no-op there.
|
|
if [ -n "${E2E_CAPTURE_PREVLOGS_LIB:-}" ]; then
|
|
return 0 2>/dev/null
|
|
fi
|
|
|
|
OUT="${1:?Usage: e2e-capture-previous-logs.sh <output-dir> [preferred-namespace]}"
|
|
PREFER_NS="${2:-}"
|
|
|
|
MAX="${COZY_PREVLOG_MAX:-12}"
|
|
TAIL="${COZY_PREVLOG_TAIL:-200}"
|
|
|
|
# The per-read budget, named once so the message that reports a timeout cannot
|
|
# quote a number the read never used. The grace counts towards the ceiling, so
|
|
# 18 + 2 is the 20s the worst-case arithmetic in the header, hack/cozytest.sh and
|
|
# .chainsaw.yaml is written against.
|
|
PREVLOG_READ_TIMEOUT=18
|
|
# The cluster-wide list gets its own, larger bound: one call against every
|
|
# namespace, where the per-container reads below are one container each.
|
|
PREVLOG_LIST_TIMEOUT=28
|
|
PREVLOG_READ_GRACE=2
|
|
|
|
# The wall-clock wrapper, resolved once. Empty when `timeout` is absent: the reads
|
|
# then run unbounded and a note says so, rather than every call exiting 127 and the
|
|
# run reporting that kubectl failed when kubectl never ran.
|
|
if command -v timeout >/dev/null 2>&1; then
|
|
PREVLOG_BOUND="timeout -k $PREVLOG_READ_GRACE"
|
|
PREVLOG_LIST_BOUND="timeout -k $PREVLOG_READ_GRACE $PREVLOG_LIST_TIMEOUT"
|
|
else
|
|
PREVLOG_BOUND=""
|
|
PREVLOG_LIST_BOUND=""
|
|
fi
|
|
|
|
# prevlog_cutoff_desc <exit-status> <seconds> <bound>: how a 124/137 should be
|
|
# described. The bound is passed in rather than read from PREVLOG_BOUND: the list
|
|
# read is wrapped by a different one, and two variables set in a single if/else
|
|
# agree only until something sets one of them alone.
|
|
#
|
|
# 124 is `timeout` and only `timeout`: the deadline passed and nothing else
|
|
# produces it. 137 is 128+SIGKILL, which our own `-k` grace produces and so does
|
|
# anything else that SIGKILLs the read -- the OOM killer on a loaded runner, a
|
|
# teardown signalling the process group. Both belong in the cut-off branch, since
|
|
# either way the capture ends before the log did; but "timed out after 30s" on a
|
|
# 137 states a cause this script never observed, and a read killed at second two
|
|
# reads as one that ran the full thirty. Same distinction cozyreport.sh draws, and
|
|
# for the same reason: these files are read by someone deciding what to look at
|
|
# next.
|
|
prevlog_cutoff_desc() {
|
|
if [ -z "$3" ]; then
|
|
printf '%s' "a signal from outside this script, which ran its reads 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
|
|
}
|
|
|
|
# Create the output directory before the first log line, not just before the
|
|
# first capture: every line below explains why the capture is smaller than the
|
|
# cluster, and until the directory exists there is nowhere to write it.
|
|
mkdir -p "$OUT" 2>/dev/null || true
|
|
NOTES="$OUT/capture-notes.txt"
|
|
# Appended, not truncated: a caller may aim two runs at one directory, and the
|
|
# earlier run's reasons are as load-bearing as the later one's. Separate them, or
|
|
# a "no container has restarted" from attempt one sits next to a "reached the
|
|
# cap" from attempt two and the file stops being able to explain anything.
|
|
if [ -s "$NOTES" ]; then
|
|
printf -- '--- new capture run ---\n' >> "$NOTES" 2>/dev/null || true
|
|
fi
|
|
|
|
# printf, not echo: under /bin/sh (dash on the CI image) echo expands backslash
|
|
# escapes, so a kubectl message containing a literal \n would split across lines
|
|
# and could forge a second "[capture-previous-logs]" verdict line.
|
|
#
|
|
# Every line goes to the artifact as well as to the job log. The job log is
|
|
# where a triager looking at a red run is already standing, but it is also the
|
|
# thing that expires, gets truncated by the runner, and is unreachable to anyone
|
|
# reading the uploaded report weeks later. That reader sees N dumps in a
|
|
# directory and no way to tell N from "all of them" -- the cap that dropped 21
|
|
# containers, the pod list that never returned, the container whose previous
|
|
# instance the kubelet had already collected, all invisible. Absent data that
|
|
# looks like absent problems is the failure mode this capture exists to prevent,
|
|
# so the reasons ship next to the logs they explain.
|
|
log() {
|
|
printf '%s\n' "[capture-previous-logs] $*"
|
|
printf '%s\n' "[capture-previous-logs] $*" >> "$NOTES" 2>/dev/null || true
|
|
}
|
|
|
|
# The output directory arrives as an argument, so it can be unusable for reasons
|
|
# that have nothing to do with the cluster: a parent that is a file, a path that
|
|
# does not exist and cannot be created, a directory this process may not write.
|
|
# Probed once here rather than left to each `> "$file"`, because a redirection
|
|
# that cannot open its target fails BEFORE kubectl runs and hands the shell's own
|
|
# status to the branch below -- which then reports "no previous instance
|
|
# retrieved (kubectl exit 2)", once per container: a local condition stated as a
|
|
# fact about the cluster, which is the mistake this script exists to stop making.
|
|
#
|
|
# Tested with `-d`/`-w` rather than by creating a probe file: a run killed between
|
|
# writing that file and removing it would ship a stray dotfile inside the
|
|
# uploaded artifact. A full filesystem slips through this check, but that is the
|
|
# case where the note explaining it could not be written either.
|
|
if [ ! -d "$OUT" ] || [ ! -w "$OUT" ]; then
|
|
log "cannot write to $OUT, so no previous-instance log can be kept; this is a condition of the machine writing the report and says nothing about whether anything crash-looped"
|
|
exit 0
|
|
fi
|
|
|
|
# Sanitise the cap here as well as in prevlog_cap, so the overflow line below
|
|
# names the limit that was actually applied rather than echoing back a typo.
|
|
# The nine-digit bound matters as much as the digits-only one, and for the reason
|
|
# the sibling's cozyreport_is_count spells out: a value `test` and `head` cannot
|
|
# compute with is not merely useless, it takes the rows with it. Under dash a
|
|
# 30-digit cap makes `[ "$_pc_max" -eq 0 ]` fail with "Illegal number" and `head`
|
|
# reject the count, so prevlog_cap emits nothing -- and the caller then reports
|
|
# that zero containers were kept because the cap was reached. The cap that broke
|
|
# collection gets named as the reason collection found nothing, which is a
|
|
# statement about the cluster produced by a typo.
|
|
case "$MAX" in
|
|
'' | *[!0-9]*)
|
|
log "ignoring malformed COZY_PREVLOG_MAX='$MAX'; using 12"
|
|
MAX=12
|
|
;;
|
|
*)
|
|
if [ "${#MAX}" -gt 9 ]; then
|
|
log "ignoring COZY_PREVLOG_MAX='$MAX' (too large for this shell to compute with); using 12"
|
|
MAX=12
|
|
fi
|
|
;;
|
|
esac
|
|
|
|
# Same treatment for the tail, and 0 is the value that makes it necessary rather
|
|
# than tidy. `--tail=0` returns no lines at all, kubectl still exits 0, and the
|
|
# empty-output branch below then deletes the capture and logs "previous instance
|
|
# ... produced no output" -- a positive claim about the cluster manufactured
|
|
# entirely by a typo, which also throws away the only remaining copy of a log the
|
|
# kubelet has already collected. A leading zero is rejected because `$(( ))`
|
|
# reads it as octal while `[` reads it as decimal, so one string means two
|
|
# numbers. -1 is kept: that is the documented
|
|
# spelling for "the whole log", and kubectl takes it.
|
|
case "$TAIL" in
|
|
-1) ;;
|
|
'' | *[!0-9]*)
|
|
log "ignoring malformed COZY_PREVLOG_TAIL='$TAIL'; using 200"
|
|
TAIL=200
|
|
;;
|
|
0 | 0*)
|
|
log "ignoring COZY_PREVLOG_TAIL='$TAIL' (a zero or leading-zero tail requests nothing, or is read as octal); using 200"
|
|
TAIL=200
|
|
;;
|
|
*)
|
|
# Same nine-digit bound as the cap above. kubectl rejects an oversized --tail
|
|
# outright, which would turn every capture into a refusal attributed to the
|
|
# cluster rather than to the value.
|
|
if [ "${#TAIL}" -gt 9 ]; then
|
|
log "ignoring COZY_PREVLOG_TAIL='$TAIL' (too large for this shell to compute with); using 200"
|
|
TAIL=200
|
|
fi
|
|
;;
|
|
esac
|
|
|
|
if [ -z "$PREVLOG_BOUND" ]; then
|
|
log "timeout is not on PATH, so the reads below ran with no wall-clock ceiling; this is a missing dependency on the machine producing the report, not a statement about the cluster"
|
|
fi
|
|
|
|
if ! command -v kubectl >/dev/null 2>&1; then
|
|
# Leaving silently would put an empty directory in the artifact, which is the
|
|
# one thing this script's notes exist to prevent: it reads as "looked, found
|
|
# no crash-loops" rather than "never looked". One caller pre-gates on kubectl,
|
|
# the other does not.
|
|
log "kubectl is not on PATH; no previous-instance logs were captured"
|
|
exit 0
|
|
fi
|
|
|
|
# The finishedAt guard is three deep, and the innermost one is the load-bearing
|
|
# one: `finishedAt` is a metav1.Time behind `json:",omitempty"`, which cannot
|
|
# omit a struct, and its zero value marshals to `null`. The kubelet does
|
|
# synthesize a terminated state with no time -- ContainerStatusUnknown on a pod
|
|
# deleted mid-run, which also bumps restartCount and so clears the filter above.
|
|
# kubectl renders that leaf as the literal string `<no value>`, and `<` sorts
|
|
# ABOVE every digit, so under the reverse sort that row would land FIRST and
|
|
# displace the most recent real restart: the exact inversion this ordering
|
|
# exists to prevent. It would also print `previous instance ended <no value>`,
|
|
# a claim about a time nothing observed. Guarding the leaf collapses both
|
|
# shapes -- null, and the key absent -- into the empty-timestamp path that
|
|
# sorts last. Covered by the `<no value>` cases in hack/capture-previous-logs.bats.
|
|
#
|
|
# One cluster-wide list call. Both initContainerStatuses and containerStatuses
|
|
# are walked: an interrupted bootstrap that leaves the datadir half-written
|
|
# lives in an init container, and that is exactly the instance whose log gets
|
|
# overwritten by the retry. `range` over an absent field yields nothing on
|
|
# kubectl's unstructured objects, so a pod with no statuses yet is skipped
|
|
# rather than erroring the template.
|
|
# kubectl's own reason for not answering is the finding, so it is captured rather
|
|
# than sent to /dev/null: "could not list pods (kubectl exit 1)" names no cause,
|
|
# and this is the read every later line depends on.
|
|
LIST_ERR=$(mktemp "${TMPDIR:-/tmp}/prevlog-list.XXXXXX" 2>/dev/null) || LIST_ERR=""
|
|
# shellcheck disable=SC2016 # Go template syntax; $ns/$pod must not be expanded by the shell.
|
|
# shellcheck disable=SC2086 # empty PREVLOG_LIST_BOUND must vanish, not become ""
|
|
if ROWS=$($PREVLOG_LIST_BOUND kubectl get pods --all-namespaces -o go-template='
|
|
{{- range .items -}}
|
|
{{- $ns := .metadata.namespace -}}
|
|
{{- $pod := .metadata.name -}}
|
|
{{- range .status.initContainerStatuses -}}
|
|
{{ $ns }}|{{ $pod }}|{{ .name }}|init|{{ .restartCount }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ if .lastState.terminated.finishedAt }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }}{{ end }}
|
|
{{ end -}}
|
|
{{- range .status.containerStatuses -}}
|
|
{{ $ns }}|{{ $pod }}|{{ .name }}|container|{{ .restartCount }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ if .lastState.terminated.finishedAt }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }}{{ end }}
|
|
{{ end -}}
|
|
{{- end -}}' 2>"${LIST_ERR:-/dev/null}"); then
|
|
LIST_RC=0
|
|
else
|
|
LIST_RC=$?
|
|
ROWS=''
|
|
fi
|
|
# Last line, not the first: a failing cluster-wide list is preceded by one klog
|
|
# discovery-retry line per attempt, each long enough that trimming it to 200
|
|
# characters would cut off the cause it ends with.
|
|
LIST_REASON=$([ -n "${LIST_ERR:-}" ] && tail -n 1 "$LIST_ERR" 2>/dev/null | cut -c1-200)
|
|
[ -z "${LIST_ERR:-}" ] || rm -f "$LIST_ERR"
|
|
|
|
# An unreachable or degraded API is the state a failed e2e is usually in, and it
|
|
# yields exactly the same empty ROWS as a healthy cluster where nothing
|
|
# restarted. Distinguish them: reporting "no container has restarted" off a list
|
|
# call that never returned asserts a cluster fact this script never observed,
|
|
# and would talk a triager out of the crash-loop hypothesis.
|
|
if [ "$LIST_RC" -ne 0 ]; then
|
|
if [ "$LIST_RC" -eq 124 ] || [ "$LIST_RC" -eq 137 ]; then
|
|
log "could not list pods: the read was cut off by $(prevlog_cutoff_desc "$LIST_RC" "$PREVLOG_LIST_TIMEOUT" "$PREVLOG_LIST_BOUND"); cannot determine whether anything crash-looped"
|
|
else
|
|
if [ -z "${LIST_ERR:-}" ]; then
|
|
log "could not list pods (kubectl exit $LIST_RC): its message could not be captured (no writable temp dir here), so whether it said anything is unknown; cannot determine whether anything crash-looped"
|
|
else
|
|
log "could not list pods (kubectl exit $LIST_RC): ${LIST_REASON:-no message from kubectl}; cannot determine whether anything crash-looped"
|
|
fi
|
|
fi
|
|
exit 0
|
|
fi
|
|
|
|
RESTARTED=$(printf '%s\n' "$ROWS" | prevlog_filter_restarted)
|
|
TOTAL=$(printf '%s\n' "$RESTARTED" | grep -c . || true)
|
|
|
|
if [ "${TOTAL:-0}" -eq 0 ]; then
|
|
# Nothing restarted anywhere: the failure is not a crash-loop, so there is no
|
|
# previous instance to read. Say so once instead of emitting an empty section
|
|
# that reads like a broken capture.
|
|
log "no container has restarted; no previous-instance logs to capture"
|
|
exit 0
|
|
fi
|
|
|
|
SELECTED=$(printf '%s\n' "$RESTARTED" | prevlog_prioritize "$PREFER_NS" | prevlog_cap "$MAX")
|
|
KEPT=$(printf '%s\n' "$SELECTED" | grep -c . || true)
|
|
|
|
log "capturing previous-instance logs for $KEPT of $TOTAL restarted container(s) -> $OUT"
|
|
if [ "$KEPT" -lt "$TOTAL" ]; then
|
|
# Never truncate silently: a reader who sees 12 dumps must know whether that
|
|
# was all of them. Raise COZY_PREVLOG_MAX to widen.
|
|
log "reached COZY_PREVLOG_MAX=$MAX cap; $((TOTAL - KEPT)) more restarted container(s) NOT captured"
|
|
fi
|
|
|
|
# Once per run, not once per container. The bound is the same for every log this
|
|
# capture writes, so repeating it per file put up to COZY_PREVLOG_MAX copies of one
|
|
# sentence into capture-notes.txt -- the file a reader holding only the artifact
|
|
# opens first, and the one place where the lines that explain a short capture have
|
|
# to be findable. Burying them under twelve identical tail notes is a cost paid by
|
|
# the reader for information they already had after the first. The sibling in
|
|
# hack/cozyreport.sh states the same fact once per pod directory for the same
|
|
# reason.
|
|
#
|
|
# Stated before the loop rather than after it: the loop body runs in a subshell, so
|
|
# nothing it sets survives, and a capture killed by the outer backstop mid-walk
|
|
# would lose an after-the-loop note entirely -- on exactly the run where knowing
|
|
# the logs are tail-bounded matters most.
|
|
#
|
|
# Suppressed on -1, which asks kubectl for the whole log: "holds at most the last
|
|
# -1 lines" describes a bound that was never applied.
|
|
if [ "$KEPT" -gt 0 ] && [ "$TAIL" != "-1" ]; then
|
|
log "every previous-instance log in this directory holds at most the last $TAIL lines (COZY_PREVLOG_TAIL=$TAIL); anything earlier was never requested"
|
|
fi
|
|
|
|
printf '%s\n' "$SELECTED" | while IFS='|' read -r ns pod container kind restarts finished; do
|
|
[ -n "$ns" ] || continue
|
|
file="$OUT/$(prevlog_logfile_name "$ns" "$pod" "$container")"
|
|
# --timestamps so these lines can be interleaved with the events and the
|
|
# current-instance logs the suite's own podLogs collector emits.
|
|
# kubectl's stderr is the ONLY thing that separates the ways this call can
|
|
# come up empty, so it is captured and then quoted into the log line rather
|
|
# than discarded. It goes to a scratch path outside $OUT: the outer backstop
|
|
# can SIGKILL this script mid-read, and a stray .err file left in the snapshot
|
|
# tree would ship as zero-byte noise in the uploaded artifact.
|
|
# mktemp, not "$$": a predictable name under a world-writable directory is a
|
|
# symlink an unprivileged process can plant ahead of the redirect, and if the
|
|
# redirect itself fails the read never runs and gets reported below as kubectl
|
|
# refusing -- a claim about the cluster caused by the local filesystem.
|
|
err=$(mktemp "${TMPDIR:-/tmp}/prevlog-stderr.XXXXXX" 2>/dev/null) || err=""
|
|
# -k: plain `timeout` sends TERM and then waits forever on a process that
|
|
# ignores it, so the 20s here would not actually bound anything and the outer
|
|
# backstop would SIGKILL the whole script instead -- and that backstop's line
|
|
# reaches the job log only, so capture-notes.txt would end silently short on
|
|
# exactly the run these notes were added for.
|
|
#
|
|
# 18 + 2 rather than 20 + 5: the grace counts towards the ceiling, and the worst
|
|
# case this script is allowed is fixed by the callers' 300s backstop. Keeping the
|
|
# pair at 20s keeps the 30 + 12 x 20 = 270s arithmetic the header, hack/cozytest.sh
|
|
# and .chainsaw.yaml all state, instead of quietly moving it to 330 and getting
|
|
# the whole script SIGKILLed on the run that needed it.
|
|
# shellcheck disable=SC2086 # empty PREVLOG_BOUND must vanish, not become ""
|
|
$PREVLOG_BOUND ${PREVLOG_BOUND:+$PREVLOG_READ_TIMEOUT} kubectl logs -n "$ns" "$pod" -c "$container" --previous \
|
|
--timestamps --tail="$TAIL" >"$file" 2>"${err:-/dev/null}"
|
|
rc=$?
|
|
# LAST line, trimmed. A read against a cold discovery cache is preceded by one
|
|
# klog "couldn't get current server API group list" line per retry, and kubectl's
|
|
# own actionable message comes after them -- so the first line names the retry,
|
|
# not the cause. Single-pod reads are not exempt: the fixture in
|
|
# hack/cozyreport.bats models exactly that shape for one pod, and a multi-hour
|
|
# failed run produces cold discovery routinely. This matters more since this
|
|
# value now reaches the artifact, both in the in-file marker and in
|
|
# capture-notes.txt, rather than only the job log. Every other stderr quote in
|
|
# these three scripts already takes the last line.
|
|
reason=$([ -n "$err" ] && tail -n 1 "$err" 2>/dev/null | cut -c1-200)
|
|
# kubectl said something and still returned a log: a deprecation notice, a
|
|
# partial-result warning. It has no place in the log file, which is read by
|
|
# machine, but dropping it loses evidence -- and the whole point of this script
|
|
# is that nothing is lost in silence. Copied whole, not reduced: with no klog
|
|
# preamble to skip, every line here is a warning of its own.
|
|
# NOT gated on the log being non-empty. A read that exits 0, writes nothing and
|
|
# still emits a warning is the one shape where dropping the message costs most:
|
|
# the branch below then reports "produced no output", which is a positive claim
|
|
# about the container made while kubectl was speaking. The refusal path keeps its
|
|
# own handling further down; this copy is about preserving what was said, whatever
|
|
# the read returned.
|
|
if [ -n "$err" ] && [ -s "$err" ] && { [ -s "$file" ] || [ "$rc" -eq 0 ]; }; then
|
|
if [ -s "$file" ]; then
|
|
log "$(basename "$file"): kubectl returned this log and also said:"
|
|
else
|
|
log "$(basename "$file"): kubectl returned no log, exited 0, and said:"
|
|
fi
|
|
while IFS= read -r _warn_line; do log " $_warn_line"; done < "$err"
|
|
fi
|
|
# Remembered before the scratch file is removed: the branches below still need to
|
|
# know whether kubectl spoke, and by then there is nothing left to ask.
|
|
err_had_output=""
|
|
if [ -n "$err" ] && [ -s "$err" ]; then err_had_output=1; fi
|
|
[ -z "$err" ] || rm -f "$err"
|
|
if [ "$rc" -ne 0 ] && [ ! -s "$file" ]; then
|
|
# Nothing landed. Report WHY instead of assuming one cause: exit 124 is our
|
|
# own read timeout (a slow or degraded apiserver), while any other non-zero
|
|
# is kubectl's own refusal. kubectl exits 1 for the kubelet having
|
|
# garbage-collected the dead container, for an RBAC denial and for an
|
|
# unreachable node alike, so the exit code alone separates nothing -- the
|
|
# message is what distinguishes them, and a blanket "kubelet GC" line would
|
|
# send a triager after the wrong problem. One line either way: this must
|
|
# never fail the catch, and the restartCount gate keeps it bounded to
|
|
# containers that really did restart.
|
|
rm -f "$file"
|
|
# 124 and 137 both mean the read hit its own timeout: `timeout -k` reports 137
|
|
# when the command ignored SIGTERM and had to be killed afterwards.
|
|
if [ "$rc" -eq 124 ] || [ "$rc" -eq 137 ]; then
|
|
log "reading the previous instance for $ns/$pod [$container] was cut off by $(prevlog_cutoff_desc "$rc" "$PREVLOG_READ_TIMEOUT" "$PREVLOG_BOUND")"
|
|
else
|
|
if [ -z "$err" ]; then
|
|
log "no previous instance retrieved for $ns/$pod [$container] (kubectl exit $rc): its message could not be captured (no writable temp dir here), so whether it said anything is unknown"
|
|
else
|
|
log "no previous instance retrieved for $ns/$pod [$container] (kubectl exit $rc): ${reason:-no message from kubectl}"
|
|
fi
|
|
fi
|
|
continue
|
|
fi
|
|
if [ ! -s "$file" ]; then
|
|
# kubectl succeeded but the previous instance wrote nothing. That is itself a
|
|
# finding -- a container OOM-killed or failing exec before its first write
|
|
# looks exactly like this -- so name it rather than leaving a silent gap that
|
|
# reads as "never attempted".
|
|
rm -f "$file"
|
|
# "Produced no output" is a claim about the container, so it may only be made
|
|
# when kubectl itself said nothing. When it did speak, the message is already
|
|
# in capture-notes.txt above and the two lines have to agree rather than one
|
|
# asserting silence the other just contradicted.
|
|
if [ -n "$err_had_output" ]; then
|
|
log "previous instance for $ns/$pod [$container] returned no log, though kubectl exited 0 and wrote the message above"
|
|
else
|
|
log "previous instance for $ns/$pod [$container] produced no output"
|
|
fi
|
|
continue
|
|
fi
|
|
if [ "$rc" -ne 0 ]; then
|
|
# The read was cut short, but whatever landed before the cut is still the
|
|
# evidence we came for. Keep it and mark it truncated; deleting a partial
|
|
# capture would throw away the only copy of a log that is already gone from
|
|
# the cluster.
|
|
# Same three-way split as the in-file marker below, not a bare exit status.
|
|
# 124 and 137 are this script's own clock; anything else is kubectl failing on
|
|
# its own terms. Reporting "kubectl exit 124" here while the marker inside the
|
|
# file names the timeout puts two sentences about ONE read in two files that
|
|
# disagree, and this is the one a reader meets first.
|
|
if [ "$rc" -eq 124 ] || [ "$rc" -eq 137 ]; then
|
|
log "previous-instance log for $ns/$pod [$container] is TRUNCATED: the read was cut off by $(prevlog_cutoff_desc "$rc" "$PREVLOG_READ_TIMEOUT" "$PREVLOG_BOUND")"
|
|
else
|
|
log "previous-instance log for $ns/$pod [$container] is TRUNCATED: kubectl exited $rc part way through${reason:+: $reason}"
|
|
fi
|
|
fi
|
|
# Why this file is not the whole log, stated inside it. Which reason applies
|
|
# depends on how the read ended: `--tail` drops the OLDEST lines, a killed read
|
|
# drops the NEWEST, and a file missing its end is a different object from one
|
|
# missing its beginning.
|
|
if [ "$rc" -ne 0 ]; then
|
|
# 124 and 137 are our own timeout firing; anything else is kubectl failing on
|
|
# its own terms, and it can also leave partial output -- a connection reset
|
|
# mid-stream writes some lines and then exits non-zero without any clock having
|
|
# run out. Naming the timeout for both would put a cause in the artifact that
|
|
# was never observed, which is the same defect as the tail note claiming a
|
|
# clean window: a confident explanation that happens to be false. The adjacent
|
|
# log() line above draws the same distinction, and both have to: they describe
|
|
# one read in two places a reader compares.
|
|
if [ "$rc" -eq 124 ] || [ "$rc" -eq 137 ]; then
|
|
prevlog_append_note "$file" \
|
|
"[capture-previous-logs] TRUNCATED: this log ends here because the read was cut off by $(prevlog_cutoff_desc "$rc" "$PREVLOG_READ_TIMEOUT" "$PREVLOG_BOUND"), not because the container stopped writing"
|
|
else
|
|
prevlog_append_note "$file" \
|
|
"[capture-previous-logs] TRUNCATED: this log ends here because kubectl exited $rc part way through, not because the container stopped writing${reason:+: $reason}"
|
|
fi
|
|
fi
|
|
|
|
# The `--tail` bound applies to this file as it does to every other one here,
|
|
# and it is stated ONCE for the whole capture above the loop rather than once per
|
|
# container. It still has to be stated for a capture cut short at its END, since
|
|
# such a file lost its OLDEST lines to `--tail` as well and naming only the end
|
|
# would tell the reader the file starts where the container did -- but that is
|
|
# what the run-level line covers, and it covers it without putting twelve copies
|
|
# of one sentence into the file a reader opens first.
|
|
#
|
|
# Recorded beside the log rather than inside it, wherever it is recorded: a log
|
|
# read in full is a complete artifact, these platforms log JSON per line, and a
|
|
# trailing prose line breaks every parser that could read the file before.
|
|
# Echo as well as archive. The archive is for later; the failing job's log is
|
|
# where whoever is triaging the red run is already looking.
|
|
#
|
|
# When the previous instance ended is in the header because it is the first
|
|
# thing that decides whether this dump is worth reading: an instance that
|
|
# ended during cluster bring-up cannot explain a test that started afterwards,
|
|
# and until a reader knows that they have to read 200 lines to find out. It is
|
|
# also what prevlog_sort_recent ordered on, so the header shows the ordering
|
|
# rather than leaving it implicit. Omitted rather than guessed when the kubelet
|
|
# has already dropped the lastState -- "ended unknown" and "ended at 00:00"
|
|
# are not the same claim.
|
|
#
|
|
# "last -1 lines" would be nonsense; -1 means the whole log was requested.
|
|
if [ -n "$finished" ]; then
|
|
_ended=", previous instance ended $finished"
|
|
else
|
|
_ended=""
|
|
fi
|
|
if [ "$TAIL" = "-1" ]; then
|
|
echo "----- previous logs: $ns/$pod [$kind $container] (restarts=$restarts$_ended, whole log) -----"
|
|
else
|
|
echo "----- previous logs: $ns/$pod [$kind $container] (restarts=$restarts$_ended, last $TAIL lines) -----"
|
|
fi
|
|
cat "$file"
|
|
echo "----- end $ns/$pod [$container] -----"
|
|
done
|
|
|
|
exit 0
|