Skip to content

Allowlist the expected FileLog bad-path reattach error in the upgrade check - #113983

Open
groeneai wants to merge 5 commits into
ClickHouse:masterfrom
groeneai:allowlist-filelog-bad-path-reattach-in-upgrade-check
Open

Allowlist the expected FileLog bad-path reattach error in the upgrade check#113983
groeneai wants to merge 5 commits into
ClickHouse:masterfrom
groeneai:allowlist-filelog-bad-path-reattach-in-upgrade-check

Conversation

@groeneai

@groeneai groeneai commented Aug 8, 2026

Copy link
Copy Markdown
Collaborator

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

Upgrade check (amd_release) intermittently fails its Error message in clickhouse-server.log sub-test on one benign line:

<Error> StorageFileLog (test_1.filelog_bad_path_attach): The absolute data path should be inside `user_files_path`(/var/lib/clickhouse/user_files/)

No product defect: the server starts, nothing crashes, no data is affected.

Root cause. 04202_filelog_attach_path_outside_user_files ATTACHes a FileLog table whose path is outside user_files_path. ATTACH is LoadingStrictnessLevel::ATTACH (2), which is >= SECONDARY_CREATE (1), so the constructor takes the relaxed branch at src/Storages/FileLog/StorageFileLog.cpp:195-198: it logs at <Error> and returns instead of throwing BAD_ARGUMENTS. That branch is deliberate and is what the test covers, since refusing to load at reattach time would break server startup. The table then outlives the test: stress threads run with a fixed --database=test_N (ci/jobs/scripts/stress/stress.py), and clickhouse-test skips its per-test teardown whenever --database is set (need_cleanup = not args.database), so that shared database is never dropped. The upgrade restart re-attaches the table, the relaxed branch fires again, and the line lands in the scanned log, where the post-restart scrub in tests/docker_scripts/upgrade_runner.sh had no entry for it. Hence the intermittency: 04202 must land on a fixed-database thread.

Change. One grep -av entry in that scrub's existing secondary pipe, plus a short rationale comment next to the sibling entries. The pattern requires the fixture table name and the message together, and (bare parens are literals in BRE) the StorageFileLog (db.table): prefix shape. No source change, no test change.

Validation. The scan pipeline, extracted verbatim from the runner, was run under GNU grep 3.11 against the failing run's own 19.9 MB clickhouse-server.upgrade.log. With the entry the artifact is empty; with it deleted the output is byte-identical to the 189-byte upgrade_error_messages.txt CI produced, so the sub-test flips FAIL to OK. Eight negative controls still surface, including a table whose name merely ends with the fixture name (prod.other_filelog_bad_path_attach), which the required . separator keeps visible.

… check

Upgrade check (amd_release) fails its "Error message in clickhouse-server.log"
sub-test on a single benign line:

  <Error> StorageFileLog (test_1.filelog_bad_path_attach): The absolute data
  path should be inside `user_files_path`(/var/lib/clickhouse/user_files/)

04202_filelog_attach_path_outside_user_files ATTACHes a FileLog table whose
path is outside user_files_path. ATTACH is LoadingStrictnessLevel::ATTACH (2),
which is >= SECONDARY_CREATE (1), so the constructor takes the relaxed branch
at src/Storages/FileLog/StorageFileLog.cpp:195-198 and logs at <Error> and
returns instead of throwing BAD_ARGUMENTS. That branch is deliberate and is
the branch the test exists to cover: refusing to load a table at reattach
time would break server startup.

The test's closing DROP is ignored here, because the upgrade check runs the
client with --fake-drop (ignore_drop_queries_probability=1, gated on
ASTDropQuery::Kind::Drop in InterpreterDropQuery.cpp:221). The table therefore
survives into the upgrade restart, is re-attached, and re-logs the same line
into the scanned log. The post-restart scrub had no entry for it.

Add one scoped entry to the existing secondary pipe of that scrub, requiring
the fixture table name and the message together. Bare parens are literals in
BRE, so the pattern also requires the "StorageFileLog (db.table):" prefix
shape; the escaped-group form would be looser and was rejected. The pattern
stops before the backtick in `user_files_path`, since inside double quotes
bash would perform command substitution there.

