Skip to content

Pin the stress readiness probe to the native port and capture stacks when it gives up - #119891

Open
groeneai wants to merge 1 commit into
ClickHouse:masterfrom
groeneai:ci/pin-stress-readiness-probe-transport
Open

Pin the stress readiness probe to the native port and capture stacks when it gives up#119891
groeneai wants to merge 1 commit into
ClickHouse:masterfrom
groeneai:ci/pin-stress-readiness-probe-transport

Conversation

@groeneai

@groeneai groeneai commented Sep 14, 2026

Copy link
Copy Markdown
Collaborator

Related: #119868

Changelog category (leave one):

  • CI Fix or Improvement (changelog entry is not required)

Changelog entry (a user-readable short description of the changes that goes into CHANGELOG.md):

...

Description

Stress test (amd_tsan) on #119868 produced no product signal: start_server gave up at its
readiness deadline before the workload ran
(job);
arm_tsan did the same six days earlier
(report).
No related open issue found; two harness defects, one file.

The probe measured an arbitrary transport. It passes neither --port nor --no-secure, so the
client auto-detects: it races 9000 against 9440, prefers TLS when both answer
(PortsProbe.cpp:196-200), and CI opens 9440 unconditionally (tests/config/install.sh:209). All
three probes committed to [::1]:9440 and paid its full handshake timeout, which is deliberately not
retried on the other port: 121 s bought 3 probes. With both ports open,
system.query_log.is_secure is 1 for 20/20 unpinned probes, 0 for 20/20 with --port; against a
frozen server the unpinned probe takes 30.5 s and names :9440, the pinned one 10.2 s and names
:9000. --port rather than --no-secure because upgrade_runner.sh calls start_server under
the previous-release client, and the auto-detection commit is not in the 26.6/26.5 line. I do not
claim this would have saved that job: the server was silent, so 9000's answer is unknowable.

The give-up recorded a duration, not a state. In both occurrences the server had stopped writing
to its log entirely (116 s and ~118 s), which the old message cannot tell from slow loading. It now
reports the probe count, how long ago the server last wrote to its log, a listener snapshot and a
bounded backtrace. Five sandboxed arms: healthy untouched; a wedged server reports
26-34 s of log silence; a listening-stopped but still-logging one 1 s; the daemon-exited branch
unchanged.

The product-side hang is not fixed here: no stack, no core, no shared code path between the two
freezes, so this captures the stack instead of guessing. The other transport-unspecified probes
(stop_server, upgrade_runner.sh, run-fuzzer.sh, stress/stress.py) have zero measured
occurrences.


Workflow [PR]
Sync PR [sync-upstream/pr/119891]

…when it gives up

stress_tests.lib::start_server decides whether a Stress test or Upgrade check job runs
at all, and its probe passed neither --port nor --secure/--no-secure. That makes the
client auto-detect its transport (programs/client/Client.cpp:651-663): it races the
plain and the secure port concurrently and, when both answer, prefers TLS
(src/Client/PortsProbe.cpp:196-200, "When both answered at the same time, TLS wins").
The CI config opens tcp_port_secure 9440 unconditionally, since
tests/config/install.sh:209 links secure_ports.xml for every job family, so on loopback
both ports answer in the same select() wake-up and the probe commits to 9440. A secure
socket defers its handshake to the first send, so a server that accepts and then does
not answer costs the whole handshake_timeout and surfaces as "Timeout exceeded while
writing to socket", and SOCKET_TIMEOUT is deliberately not retried on the other port
(Client.cpp:840-846). On the reported job 121 s of budget therefore bought exactly three
probes, none of which touched the port the workload itself uses, and the failure named a
port nothing else in the harness uses.

The auto-detection is 08a76d4 (2026-07-12); the same author then pinned the
transport in tests/clickhouse-test:7795-7805, tests/queries/shell_config.sh:42
(453e622) and ci/jobs/scripts/clickhouse_proc.py. tests/docker_scripts/ was the
one server-facing harness that sweep missed: a grep for --port, --secure or --no-secure
across that directory returns nothing.

--port rather than --no-secure, deliberately: upgrade_runner.sh:91 installs the previous
release and :138 then calls start_server, so the probe runs under the old client, and
--no-secure exists only since the auto-detection commit, which is not an ancestor of the
26.6 or 26.5 branches. --port has always existed; the release the tag resolver currently
selects, v26.8.3.105-lts, registers it at programs/client/Client.cpp:1211 and uses it in
its own CI. 9000 is the right number: no config.d file overrides the top-level tcp_port,
and wait_server_ports_free three lines up already hard-codes it. The
"timeout -s KILL 15 ... --handshake_timeout_ms=10000 --receive_timeout=10" form is
copied from stop_server in this same file, where that same previous-release client
already runs it, and where the comment recording why the external timeout is what bounds
an attempt already lives.

check_server_start gets the transport pin but deliberately not the hard bound. The
readiness loop waits on an unknown server state, where an unbounded attempt makes its
own deadline meaningless; check_server_start runs once against a server start_server has
just certified as answering SELECT 1 inside a 15 s bound (stress_runner.sh:356 then
:358), so bounding it would change a currently passing path to guard a failure mode
nothing has observed.

The second half of the defect is that the give-up recorded a duration and nothing else.
In both known occurrences the server had stopped emitting any log line at all, for 116 s
and about 118 s, which the old message cannot distinguish from a slow start. The branch
now samples how long ago the server last wrote to its log, dumps a listener snapshot and
a bounded backtrace, and reports what it measured.

Recency rather than a growth delta: in the reported job the log kept growing for about
six seconds after the deadline was anchored and only then went silent, so "did it grow
since the anchor?" answers yes for exactly the state the figure exists to name. The
listener snapshot is a coarse observation only, because socketBindListen binds and
listens inside the createServer lambda while createServers runs with start_servers
false, so every client port enters LISTEN together, well before startServers reaches any
of them; what it separates is a server that never got that far from one that did.
Locating the stall is the backtrace's job.

The backtrace is bounded at 10m rather than the 30m used by the other three sites in
these scripts: the readiness give-up happens before any test has run, so the job is
already a total loss and the remaining wall clock should not be spent, and a
startup-time thread set is far smaller than the post-stress ones the 30m sites dump.
Both figures in the message are sampled before the capture, which takes tens of seconds,
so the reported duration still measures the wait rather than the diagnostics. The
capture ends in ||: and the mtime sample uses a guarded form because it now runs before
the failure is recorded: an unguarded version aborted the whole job under set -e and
wrote no result row at all when the pipeline failed.

The restart branch is untouched, so a daemon that keeps exiting reports exactly what it
reported before, with no readiness claim attached.

The product-side hang itself is not addressed here. In both occurrences the server
stopped logging during startup and never recovered, with no core, no sanitizer report,
and no shared code path between the two in their final 300 log lines, so there is
nothing to root-cause from what CI captured. This change captures the stack instead of
guessing at a fix.

Related: ClickHouse#119868

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@groeneai groeneai added can be tested Allows running workflows for external contributors groeneai-origin-ci-own-pr PR origin: CI on a groeneai PR exposed a separate defect labels Sep 14, 2026
@groeneai

Copy link
Copy Markdown
Collaborator Author
Internal second-model review: adjudication log (click to expand)

Pre-publication review by an independent model (engine: codex; 2 findings) plus my own cold
review of the resulting diff (4 findings). No blocker or major survived adjudication.

# Sev Finding Verdict Evidence / action
1 ⚠️ No liveness evidence that the probe really uses 9000, or that a degraded stat/ss/gdb still emits the failure row (stress_tests.lib:390, :415-429) DISAGREE system.query_log.is_secure is 0 for 20/20 pinned probes and 1 for 20/20 unpinned, with a negative control (stopping the secure listener flips the unpinned arm to 0, 10/10). Removing only the --port token returns the probe to the secure port with the TLS-handshake signature ("while writing to socket"), which is the closure condition the finding names. Arms B/B2/C record `(1
2 💡 gdb stderr is not redirected into gdb.log, so a refused attach leaves an artifact that cannot explain its own emptiness AGREE, not fixed here Correct, and the precedent is ci/jobs/scripts/clickhouse_proc.py:588-596, which redirects 2>&1 for exactly this reason. Not a regression: all three existing thread apply all backtrace sites in these scripts (stress_tests.lib:325, stress_runner.sh:236, upgrade_runner.sh:165) share the property, and the job log still carries the reason. It belongs to a four-site sweep rather than to this PR; happy to do it here if a reviewer prefers.
3 💡 The provenance link was only inside the template's HTML comment, so it rendered as nothing AGREE, fixed Visible Related: line added to the description before publication.
4 💡 stop_server's SYSTEM STOP DISTRIBUTED SENDS probe stays transport-unspecified in the same file DISAGREE It decides nothing: the result is discarded and clickhouse stop runs regardless, so it cannot lose or misattribute job signal. Zero measured occurrences, so pinning it would be a change against an unreproduced defect. Named in the description.
5 💡 upgrade_runner.sh:336 is an inline copy of check_server_start and stays unpinned DISAGREE It runs only after start_server has certified the server on 9000, and a healthy server completes a TLS handshake too, so the auto-detection resolves benignly there. Same for :140 and :344. Named in the description.

Severity: ❌ blocker / ⚠️ major / 💡 nit. DISAGREE verdicts carry recorded evidence and are terminal
per finding. Claims made in the diff's comments were each checked against source rather than
accepted: the TLS tie-break (PortsProbe.cpp), --port being what disables detection
(Client.cpp:651), --receive_timeout being inert until Hello (Connection.cpp:328-329 then
:416), and every client port entering LISTEN together (Server.cpp:4292 and :4360).

Session id: cron:clickhouse-review-slot-11:20260914-062800

@clickhouse-gh clickhouse-gh Bot added the manual approve Manual approve required to run CI label Sep 14, 2026
@clickhouse-gh

clickhouse-gh Bot commented Sep 14, 2026

Copy link
Copy Markdown
Contributor

Workflow [PR], commit [fbfd656]

Summary:

job_name test_name status info comment
Upgrade check (amd_release) FAIL
Error message in clickhouse-server.log (see upgrade_error_messages.txt) FAIL cidb

AI Review

Summary

This PR fixes the stress harness readiness check in tests/docker_scripts/stress_tests.lib by pinning the probe to the native client port, bounding each probe attempt, and collecting extra diagnostics when startup gives up. I did not find a remaining correctness or CI-signal regression in the current diff: the hardcoded 9000 matches the installed stress configs, and the failure path still records the startup failure even when the added diagnostics are best-effort.

Final Verdict

Status: ✅ Approve

@groeneai

Copy link
Copy Markdown
Collaborator Author
Pre-PR validation gate (click to expand)
# Question Answer
a Deterministic repro? Yes, two commands. With both ports open, an unpinned clickhouse-client probe logs is_secure = 1 (20/20) while --port logs 0 (20/20); against a SIGSTOPped server the unpinned probe takes 30.5 s and names :9440, the pinned one 10.2 s and names :9000. The give-up branch is exercised by five sandboxed start_server arms.
b Root cause explained? The probe passes neither --port nor --no-secure, so the client races the plain and secure ports and prefers TLS when both answer (PortsProbe.cpp:196-200); CI opens 9440 unconditionally (tests/config/install.sh:209), so every probe commits to 9440, pays the full handshake timeout, and is not retried on the other port (Client.cpp:840-846). 121 s bought 3 probes. On give-up only a wall-clock number was recorded, so a server that had stopped making progress was indistinguishable from a slow one.
c Fix matches root cause? Yes: the probe is moved onto the port the workload uses and each attempt is bounded, and the give-up records what it measured. No budget change (START_SERVER_READY_TIMEOUT untouched), no widened bound, no defensive guard. The reported premise that 120 s was too short was measured false: in both occurrences the server had stopped logging entirely.
d Test intent preserved / new tests added? Preserved. This is a CI harness library with no test surface, and the sibling changes to it (#112927, #117094, #111873) shipped the same way. Arm A shows the healthy path still succeeds on the first probe; arm D shows the restart branch keeps its message and gains nothing.
e Both directions demonstrated? Yes. Removing only the --port token from the fixed command restores the old behaviour (names :9440, TLS-handshake signature). Replacing the log-recency oracle with the growth-delta form rejected during review makes the same wedged arm report GREW 226 lines, that is, progress, instead of 26s ago.
f Fix is general across code paths? The invariant is that every probe deciding "the server is up" names its transport and bounds its attempts. Both probes in this file are pinned and both were exercised directly; stress_runner.sh and upgrade_runner.sh inherit the readiness fix through the shared function. check_server_start gets the pin but deliberately not the hard bound: it runs once against a server start_server has just certified inside a 15 s bound. The other unpinned probes (stop_server, upgrade_runner.sh:140/336/344, run-fuzzer.sh:156/211/376, stress/stress.py:947/1111) have zero measured occurrences and are listed in the description rather than edited.
g Fix generalizes across inputs (params/datatypes/wrappers)? The inputs here are server states and client vintages: healthy, wedged before the call, wedged during the wait, listening stopped but still logging, and daemon exited (five arms) plus the previous-release client. A missing log file, a missing pid file, an absent ts and a gdb that cannot attach are all covered by the guard forms, verified by running into three of them.
h Backward compatible? Yes. No product code, no setting, no SettingsChangesHistory.cpp, no format change. --port was chosen over --no-secure precisely for compatibility: upgrade_runner.sh runs start_server under the previous-release client, and the transport auto-detection commit is not an ancestor of the 26.6 or 26.5 branches. The resolved previous release (v26.8.3.105-lts) registers --port in programs/client/Client.cpp and its own CI already uses it.
i Invariants and contracts preserved? Three, all checked on the failure path. (1) The failure must still be recorded: an early version aborted under set -e when the backtrace pipeline failed and wrote no row at all, so the capture now ends `

Session id: cron:clickhouse-impl-slot-6:20260914-053700

@groeneai

Copy link
Copy Markdown
Collaborator Author

CI finish ledger - fbfd656

Every failure below has an owner: a fixing PR (mine or external), or a full-effort fix task
whose fixing-PR link will be posted here when it opens. Only CH Inc sync is exempt.

Check / test Reason Owner / fixing PR
Upgrade check (amd_release) / Error message in clickhouse-server.log (see upgrade_error_messages.txt) Pre-existing background-mutation retry loop, not from this diff: MutatePlainMergeTreeTask: Code: 47. DB::Exception: Unknown expression identifier 'b'. Maybe you meant: ['a']. In scope b, b. (UNKNOWN_IDENTIFIER) re-logged about once a second on part all_1_1_1_2, which the job's <Error> log grep then reports. Carrier is 04653_mutation_rewrite_stale_part_column_type (RENAME COLUMN b TO d, then MATERIALIZE), so the identifier the mutation cannot resolve is a column the table no longer has. Signature-scoped census over 30 days: 74 rows / 70 distinct pull requests / 0 true-master, exclusively on Upgrade check (amd_release), onset 2026-08-22 #118499 (mine, open)
Mergeable Check, PR praktika rollups of the row above, no independent leaf failure #118499 (mine, open)
Sync - CH Inc sync (private, not actionable by me)

CI is finished on this head: 172 unique check-runs, 0 incomplete, Finish Workflow green, last
completion 08:42:20Z. The Upgrade check leaf above is the only red.

This diff touches exactly one file, tests/docker_scripts/stress_tests.lib, and inside it only the
readiness probe of start_server / check_server_start plus the diagnostics its give-up branch
writes. It cannot reach identifier resolution in a background mutation, and the failing log lines
are emitted by the server under test, not by the probe.

Session id: cron:our-pr-ci-monitor:20260914-090208

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

Labels

can be tested Allows running workflows for external contributors comp-testing Test content only (no production code). groeneai-origin-ci-own-pr PR origin: CI on a groeneai PR exposed a separate defect manual approve Manual approve required to run CI pr-ci

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant