Record RestartCount and log timestamps in the ELK stack logs by sscarduzio · Pull Request #134 · beshu-tech/readonlyrest-e2e-tests

sscarduzio · 2026-09-13T13:11:05Z

This PR no longer raises the Kibana heap. That hypothesis was wrong, and the diagnostic that replaced it found the real cause.

What this PR does now

#120 merged with the ERR-trap log capture (collect-logs.sh), so master already writes each container's log under results/stack-logs/. What is left here is the part that tells a restarted container apart from a healthy one:

containers.txt gets a RESTARTS column from docker inspect .RestartCount. docker ps shows only the live process.
docker logs --timestamps, so each earlier death lines up with the Cypress timeline.

Why CI could not tell us why Kibana restarts

Three independent gaps, each verified:

1. docker inspect cannot see it. The monitor samples every 10 seconds, and restart: always on kbn-ror puts a dead container back into running long before the next sample. All 1530 inspect lines in a failing job read Status=running ExitCode=0 OOMKilled=false. Those fields describe the live process, not the one that died. Measured on a container killed on purpose, polled once per second:

t=1 Status=running ExitCode=0 OOMKilled=false Restarts=0
t=3 Status=running ExitCode=0 OOMKilled=false Restarts=1
t=5 Status=running ExitCode=0 OOMKilled=false Restarts=2

That is a container being kernel OOM-killed every second — and the signature is identical to a clean run. A Node heap abort exits 134 (128 + SIGABRT) and is equally invisible.

2. elk-ror.log is never written on this path. environments/elk-ror/start.sh writes it only from the ERR trap on docker compose up --wait. A stack that starts cleanly and loses Kibana fifteen minutes later produces nothing, and the job log says so: cat: elk-ror.log: No such file or directory.

3. But docker logs keeps everything. Docker retains the previous process's output across a restart-policy restart. Verified on a container that died 7 times: docker logs still held all 7 boots and all 7 fatal errors.

What it found, on the first run

[FATAL][root] Reason: Unable to complete saved object migrations for the
[.kibana_usage_counters] index. Please check the health of your Elasticsearch
cluster and try again. Unexpected ElasticsearchResponseError:
  statusCode: 500, method: GET,
  url: /_cluster/health/.kibana_usage_counters_9.4.6_001?wait_for_status=green&timeout=300s
  error: [undefined]: <!DOCTYPE html>

Four of these across the two replicas, and zero occurrences of heap out of memory or Reached heap limit.

Kibana asks Elasticsearch for the health of one index and gets back HTTP 500 with an HTML body. Elasticsearch answers in JSON, so something else produced that page. Kibana treats it as fatal, shuts down, and restart: always brings it back — which is the restart cascade that empties the nginx upstream and produces the 502: Bad Gateway the specs report.

That is a product-level finding and it needs its own investigation. It is not a test-infrastructure tuning problem.

What I got wrong, and how

I claimed the replicas were exhausting a 768 MiB V8 heap. Two pieces of evidence refute it:

ECK runs one Kibana at the same 768 MiB cap, serving all of the suite's traffic, and peaks higher than either docker replica — median 921 MiB, p95 990, max 1071, across 447 samples — with zero restarts. The docker replicas max at 1052 and 1059. If 768 were the ceiling, the pod sitting closest to it would fail first. It never does.
OOMKilled=false proves nothing, per the measurement above. I read it as "V8, not the kernel". It is what both look like.

A third claim in the earlier version was simply false: I wrote that 7.17 sits at 0.91–0.92 GiB. It sits at 0.41 GiB. The number came from gh run view --log, which silently truncates — it returned 1.07 MB where the API returns 2.96 MB, cutting the log off eight minutes in, before the monitor's samples. Fetching through /logs directly gives the real series.

Still worth fixing, separately

base.limits.docker-compose.yml caps kbn-ror at mem_limit: 1g, but measured max RSS is 1052–1084 MiB on every 9.4.6 leg. The overlay is miscalibrated. It has never fired — Resource limits: disabled (auto: host has 16373452 kB, threshold is 12000000 kB) — so nobody noticed. es-ror is worse: 2693 MiB measured against a 2048 MiB cap.
conf/kbn/kbn-proxy-nginx.conf has no proxy_next_upstream for http_503, so a single restarting replica already fails requests; both replicas down is not required. That is Take a restarting Kibana replica out of the proxy rotation #128's subject.

