Skip to content

Keep the stack logs when the suite fails - #120

Open
sscarduzio wants to merge 4 commits into
masterfrom
fix/capture-stack-logs-on-failure
Open

Keep the stack logs when the suite fails#120
sscarduzio wants to merge 4 commits into
masterfrom
fix/capture-stack-logs-on-failure

Conversation

@sscarduzio

@sscarduzio sscarduzio commented Sep 5, 2026

Copy link
Copy Markdown
Contributor

The problem

Seven runs between 12 August and 4 September collapsed with every spec red while it_linux was green, and not one of them left a single line of Kibana or Elasticsearch log behind. There was nothing to diagnose them with.

The stack does write a log, elk-ror.log, but start.sh writes it only from its ERR trap — that is, only when the stack fails to come up. These seven runs are the opposite case: the stack came up, the healthchecks passed, and the Cypress suite then collapsed with every spec stuck on /login. By then the file that would have explained it was never written.

print-logs.sh is not a substitute either. It cats that same elk-ror.log, so on a test failure it has nothing to print.

The change

runner.sh takes the suite's exit status by hand and, on failure, calls a new dump-logs.sh for the environment before it exits:

  • environments/elk-ror/dump-logs.sh — container status, exit codes and per-container logs. It reads the container list straight from docker rather than from docker compose, so it needs neither the compose file list that start.sh assembles nor the working directory it assembles them in.
  • environments/eck-ror/dump-logs.sh — the twin for ECK: pod logs, pod status and cluster events, one file per pod. Every kubectl call goes through docker exec on the kind control-plane node, because the host does not necessarily have a kubectl that can reach that cluster. It queries all namespaces: ES and Kibana live in default, but on an ECK failure the operator's log is usually the one that explains it, and that lives in elastic-system.

Both write into results/stack-logs. The ES repo already uploads "$E2E_TESTS_DIR/results" to S3 on failure, next to the Cypress videos and screenshots, so no caller has to change to start receiving the logs.

Neither collector can fail its caller. They run on a path that has already failed, and a missing log must not replace the real error with an error from collecting logs.

The run summary

Cypress prints its per-spec table thousands of lines into the step log, where nobody finds it — in run 34421845288 it starts at line 13,072. runner.sh now repeats that table on the run's summary page, on a pass as well as on a failure.

It tees the suite's output, strips the colour codes and copies the block from Run Finished onward into $GITHUB_STEP_SUMMARY. Verified against the real log of the failing 9.4.6 leg: 121 lines, the table and the totals, no escapes left. GITHUB_STEP_SUMMARY is unset outside Actions, so a local run is unchanged.

One collector, two failure paths

print-logs.sh and the new dump-logs.sh were unrelated mechanisms. They are now called from one function, used by the ERR trap and by the suite-failure path:

collect_logs() {
  ./environments/"$ENV_NAME"/print-logs.sh || true
  ./environments/"$ENV_NAME"/dump-logs.sh results/stack-logs || true
}

They are not redundant. print-logs.sh cats elk-ror.log, which exists only when the stack failed to come up. The dump covers the opposite case. Calling both from one place means neither path can lose its logs again.

Limit

This does not fix the collapse. It makes the next one possible to diagnose.

Review notes

  • Base branch is now master. docs/dev/branching.md in [RORDEV-2220] add branching, code style and writing style docs #125, case 4: a pipeline, workflow or runner change targets master. Rebased onto master, so this PR carries only its own two commits.
  • The comments were rewritten. docs/dev/code-style.md asks a comment to explain the current state and to avoid naming other files. The headers did the opposite: they counted the seven collapses, walked through what start.sh and print-logs.sh each write and when, and named another repository's S3 upload. All of that is above instead. The comments keep only what a reader cannot get from the code — which failure the script runs on, why the container list comes from docker and not from compose, why kubectl goes through the control-plane node, and why the collector must never fail its caller.

🤖 Generated with Claude Code

@coderabbitai

This comment was marked as outdated.

sscarduzio

This comment was marked as outdated.

@sscarduzio

This comment was marked as outdated.

@10hexdev

This comment was marked as outdated.

@10hexdev

This comment was marked as outdated.

sscarduzio added a commit that referenced this pull request Sep 5, 2026
@10hexdev is right, and the correction is bigger than the arithmetic.

timeout_minutes is per attempt, and retryWait runs after every failed attempt
including the last (src/index.ts, both the timeout and the error branch), so two
attempts cost 2x45+4 = 94 min, not 92. A 40.9-minute failure therefore cannot be
a timeout at all.

