Improve waiting for specific line in logs in integration tests

azat · azat · commit 586450e1a50c · 2025-08-22T15:01:03.000+02:00
Recently CI found the failure of test_postgresql_replica_database_engine [1], but, according to logs: - the grep executed **before** the log entry appeared in logs - the log entry appeared **before** timeout expired <details> <summary>logs</summary> ``` 2025-08-21 16:45:14.632000 [ 683 ] DEBUG : Command:[docker exec roottestpostgresqlreplicadatabaseengine0-gw0-instance-1 bash -c timeout 30 tail -Fn100 "/var/log/clickhouse-server/clickhouse-server.log" | grep -Em 1 'Table postgresql_replica_2 is skipped from replication stream'] (cluster.py:159, run_and_check) 2025-08-21 16:45:44.679000 [ 683 ] DEBUG : Exitcode:1 (cluster.py:187, run_and_check) ``` ``` 2025.08.21 16:45:14.638793 [ 962 ] {BgSchPool::8d13df61-833b-4141-83e2-0e8e1c30d1c9} <Information> PostgreSQLReplicaConsumer(postgres_database): Table structure of the table postgresql_replica_2 changed (column value2 was not found), will mark it as skipped from replication. Please perform manual DETACH and ATTACH of the table to bring it back 2025.08.21 16:45:14.638813 [ 962 ] {BgSchPool::8d13df61-833b-4141-83e2-0e8e1c30d1c9} <Warning> PostgreSQLReplicaConsumer(postgres_database): Table postgresql_replica_2 is skipped from replication stream because its structure has changes. Please detach this table and reattach to resume the replication (relation id: 16583) ``` </details> But the test was not succeeded in locating this line. [1]: https://s3.amazonaws.com/clickhouse-test-reports/json.html?PR=85765&sha=d9c83add6087386351df45010de71b027af87a76&name_0=PR&name_1=Integration%20tests%20%28amd_binary%2C%204%2F5%29 I don't see any other reason except for line buffer for this to happen, so let's disable it with `stdbuf`. Also I've added some introspection with `tee /dev/stderr`, so that now we will see all entries that the `grep` received.
diff --git a/tests/integration/helpers/cluster.py b/tests/integration/helpers/cluster.py
@@ -4741,7 +4741,7 @@ def wait_for_log_line(
             [
                 "bash",
                 "-c",
-                'timeout {} tail -Fn{} "{}" | grep -Em {} {}'.format(
+                'timeout {} stdbuf -o0 -e0 tail -Fn{} "{}" | stdbuf -o0 -e0 tee /dev/stderr | grep -Em {} {}'.format(
                     timeout,
                     look_behind_lines,
                     filename,

Original file line number	Diff line number	Diff line change
`@@ -4741,7 +4741,7 @@ def wait_for_log_line(`
`4741`	`4741`	`[`
`4742`	`4742`	`"bash",`
`4743`	`4743`	`"-c",`
`4744`		`- 'timeout {} tail -Fn{} "{}" \| grep -Em {} {}'.format(`
	`4744`	`+ 'timeout {} stdbuf -o0 -e0 tail -Fn{} "{}" \| stdbuf -o0 -e0 tee /dev/stderr \| grep -Em {} {}'.format(`
`4745`	`4745`	`timeout,`
`4746`	`4746`	`look_behind_lines,`
`4747`	`4747`	`filename,`