Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Make 01565_query_loop_after_client_error slightly more robust #50542

Merged
merged 1 commit into from Jun 5, 2023

Conversation

azat
Copy link
Collaborator

@azat azat commented Jun 4, 2023

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.

Changelog category (leave one):

  • Not for changelog (changelog entry is not required)

@robot-clickhouse-ci-1 robot-clickhouse-ci-1 added the pr-not-for-changelog This PR should not be mentioned in the changelog label Jun 4, 2023
@robot-clickhouse-ci-1
Copy link
Contributor

robot-clickhouse-ci-1 commented Jun 4, 2023

This is an automated comment for commit 60c2245 with description of existing statuses. It's updated for the latest CI running
The full report is available here
The overall status of the commit is 🔴 failure

Check nameDescriptionStatus
AST fuzzerRuns randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help🟢 success
CI runningA meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR🟢 success
ClickHouse build checkBuilds ClickHouse in various configurations for use in further steps. You have to fix the builds that fail. Build logs often has enough information to fix the error, but you might have to reproduce the failure locally. The cmake options can be found in the build log, grepping for cmake. Use these options and follow the general build process🟢 success
Compatibility checkChecks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help🟢 success
Docker image for serversThe check to build and optionally push the mentioned image to docker hub🟢 success
Fast testNormally this is the first check that is ran for a PR. It builds ClickHouse and runs most of stateless functional tests, omitting some. If it fails, further checks are not started until it is fixed. Look at the report to see which tests fail, then reproduce the failure locally as described here🟢 success
Flaky testsChecks if new added or modified tests are flaky by running them repeatedly, in parallel, with more randomization. Functional tests are run 100 times with address sanitizer, and additional randomization of thread scheduling. Integrational tests are run up to 10 times. If at least once a new test has failed, or was too long, this check will be red. We don't allow flaky tests, read the doc🟢 success
Install packagesChecks that the built packages are installable in a clear environment🟢 success
Integration testsThe integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests🔴 failure
Mergeable CheckChecks if all other necessary checks are successful🟢 success
Performance ComparisonMeasure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests🟢 success
Push to DockerhubThe check for building and pushing the CI related docker images to docker hub🟢 success
SQLancerFuzzing tests that detect logical bugs with SQLancer tool🟢 success
SqllogicRun clickhouse on the sqllogic test set against sqlite and checks that all statements are passed🟢 success
Stateful testsRuns stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc🟢 success
Stateless testsRuns stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc🟢 success
Stress testRuns stateless functional tests concurrently from several clients to detect concurrency-related errors🟢 success
Style CheckRuns a set of checks to keep the code style clean. If some of tests failed, see the related log from the report🟢 success
Unit testsRuns the unit tests for different release types🟢 success
Upgrade checkRuns stress tests on server version from last release and then tries to upgrade it to the version from the PR. It checks if the new server can successfully startup without any errors, crashes or sanitizer asserts🟢 success

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>
@alexey-milovidov alexey-milovidov merged commit 6241ea3 into ClickHouse:master Jun 5, 2023
258 of 259 checks passed
@azat azat deleted the tests/fix-expect branch June 5, 2023 06:54
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
pr-not-for-changelog This PR should not be mentioned in the changelog
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants