Keep the stack logs when the suite fails - #120
Open
sscarduzio wants to merge 4 commits into
Open
Conversation
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
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>
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
This comment was marked as outdated.
sscarduzio
force-pushed
the
fix/capture-stack-logs-on-failure
branch
from
September 10, 2026 07:23
59af55b to
0c44e31
Compare
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>
This was referenced Sep 10, 2026
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>
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
force-pushed
the
fix/capture-stack-logs-on-failure
branch
from
September 10, 2026 09:22
0c44e31 to
b606367
Compare
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>
This comment was marked as resolved.
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>
This comment was marked as resolved.
This comment was marked as resolved.
coutoPL
reviewed
Sep 10, 2026
coutoPL
left a comment
Collaborator
There was a problem hiding this comment.
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?
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The problem
Seven runs between 12 August and 4 September collapsed with every spec red while
it_linuxwas 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, butstart.shwrites it only from itsERRtrap — 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.shis not a substitute either. It cats that sameelk-ror.log, so on a test failure it has nothing to print.The change
runner.shtakes the suite's exit status by hand and, on failure, calls a newdump-logs.shfor 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 fromdocker compose, so it needs neither the compose file list thatstart.shassembles 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. Everykubectlcall goes throughdocker execon 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 indefault, but on an ECK failure the operator's log is usually the one that explains it, and that lives inelastic-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.shnow 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 Finishedonward 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_SUMMARYis unset outside Actions, so a local run is unchanged.One collector, two failure paths
print-logs.shand the newdump-logs.shwere unrelated mechanisms. They are now called from one function, used by the ERR trap and by the suite-failure path:They are not redundant.
print-logs.shcatselk-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
master.docs/dev/branching.mdin [RORDEV-2220] add branching, code style and writing style docs #125, case 4: a pipeline, workflow or runner change targetsmaster. Rebased ontomaster, so this PR carries only its own two commits.docs/dev/code-style.mdasks 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 whatstart.shandprint-logs.sheach 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