🤖 Generated with Claude Code

Summary by CodeRabbit

New Features
- Added detailed container status reports with names, states, restart counts, and images.
- Added timestamps to collected container logs.
Reliability
- Log collection continues even when individual container log retrieval fails.

Both replicas run at the ceiling that --max-old-space-size=768 sets: 768 MiB of heap plus the ~250 MiB V8 needs outside it is about 1.0 GiB per container, and docker stats over four 9.4.6 docker legs put them at a median of 0.93-1.01 GiB and a p95 of 1.00-1.06 GiB. Every Kibana restart on the red legs began from that ceiling, with 6-8 GiB free on the host and OOMKilled false on the container — the process ran out of V8 heap, not the kernel. The 8.19 and 9.5 legs sit at 0.91-0.97 GiB and never restart. Two replicas restarting one after the other is what the proxy saw as "no live upstream". The proxy was reporting the problem, not causing it. The cap is not old. #74 (2026-02-24) added it where none existed; before that Kibana ran at Node's default, which is 4144 MiB on a 16 GiB host. The opt-in limits overlay from #101 gives kbn-ror a 1 GiB cgroup, so it is raised to 2 GiB in step, or an opted-in cap would kill what the heap now allows. 1536 MiB leaves each replica about 50% headroom over the measured p95 and fits the host: two of them add about 1.5 GiB to a machine that had 6.5-7.6 GiB free. ECK keeps 768: it runs one Kibana, which has not restarted on any leg. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

Nothing in CI records why a Kibana replica restarts, so a failing leg leaves no way to tell one cause from another. The monitor samples `docker inspect` every 10 seconds, and `restart: always` on kbn-ror puts a dead container back in `running` long before the next sample. Every one of the 1530 inspect lines in a failing job therefore reads `Status=running ExitCode=0 OOMKilled=false`, which describes the live process and not the one that died. Measured on a container killed on purpose: a Node heap abort exits 139 and never appears, and a kernel OOM kill shows `OOMKilled=true` for about one second in ten. t=1 Status=running ExitCode=0 OOMKilled=false Restarts=0 t=3 Status=running ExitCode=0 OOMKilled=false Restarts=1 t=5 Status=running ExitCode=0 OOMKilled=false Restarts=2 That is a container being OOM-killed once a second, polled once a second. elk-ror.log does not help either. start.sh writes it only from the ERR trap on `docker compose up --wait`, so a stack that starts cleanly and loses Kibana fifteen minutes later never produces one, and the job prints `cat: elk-ror.log: No such file or directory`. docker keeps the previous process's output across a restart-policy restart, verified: RestartCount=7, and `docker logs` still holds all 7 boots and all 7 fatal errors. So the stop step now dumps the tail of every container's log. That is the only surviving record of why a container went away. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

…l up The memory monitor's stop step runs after runner.sh's EXIT trap, and that trap removes the containers. `docker ps -a` is empty there, so the loop in the stop step captured nothing. The ERR trap runs first, with the stack up. print-logs.sh now writes each container's log under results/stack-logs, which the workflow uploads on failure, and prints the tail to the job log. For eck-ror it also keeps the previous container's log of each pod. Verified with a throwaway compose project named elk-ror and a container that dies every second: the ERR trap sees RestartCount=7 and all 7 fatal lines; after the EXIT trap `docker ps -a` lists no container. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Master carries the ERR-trap log capture from #120 (collect-logs.sh). Take master's runner.sh and drop the print-logs.sh scripts this branch changed. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

A container that a restart policy replaced looks alive in docker ps. RestartCount in containers.txt tells it apart, and --timestamps lines each earlier death up with the Cypress timeline. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

coutoPL

LGTM

sscarduzio requested a review from Dzuming September 13, 2026 13:11

This comment was marked as off-topic.

Sign in to view