Product logging is not touched. Lowering the LOG_ERROR to LOG_WARNING was
rejected: it would change what users see in order to satisfy a CI scanner, and
would hide a genuine misconfiguration.

Validation: the pipeline was extracted verbatim from the runner and run under
GNU grep 3.11 over a fixture log. Without the entry the sub-test emits FAIL;
with it, OK. Five negative controls plus a prefix-shape control still surface:
the same message on another table, a different message on the fixture table,
and a different logger. Deleting the new line flips the fixture line back to
being reported, so the entry is load-bearing rather than a pattern that
matches nothing.
…tionale

The allowlist entry matched any table name ENDING in filelog_bad_path_attach,
so the same error from an unrelated table (prod.other_filelog_bad_path_attach)
would have been suppressed too. Require the StorageID separator: the logger name
is built as "StorageFileLog (" + getFullTableName() + ")" and getFullTableName()
is backQuoteIfNeed(db) + "." + backQuoteIfNeed(table), so the literal '.' is
always present and the genuine line still matches.

Also correct the reason the table survives the upgrade restart. It is not
--fake-drop: that is appended to args.client (tests/clickhouse-test:7089), which
.sh tests do not use, and the line bridging it into the .sh environment is
commented out (:5889, and :5574 in the v26.7 tree the upgrade check actually
runs). Measured on the failing run's own query_log, 0 of 15021 .sh DROP rows
carry ignore_drop_queries_probability while 21111 .sql rows do, and the
fake-drop branch's LOG_TEST lines appear 0 times in the pre-restart log.

The table persists because stress threads run with a fixed --database=test_N
(stress.py:271-272) and clickhouse-test skips its per-test teardown when
--database is set (need_cleanup = not args.database, :4046), so that shared
database is never dropped. Only those fixed-database threads leak the table,
which is why the failure is intermittent.

Validated against the failing run's 19.9 MB clickhouse-server.upgrade.log: with
the entry the scan output is empty, and with it deleted the output is
byte-identical to the 189-byte upgrade_error_messages.txt that CI uploaded.
Two prefix-extension negative controls are now part of the matcher's test matrix.
@groeneai

groeneai commented Aug 8, 2026

Copy link
Copy Markdown
Collaborator Author
Internal second-model review (2 rounds, 0 blockers outstanding)

An independent reviewer and a second model reviewed this change cold, twice. Round 1 raised two
majors and both were fixed; round 2 is clean apart from one documentation nit, recorded below
rather than fixed.

Round 1 — 2 majors, both AGREEd and fixed

The allowlist pattern was over-broad. StorageFileLog (.*filelog_bad_path_attach) has an
unanchored .* before the fixture name, so it also matched any table merely ending with it.
Measured: it suppressed prod.other_filelog_bad_path_attach and prod.my_filelog_bad_path_attach,
i.e. it would have hidden the genuine misconfiguration error for unrelated production tables.
Fixed by requiring the StorageID separator, (.*\.filelog_bad_path_attach). That cannot cause a
miss: the logger name is getLogger("StorageFileLog (" + StorageID::getFullTableName() + ")") and
getFullTableName() is backQuoteIfNeed(db) + "." + backQuoteIfNeed(table), so the literal . is
unconditional. Re-verified in round 2 with a 15-case matrix under GNU grep 3.11: the fixture line is
suppressed, and all 14 negative controls surface — including both prefix-extension cases, a
different logger, a different message on the fixture table, and the no-database form. Both
prefix-extension cases are now permanent controls; they were a hole in the original 6-control
matrix too.

