Failure: disk_level_encryption/operations — log rotation during restart hides ConfigReloader, job hangs until timeout on 26.6 #161

Affected tests:

• /disk level encryption/operations/* — any scenario calling add_config() / remove_config() with restart=True. Observed hang at .../alter move partition multi volume policy two volumes one encrypted disk/I clean up/I remove encrypted_disk.xml on clickhouse1. Which scenario hangs varies between runs.
• Everything after it never runs: rest of operations, encryption at rest, key formats.

Affected files:

• helpers/common.py

Description

disk_level_encryption intermittently hits the 3h GHA job timeout on antalya-26.6 and passes on rerun (also times out on Altinity/ClickHouse, where the limit is 3h30m). The job is cancelled before create_and_upload_logs.sh runs, so no report is uploaded and these failures are invisible in gh-data.clickhouse_regression_results.

The failing job was cancelled with a test at 1h 33m elapsed. Features before the hang take identical time in both runs (merge parts 16m27s vs 16m43s), so it is one unbounded wait, not general slowness.

Analysis

Root cause

wait_for_config_to_be_loaded captures stat -c %s of the server log before a restart, then does tail -c +{logsize} -f and bash.expect("ConfigReloader: ... performed update on configuration", timeout=300).

With <size>1000M</size> (1,048,576,000 bytes), the failing run had:

• pre-restart: 1,048,382,168 bytes — 193,832 short of the threshold
• the server appends its startup including the ConfigReloader line to that nearly-full file, then crosses the threshold and rotates → clickhouse-server.log.0.gz + new empty log
• post-restart: 4,420,228 bytes

b4353764a (from #140) detects the shrink and resets the offset to 1, so the tail reads the new file — but the message is in the archive. Confirmed: the new file starts mid table-loading and contains Application: Ready for connections (logged after ConfigReloader), while ConfigReloader appears 0 times in all 141,513 streamed lines.

The first fix was incomplete: the archive is compressed asynchronously

da2414387 replays the archived file from the captured offset, which is correct in principle but reads the archive too early. ClickHouse compresses the rotated file after renaming it, so a clickhouse-server.log.0.gz that already exists may still be partially written.

Observed on a MasterCI run whose release checkout already contained the fix:

{ zcat -f /var/log/clickhouse-server/clickhouse-server.log.0.gz | tail -c +1044697534; \
  tail -c +1 -f /var/log/clickhouse-server/clickhouse-server.log; }
gzip: /var/log/clickhouse-server/clickhouse-server.log.0.gz: unexpected end of file

zcat stops short, so tail -c +1044697534 asks for a byte past the end of a much shorter stream and emits nothing. Only the new file is followed, the message is not there, and the wait never ends: 0 occurrences of ConfigReloader in the 11,418 lines that follow. The offset again sits just under the 1000M threshold.

Why the 300s timeout never fires

testflows/uexpect/uexpect.py (~185-208) decrements timeleft on both paths but only tests if timeleft <= 0: raise inside the except TimeoutError: branch. While read() keeps returning data the check is unreachable.

part_log <flush_interval_milliseconds>500</flush_interval_milliseconds> keeps an idle server emitting ~8.87 KB/s with no gaps, so read() never times out and the wait becomes unbounded. This is why #140 saw both symptoms: with gaps it fails cleanly at 300s, gapless it burns the job.

Why it is intermittent

The suite stops right at the threshold, so whether a restart lands in the window that splits the startup is a coin flip.

Relation to #140

Same helper, same trigger, different suite. PR #139 made two changes; only the generic one reached here, and it does not cover this case. The logs.xml hardening (2000M + flush 7500) was applied to rbac only — still the sole one of 45 such files with it.

Worth noting for #140: the <size> bump is what actually fixed it, not the flush. In a real pre-#139 rbac log, part_log is 0.9% of bytes; flush 500→7500 would save ~4%. Raising <size> hid the bug rather than fixing it.

Solution

Make the wait rotation-aware in helpers/common.py; no config change needed.

1. On rotation, locate the newest archive by mtime (not assuming .0; matches .0.gz and the briefly uncompressed .0).
2. Replay it from the captured offset, then follow the new file from byte 1 — together they reconstruct the contiguous stream written since the restart, so the message is found on either side of the rotation. The offset survives compression because it was measured uncompressed and zcat reproduces those bytes.
3. Extract the restart-and-tail block, duplicated verbatim in add_config and remove_config, into one helper.
4. Wait for the archive to decompress to at least the captured offset before reading it, and emit a note when it never does, instead of falling back to the new file silently.

Tracked separately: the uexpect timeout bug is what turns any missed message into a burned job instead of a 300s failure. The restart=False path has a latent variant — its tail -f follows the descriptor, so a mid-follow rotation leaves it reading the renamed file.

Fix:

• da24143
• 43a29f8
• dcabcad

Verification

logger.size lowered to force the condition, running the operations subset:

• 8 runs, 8 passes, 581-592s each (2% spread → no hangs)
• 14 rotations inside a restart; all 14 recovered the message from the archive, 0 fallbacks, 0 ExpectTimeoutError
• try #0 retry failures identical (47) before and after — baseline

The forced-rotation runs above used a lowered logger.size, where compression is instantaneous, so they did not exercise the window described in the second cause.

References

• Second failure, with the first fix already in place (3h35m, cancelled): https://github.com/Altinity/ClickHouse/actions/runs/31713806632/job/94532979200
• Reproduced on clickhouse-regression: https://github.com/Altinity/clickhouse-regression/actions/runs/31754439797/job/94627092750
• Same root cause, previous instance: Failure: rbac/part 3/multiple authentication methods — log rotation race breaks wait_for_config_to_be_loaded on 26.3+ #140 (fixed by fix(rbac): prevent log rotation breakage in multiple_auth_methods restarts #139)
• Failing run (antalya-26.6, aarch64, 3h timeout): https://github.com/Altinity/clickhouse-regression/actions/runs/31128239415/job/92708184658
• Passing rerun, same commit: https://github.com/Altinity/clickhouse-regression/actions/runs/31128239415/job/93478946311