Checking that against all 82 failed E2E legs from 26 Aug to 5 Sep: exactly ONE
reached 94 min. The other 81 finished below the double-timeout floor, so at most
one of their attempts timed out. My "every failure sampled ended in Timeout" came
from five recent legs, and only the last attempt's error is reported - so a leg
whose attempt 1 failed for a real reason and whose attempt 2 was then cut off
reports a timeout and hides the actual failure.

Run 33853781633, measured attempt by attempt: attempt 1 08:57:24 to ~09:42
(timed out), attempt 2 09:44:24 to 10:31 (timed out) = 94 min. That is the one
outlier, not the pattern. The pattern is the 75-78 min cluster: about 29 min of
real failure, then 45 min of cap.

So this raise does not turn the matrix green, and the PR should never have
implied it would. What it buys is a suite that reports the real failure instead
of a timeout, and a second attempt allowed to finish. The redness is spec
flakiness, addressed in #118 and made visible by #120.

Cost arithmetic corrected with it: 94 -> 154 min worst case per leg. The +720
runner-minutes delta is unchanged.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
10hexdev[bot]

This comment was marked as outdated.

@sscarduzio
sscarduzio requested a review from coutoPL September 5, 2026 17:00
@sscarduzio

This comment was marked as outdated.

@sscarduzio

This comment was marked as outdated.

@10hexdev

This comment was marked as outdated.

@10hexdev

This comment was marked as outdated.

@sscarduzio
sscarduzio requested a review from Dzuming September 10, 2026 06:08
@sscarduzio
sscarduzio force-pushed the fix/capture-stack-logs-on-failure branch from 59af55b to 0c44e31 Compare September 10, 2026 07:23
sscarduzio added a commit that referenced this pull request Sep 10, 2026
@10hexdev is right, and the correction is bigger than the arithmetic.

timeout_minutes is per attempt, and retryWait runs after every failed attempt
including the last (src/index.ts, both the timeout and the error branch), so two
attempts cost 2x45+4 = 94 min, not 92. A 40.9-minute failure therefore cannot be
a timeout at all.

Checking that against all 82 failed E2E legs from 26 Aug to 5 Sep: exactly ONE
reached 94 min. The other 81 finished below the double-timeout floor, so at most
one of their attempts timed out. My "every failure sampled ended in Timeout" came
from five recent legs, and only the last attempt's error is reported - so a leg
whose attempt 1 failed for a real reason and whose attempt 2 was then cut off
reports a timeout and hides the actual failure.

Run 33853781633, measured attempt by attempt: attempt 1 08:57:24 to ~09:42
(timed out), attempt 2 09:44:24 to 10:31 (timed out) = 94 min. That is the one
outlier, not the pattern. The pattern is the 75-78 min cluster: about 29 min of
real failure, then 45 min of cap.

So this raise does not turn the matrix green, and the PR should never have
implied it would. What it buys is a suite that reports the real failure instead
of a timeout, and a second attempt allowed to finish. The redness is spec
flakiness, addressed in #118 and made visible by #120.

Cost arithmetic corrected with it: 94 -> 154 min worst case per leg. The +720
runner-minutes delta is unchanged.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Base automatically changed from develop to master September 10, 2026 08:28
coutoPL

This comment was marked as outdated.

sscarduzio added a commit that referenced this pull request Sep 10, 2026
@10hexdev is right, and the correction is bigger than the arithmetic.

timeout_minutes is per attempt, and retryWait runs after every failed attempt
including the last (src/index.ts, both the timeout and the error branch), so two
attempts cost 2x45+4 = 94 min, not 92. A 40.9-minute failure therefore cannot be
a timeout at all.

Checking that against all 82 failed E2E legs from 26 Aug to 5 Sep: exactly ONE
reached 94 min. The other 81 finished below the double-timeout floor, so at most
one of their attempts timed out. My "every failure sampled ended in Timeout" came
from five recent legs, and only the last attempt's error is reported - so a leg
whose attempt 1 failed for a real reason and whose attempt 2 was then cut off
reports a timeout and hides the actual failure.

Run 33853781633, measured attempt by attempt: attempt 1 08:57:24 to ~09:42
(timed out), attempt 2 09:44:24 to 10:31 (timed out) = 94 min. That is the one
outlier, not the pattern. The pattern is the 75-78 min cluster: about 29 min of
real failure, then 45 min of cap.

So this raise does not turn the matrix green, and the PR should never have
implied it would. What it buys is a suite that reports the real failure instead
of a timeout, and a second attempt allowed to finish. The redness is spec
flakiness, addressed in #118 and made visible by #120.

Cost arithmetic corrected with it: 94 -> 154 min worst case per leg. The +720
runner-minutes delta is unchanged.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
sscarduzio and others added 2 commits September 10, 2026 09:22
Seven runs between 12 Aug and 4 Sep failed with EVERY spec red and it_linux
green, so the branch was fine and the stack was not:

  31619463489 31724078645 32137375246 32273850268 32949155033 33516300157
  33860724157

All three legs of a run fail together - es717x, es818x and es94x, three ELK
majors on three machines - so it is not a version problem or a per-stack race.
Beyond that I cannot say what it is, because none of those runs left a single
line of Kibana or Elasticsearch log behind.

start.sh writes elk-ror.log from its ERR trap, so that file exists only when the
stack fails to COME UP. In all seven the stack came up: the healthchecks passed,
and in 33381974538 the first two specs ran, one of them exercising the ROR admin
API and getting 200s back. The collapse is later, and nothing captures it.
runner.sh's ERR trap calls print-logs.sh, which cats an elk-ror.log that in this
case was never written.

So: dump the container logs when the SUITE fails, one file per container, plus
the health status of each.

They go to results/stack-logs, because that is the directory the callers already
collect - the ES repo uploads "$E2E_TESTS_DIR/results" to S3 next to the Cypress
videos and screenshots, with `find "$SOURCE_DIR" -type f`. No caller has to
change to start receiving them.

The dump runs before the EXIT trap tears the stack down, and never fails the
caller: it runs on a path that is already failing, and losing the logs must not
replace the real error with an error from collecting them.

Verified with a stub run-tests.sh:

  failing suite -> exit 1, results/stack-logs written
  passing suite -> exit 0, no dump
  order         -> cypress ran / DUMP CALLED / stack stopped

and dump-logs.sh against a live docker daemon: captures stdout and stderr per
container plus the status table, and exits 0 with no matching containers and
with an unwritable output directory.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Review findings on this PR.

**The eck dump saw only the default namespace.** ES and Kibana live there, but
on an ECK failure the operator's log is usually the one that explains it, and
that is in elastic-system. `get pods`, `get events` and the pod loop now use -A,
and the loop reads `<namespace> <name>` pairs so each pod is fetched from its
own namespace.

**It also lost the log that matters most on a crash.** A container that
restarted gives you the new process, not the one that died. Added a best-effort
--previous pass, removing the file when there is no previous instance - most
pods have none, and that is not an error here.

**Dropped the dead second parameter from both scripts.** Nothing passed it, and
the same positional meant a compose project name in one twin and a kind node
name in the other, which is how a future caller passes the wrong thing to the
wrong script. Both are constants now, with a line saying where the value comes
from.

**Corrected the runner.sh comment.** It said the logs would never be read
without the change. The ERR trap fires either way - bash runs it with errexit
off - so print-logs.sh runs first as it always did. It is not a substitute: it
cats elk-ror.log, which start.sh writes only from its own trap, so on a test
failure that file does not exist. The comment now says that.

Re-tested both scripts against a live docker daemon: the elk one captures
stdout and stderr per container plus the status table, the eck one exits 0 with
no cluster present.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@sscarduzio
sscarduzio force-pushed the fix/capture-stack-logs-on-failure branch from 0c44e31 to b606367 Compare September 10, 2026 09:22
docs/dev/code-style.md asks a comment to explain the current state, and
to avoid naming other files. These headers did the opposite: they counted
the seven collapses that motivated the script, walked through what two
other scripts do and when each writes its file, and named the S3 upload
of another repository.

The description carries all of that now. The comments keep the parts a
reader cannot get from the code: which failure this runs on, why the
container list comes from docker and not from compose, why kubectl goes
through the control-plane node, and why the collector must never fail
its caller.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@sscarduzio

This comment was marked as resolved.

Two things @coutoPL asked for on the review.

The suite's own table sat thousands of lines inside the step log, which
is where nobody finds it. runner.sh now tees the run, strips the colour
codes and repeats the table on the run's summary page, for a pass as
well as for a failure. GITHUB_STEP_SUMMARY is unset outside Actions, so
a local run behaves as before.

Printing and dumping were two mechanisms with nothing between them. One
collector now serves both failure paths. The console keeps the stack's
own log, which is what a stack that never came up explains itself with.
The files carry the per-container detail, which the console cannot hold
and which a failure after start-up needs.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@sscarduzio

This comment was marked as resolved.

@sscarduzio
sscarduzio requested a review from coutoPL September 10, 2026 09:29

@coutoPL coutoPL left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok, but I still have a doublt. We collect logs in the dump-logs.sh script differently that in the print-logs.sh. I think these are related things. Maybe we can replace both by some common script. Or do sth else to make it more common?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants