CI founds one failure of this test [1], which is quite interesting, the
test itself should not takes too long:
2023.06.04 05:01:36.889144 [ 42287 ] {} <Trace> DynamicQueryHandler: Request URI: /?query=SELECT+%27Running+test+stateless%2F01565_query_loop_after_client_error.expect+from+pid%3D1053%27&database=system&connect_timeout=30&receive_timeout=30&send_timeout=30&http_connection_timeout=30&http_receive_timeout=30&http_send_timeout=30&output_format_parallel_formatting=0
...
2023.06.04 05:01:37.364595 [ 42844 ] {fa79939f-1fa0-4f3b-b599-fd2269122d6a} <Debug> executeQuery: (from [::1]:40264) (comment: 01565_query_loop_after_client_error.expect) INSERT INTO t01565(c0, c1) VALUES (stage: Complete)
2023.06.04 05:01:37.366485 [ 42844 ] {fa79939f-1fa0-4f3b-b599-fd2269122d6a} <Information> TCPHandler: Change cancellation status from NOT_CANCELLED to FULLY_CANCELLED. Log message: Received 'Cancel' packet from the client, canceling the query.
2023.06.04 05:01:37.366810 [ 42844 ] {fa79939f-1fa0-4f3b-b599-fd2269122d6a} <Debug> TCPHandler: Processed in 0.002539914 sec.
But for the last INSERT the client itself works **very slow**, which
seems was the reason why "\r" had been sent too early and was never
interpreted:
send: sending "INSERT INTO t01565(c0, c1) VALUES ('1', 1) ;\n" to { exp4 }
expect: does " " (spawn_id exp4) match glob pattern "INSERT"? no
[21GI[0m[J[22G
expect: does " \u001b[21GI\u001b[0m\u001b[J\u001b[22G" (spawn_id exp4) match glob pattern "INSERT"? no
[21G
expect: does " \u001b[21GI\u001b[0m\u001b[J\u001b[22G\u001b[21G" (spawn_id exp4) match glob pattern "INSERT"? no
INSERT INTO t[0m
expect: does " \u001b[21GI\u001b[0m\u001b[J\u001b[22G\u001b[21GINSERT INTO t\u001b[0m" (spawn_id exp4) match glob pattern "INSERT"? yes
expect: set expect_out(0,string) "INSERT"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) " \u001b[21GI\u001b[0m\u001b[J\u001b[22G\u001b[21GINSERT"
send: sending "\r" to { exp4 }
expect: does " INTO t\u001b[0m" (spawn_id exp4) match glob pattern "Ok."? no
[J
expect: does " INTO t\u001b[0m\u001b[J" (spawn_id exp4) match glob pattern "Ok."? no
[34G
expect: does " INTO t\u001b[0m\u001b[J\u001b[34G" (spawn_id exp4) match glob pattern "Ok."? no
[21G
expect: does " INTO t\u001b[0m\u001b[J\u001b[34G\u001b[21G" (spawn_id exp4) match glob pattern "Ok."? no
[JINSERT INTO t01565[0;22;33m([0mc0[0;1m,[0m c1[0;22;33m)[0m VALUES [0;22;33m([0;22;36m'1'[0;1m,[0m [0;22;32m1[0;22;33m)[0m [0;1m;[0m
[0m[1G
expect: does " INTO t\u001b[0m\u001b[J\u001b[34G\u001b[21G\u001b[JINSERT INTO t01565\u001b[0;22;33m(\u001b[0mc0\u001b[0;1m,\u001b[0m c1\u001b[0;22;33m)\u001b[0m VALUES \u001b[0;22;33m(\u001b[0;22;36m'1'\u001b[0;1m,\u001b[0m \u001b[0;22;32m1\u001b[0;22;33m)\u001b[0m \u001b[0;1m;\u001b[0m\r\n\r\n\u001b[0m\u001b[1G" (spawn_id exp4) match glob pattern "Ok."? no
expect: timed out
Here you can see that it matched "INSERT" and then expect receive data
from the client almost byte by byte.
So I hope that expecting the last part of the query should fix the
problem.
[1]: https://s3.amazonaws.com/clickhouse-test-reports/50429/228ebab86db95dca1e29967061d245985bc86a0f/stateless_tests__release__s3_storage__[2_2].html
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