The published root cause was false. The first revision attributed the table's survival to
--fake-drop. It cannot: --fake-drop is appended to args.client (tests/clickhouse-test:7089),
which .sh tests do not use, and the line bridging it into the .sh environment is commented out
(:5889, and :5574 in the v26.7 tree the upgrade check actually runs). Independently,
stress.py sets ignore_drop_queries_probability=0.2 only when not upgrade_check, so the
setting is absent from this job by construction; the fake-drop branch's LOG_TEST lines appear 0
times in the 1.28 GB pre-restart log, and 0 of the run's .sh DROP rows carry the setting. Replaced
with the measured mechanism: stress threads run with a fixed --database=test_N
(stress.py:271-272) and clickhouse-test skips its per-test teardown when --database is set
(need_cleanup = not args.database, :4046). Confirmed by parity against the failing run: exactly
test_1, test_5, test_7 — the fixed databases — load at the restart, and the fixture is in
test_1.

Round 2 — clean, plus one nit not fixed

⚠️ The rationale comment omits one causal step (nit, both reviewers, independently). A fixed
database disables only the framework's database-level cleanup; it does not undo the fixture's own
trailing DROP TABLE (04202:31). So the table also required that DROP not to execute. Measured on
the failing run: by log_comment the pre-restart log contains exactly 5 queries from this test, the
only DROP that reached the server is the leading one (:20, which precedes the ATTACH), and no
post-ATTACH drop appears anywhere in the log. Why the trailing DROP was skipped could not be
established from the artifacts — the random client killer is disabled in upgrade-check mode (0
Killing random client process lines in job.log) and --global_time_limit stops between test
files. Left as a documentation nit rather than another round: the load-bearing claim is only that the
table was in test_1's metadata at restart, which is directly observed (AsyncLoader: Execute load job 'load table test_1.filelog_bad_path_attach'), and the description asserts nothing about the
trailing DROP.

Validation the review relied on

Rather than the synthetic fixture, the review used this run's own artifacts (PR #113781, sha
d21b532): the 19.9 MB clickhouse-server.upgrade.log, upgrade_error_messages.txt, the 1.28 GB
pre-restart stress.log and query_log. Running the scrub pipeline extracted verbatim from the
runner under GNU grep 3.11: with the entry the artifact is empty; with it deleted the output is
byte-identical to the 189-byte upgrade_error_messages.txt CI uploaded. The total <Error> line
count goes 27 → 26 — the entry removes exactly the target line and nothing else.

Carrier coverage was re-derived independently: ATTACH TABLE ... FileLog has exactly one hit in the
whole test tree (04202:26), and every other FileLog test builds its path from ${USER_FILES_PATH}
so it never reaches the guard, while 02125/02126/03277 use CREATE and take the throw branch.
One entry is therefore the complete fix. 04202 and StorageFileLog.cpp are untouched, so the
behaviour under test is preserved.

@groeneai

groeneai commented Aug 8, 2026

Copy link
Copy Markdown
Collaborator Author
Pre-PR validation gate (click to expand)
# Question Answer
a Deterministic repro? Yes, 100%, no randomization. The error-scan pipeline extracted verbatim from tests/docker_scripts/upgrade_runner.sh (lines 471-568), run under GNU grep 3.11 over a fixture log containing the exact failing line, deterministically emits the FAIL row without the fix.
b Root cause explained? Yes. 04202_filelog_attach_path_outside_user_files ATTACHes a FileLog path outside user_files_path; ATTACH is LoadingStrictnessLevel::ATTACH (2) >= SECONDARY_CREATE (1), so the constructor takes the relaxed branch at StorageFileLog.cpp:195-198 (log at <Error> and return, by design, since refusing to load would break startup). The table then outlives the test: stress threads run with a fixed --database=test_N (stress.py:271-272) and clickhouse-test skips per-test teardown when --database is set (need_cleanup = not args.database, :4046), so that shared database is never dropped. The upgrade restart re-attaches the table (observed in the failing run's log as AsyncLoader: Execute load job 'load table test_1.filelog_bad_path_attach' immediately before the <Error>), it re-logs the line, and the post-restart scrub had no entry for it. That also explains the intermittency: 04202 must land on a fixed-database thread.
c Fix matches root cause? Yes. The defect is the scanner's blindness to a by-design log line, so the fix is one scoped entry in that scanner, which is what this file exists for (25 sibling entries). Product logging is untouched. Lowering LOG_ERROR to LOG_WARNING was rejected: it would change product logging to satisfy a CI scanner and hide a genuine misconfiguration from users.
d Test intent preserved / new tests added? Yes / no new test, deliberately. 04202 is untouched and still covers the relaxed branch; the throw branch stays covered by 02125, 02126 and 03277. Each of the four merged sibling allowlist commits in this block changed 1 file with 0 test files, and no harness in the tree asserts on this block.
e Both directions demonstrated? Yes, and against the failing run's own 19.9 MB clickhouse-server.upgrade.log, not only a fixture: with the entry the artifact is empty (sub-test No Error messages after server upgrade + OK); with the entry deleted the output is byte-identical (cmp) to the 189-byte upgrade_error_messages.txt CI uploaded, i.e. Error message in clickhouse-server.log + FAIL. Deleting just the new line is what flips it, confirming the entry is load-bearing and not a pattern that matches nothing.
f Fix is general across code paths? Yes. The message has exactly 2 emit sites in src/ (StorageFileLog.cpp:197 LOG_ERROR, :201 throw); only :197 can reach the server log, and it is unchanged. The other two LOG_ERRORs in that file carry different text and still surface. stress_runner.sh has no equivalent scanner, so no sibling entry is owed.
g Fix generalizes across inputs (params/datatypes/wrappers)? Yes within the scanner's input space, which is log text. Eight controls cover every axis that exists: same message on another table (default.my_real_filelog, test_9.other_tbl, prod.applog), a different message on the fixture table, a different logger, a paren-less prefix shape, and two tables whose names merely END with the fixture name (prod.other_filelog_bad_path_attach, prod.my_filelog_bad_path_attach). All still surface. The pattern requires the . StorageID separator so a prefix-extended name cannot be swallowed; the database prefix is intentionally not pinned, since --replicated-database yields an rdb_test_* prefix.
h Backward compatible? (maintainer-approved exception only) Yes, trivially. CI-only shell script: no settings, no defaults, no serialization, so no SettingsChangesHistory.cpp entry is owed.
i Invariants and contracts preserved? Yes. Invariant: suppress only this fixture's benign line, never a real table's. The change is one additional grep -av stage in an existing pipe, keeps the grep -Fa "<Error>" gate last, and bash -n passes. All eight negative controls show nothing else was widened, and the required . separator is what keeps a same-suffix production table visible. No locks, concurrency or error paths are involved.

Session id: cron:clickhouse-impl-slot-6:20260808-171700

@groeneai

groeneai commented Aug 8, 2026

Copy link
Copy Markdown
Collaborator Author

cc @leshikus, could you review this? It adds one scoped grep -av entry to the post-upgrade error scan: 04202 ATTACHes a FileLog table whose path is outside user_files_path, which takes the by-design relaxed branch that logs at and returns instead of throwing, and the table survives into the upgrade restart and re-logs it. The pattern requires the StorageID separator so the same error from an unrelated table still fails the job.

@alexey-milovidov alexey-milovidov added the can be tested Allows running workflows for external contributors label Aug 8, 2026
@clickhouse-gh

clickhouse-gh Bot commented Aug 8, 2026

Copy link
Copy Markdown
Contributor

Workflow [PR], commit [70cbee0]

Summary:


AI Review

Summary

This PR narrows the upgrade-check log scrub so it suppresses only the expected StorageFileLog (...filelog_bad_path_attach): The absolute data path should be inside ... line emitted when 04202_filelog_attach_path_outside_user_files is reattached during the upgrade restart. The current matcher now enforces the db.table): boundary, the rationale comment matches the actual ATTACH and fixed---database behavior, and I did not find a remaining correctness or evidence gap on the current head.

Final Verdict
  • Status: ✅ Approve

@clickhouse-gh clickhouse-gh Bot added the pr-ci label Aug 8, 2026
@groeneai

groeneai commented Aug 9, 2026

Copy link
Copy Markdown
Collaborator Author

CI finish ledger - 58245a2

CI is fully finished on this head and there are no failing checks.

Check / test Reason Owner / fixing PR
(none) - -
CH Inc sync private sync (SUCCESS) CH Inc sync (private, not actionable by me)

Session id: cron:our-pr-ci-monitor:20260809-013000

master gained four Backup-engine allowlist entries (ClickHouse#109042) plus a hung-check
fix in the same two regions of tests/docker_scripts/upgrade_runner.sh that this
branch edits, so the grep pipe conflicted.

Resolved as a union: every allowlist filter master added is kept verbatim and
the FileLog entry is appended after them. Verified that all 96 -e patterns
present on master survive the resolution and that the net diff against master
is still the reviewed 1 file / +5 / -0. A side-pick would have deleted a merged
allowlist entry and re-reddened the upgrade check for someone else.

The FileLog matcher keeps its reviewed scoping to the fixture table
(`.filelog_bad_path_attach`), so a genuine bad-path error elsewhere still
surfaces.
The rationale said the fixed-database tables are "never torn down", which
overstates it: 04202 runs its own final DROP, and a fixed --database only stops
clickhouse-test's framework-level cleanup. The table therefore survives only
when stress stops the fixture before that DROP, after which no teardown runs
from either side.

Verified: the fixture drops the table at
tests/queries/0_stateless/04202_filelog_attach_path_outside_user_files.sh:31,
and tests/clickhouse-test:4025 gates only the framework _cleanup on
`not args.database`.

Comment only, no behaviour change.
@clickhouse-gh clickhouse-gh Bot added the manual approve Manual approve required to run CI label Aug 13, 2026
Comment thread tests/docker_scripts/upgrade_runner.sh Outdated
@clickhouse-gh

clickhouse-gh Bot commented Aug 13, 2026

Copy link
Copy Markdown
Contributor

Build profile diff (arm_release)

Comparing 70cbee064 with master 84a72213f (stripped binary size, per-symbol sizes and ThinLTO time; object sizes against the warmup build of 5f6d1cd38; compile times per translation unit against the most recent warmup build that recompiled it).

✅ No significant changes.

Binary sizes
Binary Master PR Δ
programs/clickhouse-stripped 691.73 MiB 688.73 MiB -3.01 MiB (-0.43%)

Only the stripped binary is compared: the official master build keeps debug symbols while PR builds strip them, so the other binaries differ by construction.

Compile time of recompiled translation units

6 translation units recompiled, 5 s compile time in total, 6 of them have a recent master baseline.

Job report

The matcher used ".*" between the logger's closing paren and the message,
so it also suppressed a line carrying interposed text between the two, for
example "StorageFileLog (prod.filelog_bad_path_attach) prefix The absolute
data path should be inside ...". That is wider than the contract of this
entry, which is to allowlist exactly the one benign reattach line.

OwnPatternFormatter writes the logger source and then ": " unconditionally
(src/Loggers/OwnPatternFormatter.cpp:61-64), and colouring is off for the
file channel that produces the scanned clickhouse-server.upgrade.log
(src/Loggers/Loggers.cpp:159 takes the default color = false), so the two
are always adjacent in that file and requiring the literal boundary cannot
cause a miss.

Verified with GNU grep 3.11 against the real 19.9 MB
clickhouse-server.upgrade.log of the failing run: the target line is still
suppressed, the surviving output is byte-identical to the CI-produced
upgrade_error_messages.txt when the entry is removed, the delta between the
two arms is exactly that one line, and 9 negative controls still surface,
including the interposed-text shape. No allowlist entry from master is lost.
@groeneai

Copy link
Copy Markdown
Collaborator Author

CI finish ledger - 70cbee0

No failures to own on this head: 26 checks succeeded, 151 were skipped, and praktika reports
the run OK with 0 dropped jobs.

Check / test Reason Owner / fixing PR
- no failures -

The high skip count is expected for this diff, which touches only
tests/docker_scripts/upgrade_runner.sh: 103 jobs are not affected by the changed files, 25
report that coverage would be identical to master with no build-affecting changes, and the rest
carry ordinary reasons such as not a bug-fix PR or not labeled with pr-performance. No job was
dropped, so the run does carry real coverage.

Session id: cron:our-pr-ci-monitor:20260813-183000

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 manual approve Manual approve required to run CI pr-ci

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants