Fix 03172_error_log_table_not_empty by pamarcos · Pull Request #65604 · ClickHouse/ClickHouse

pamarcos · 2024-06-24T10:56:00Z

Fix 03172_error_log_table_not_empty without any time constraints

Let's get rid of the time constraints by checking the previous number of errors and making sure they're increased.

Changelog category (leave one):

CI Fix or Improvement (changelog entry is not required)

Turns out when executing lots of tests in parallel there might be more than 1 min elapsed between the first errors and the second ones.

robot-ch-test-poll4 · 2024-06-24T10:57:48Z

This is an automated comment for commit fa3295b with description of existing statuses. It's updated for the latest CI running

❌ Click here to open a full report in a separate page

Check name	Description	Status
CI running	A meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR	❌ failure
Stress test	Runs stateless functional tests concurrently from several clients to detect concurrency-related errors	❌ failure

Successful checks

Check name	Description	Status
AST fuzzer	Runs randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help	✅ success
ClickBench	Runs [ClickBench](https://github.com/ClickHouse/ClickBench/) with instant-attach table	✅ success
ClickHouse build check	Builds 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
Cloud fork sync (only for ClickHouse Inc. employees)	If it fails, ask a maintainer for help	✅ success
Compatibility check	Checks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help	✅ success
Docker keeper image	The check to build and optionally push the mentioned image to docker hub	✅ success
Docker server image	The check to build and optionally push the mentioned image to docker hub	✅ success
Docs check	Builds and tests the documentation	✅ success
Fast test	Normally 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 tests	Checks 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. Integration 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 packages	Checks that the built packages are installable in a clear environment	✅ success
Integration tests	The integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests	✅ success
Mergeable Check	Checks if all other necessary checks are successful	✅ success
PR Check	Checks correctness of the PR's body	✅ success
Performance Comparison	Measure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests	✅ success
Stateful tests	Runs stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	✅ success
Stateless tests	Runs stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	✅ success
Style check	Runs a set of checks to keep the code style clean. If some of tests failed, see the related log from the report	✅ success
Unit tests	Runs the unit tests for different release types	✅ success
Upgrade check	Runs 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

devcrafter · 2024-06-24T12:14:06Z

This PR makes the test less flaky but doesn't fix flakiness. The system.errors lacks columns which can provide context. I'd consider adding there query_id at least (it'll be empty if error occurs not in a query context). This way, query_id could be used to filter the errors, and it'd not be necessary to rely on time.

devcrafter

It can be a temporary fix. And I'd suggest addressing the comment above (can be in separate PR)

pamarcos · 2024-06-24T13:49:17Z

The system.errors lacks columns which can provide context.

Just to clarify, do you mean system.errors or the new system.error_log? The latter is based on the former, so we'd have to add an array of query ids to system.errors anyway

I'd consider adding there query_id at least (it'll be empty if error occurs not in a query context). This way, query_id could be used to filter the errors, and it'd not be necessary to rely on time.

I thought exactly the same, because it'd help to disambiguate the query without the need for filtering within any time window at all.

pamarcos · 2024-06-24T14:10:51Z

I'm taking a look and we may have to limit the amount of query ids we store in system.errors. Maybe we can store the last 100 or 1000 or something among those lines.

e.g. the NOT_IMPLEMENTED in a recently started server in my dev machine has almost 20K entries. Which doesn't mean all of them belong to queries. I'll run some tests to check.

SELECT
    name,
    code,
    value
FROM system.errors

Query id: ff43780c-36c3-4081-bbfc-d0e1961a3a3c

   ┌─name─────────────────────┬─code─┬─value─┐
1. │ NOT_IMPLEMENTED          │   48 │ 19424 │
2. │ CANNOT_MANIPULATE_SIGSET │  111 │     1 │
3. │ NO_ELEMENTS_IN_CONFIG    │  139 │     2 │
4. │ KEEPER_EXCEPTION         │  999 │     2 │
   └──────────────────────────┴──────┴───────┘

4 rows in set. Elapsed: 0.016 sec.

devcrafter · 2024-06-24T14:34:36Z

Just to clarify, do you mean system.errors or the new system.error_log? The latter is based on the former, so we'd have to add an array of query ids to system.errors anyway

Yes, sorry, I meant system.error_log

Let's get rid of the time constraints by checking the previous number of errors and making sure they're increased.

devcrafter · 2024-06-26T10:23:19Z

@pamarcos Not a big deal here, but not sure that merging w/o review is a good thing. AFAIS, the updated test should be run sequentially, i.e. # Tags: no-parallel since it relies on previous state. Otherwise, in case of the test flakiness, it can succeed if another instance of the same test (running in parallel) wrote errors into log

pamarcos · 2024-06-26T13:55:43Z

@pamarcos Not a big deal here, but not sure that merging w/o review is a good thing. AFAIS, the updated test should be run sequentially, i.e. # Tags: no-parallel since it relies on previous state. Otherwise, in case of the test flakiness, it can succeed if another instance of the same test (running in parallel) wrote errors into log

@devcrafter you're absolutely right. My apologies 🙏. I rushed it because I saw more instances of the flake test making harm to other PRs CI.
I've created another PR adding the tag and added you as reviewer, if you don't mind. Please feel free to add any feedback there in case there's something missing apart from the no-parallel tag.

And I'd suggest addressing the comment above (can be in separate PR)

Regarding this, I have the work done in a branch that adds last 10 query_ids to system.errors and system.error_log. However, I presented the idea in a Slack thread, but I didn't get any positive feedback about it.

CheSema · 2024-07-04T13:01:52Z

That test 03172_error_log_table_not_empty become flaky after that change.

CheSema · 2024-07-04T13:07:54Z

tests/queries/0_stateless/03172_error_log_table_not_empty.sh

+SELECT throwIf(true, 'error_log', toInt16(111)) SETTINGS allow_custom_error_code_in_throwif=1; -- { serverError 111 }
+SELECT throwIf(true, 'error_log', toInt16(222)) SETTINGS allow_custom_error_code_in_throwif=1; -- { serverError 222 }
+SELECT throwIf(true, 'error_log', toInt16(333)) SETTINGS allow_custom_error_code_in_throwif=1; -- { serverError 333 }
+SELECT sleep(2) format NULL;


It should be marked as Tags: no-fasttest since it uses timeouts.

one type of error is:

2024-07-03 12:44:54 [ip-172-31-35-113] 2024.07.03 12:44:47.969209 [ 186095 ] {fa1e0b0e-25ea-4877-898e-7443db13c751} <Error> executeQuery: Code: 60. DB::Exception: Unknown table expression identifier 'system.error_log' in scope SELECT sum(value) FROM system.error_log WHERE code = 111. (UNKNOWN_TABLE) (version 24.7.1.1) (from [::ffff:127.0.0.1]:43186) (comment: 03172_error_log_table_not_empty.sh) (in query: SELECT sum(value) FROM system.error_log WHERE code = 111), Stack trace (when copying this message, always include the lines below):

the other type is:

2024-06-26 05:54:21 --- /usr/share/clickhouse-test/queries/0_stateless/03172_error_log_table_not_empty.reference 2024-06-26 05:06:35.554695301 +0700 2024-06-26 05:54:21 +++ /tmp/clickhouse-test/0_stateless/03172_error_log_table_not_empty.stdout 2024-06-26 05:54:21.550673271 +0700 2024-06-26 05:54:21 @@ -1,6 +1,6 @@ 2024-06-26 05:54:21 1 2024-06-26 05:54:21 1 2024-06-26 05:54:21 1 2024-06-26 05:54:21 -1 2024-06-26 05:54:21 -1 2024-06-26 05:54:21 -1 2024-06-26 05:54:21 +0 2024-06-26 05:54:21 +0 2024-06-26 05:54:21 +0

the second type of error is stale, it from the old version of the test AND event_time > now() - INTERVAL 1 MINUTE;

Systems tables are created lazily. It could be not created yet when we read from it.

fixing it #66093

It should be marked as Tags: no-fasttest since it uses timeouts.

Here's the reasoning why I closed the PR that added precisely that tag

the second type of error is stale, it from the old version of the test AND event_time > now() - INTERVAL 1 MINUTE;

That was part of the original test. The timing issue was fixed precisely in this PR. Are you sure the error you see is not from a prior and flaky version of the test?

Systems tables are created lazily. It could be not created yet when we read from it.

I don't follow you. At what point is the test reading from the table without flushing logs first?

It should be marked as Tags: no-fasttest since it uses timeouts.

Here's the reasoning why I closed the PR that added precisely that tag

No. You were trying to add Tags: no-parallel. I'm talking about Tags: no-fasttest because the test uses timeouts.

the second type of error is stale, it from the old version of the test AND event_time > now() - INTERVAL 1 MINUTE;

That was part of the original test. The timing issue was fixed precisely in this PR. Are you sure the error you see is not from a prior and flaky version of the test?

That error from the test before you changes. Your changes fixed that error, that is good.

Systems tables are created lazily. It could be not created yet when we read from it.

I don't follow you. At what point is the test reading from the table without flushing logs first?

here
errors_111=$($CLICKHOUSE_CLIENT -q "SELECT sum(value) FROM system.error_log WHERE code = 111")

No. You were trying to add Tags: no-parallel. I'm talking about Tags: no-fasttest because the test uses timeouts.

Right, but since it's not using timeouts anymore it shouldn't be needed, right?

here
errors_111=$($CLICKHOUSE_CLIENT -q "SELECT sum(value) FROM system.error_log WHERE code = 111")

You're absolutely right, my bad

Right, but since it's not using timeouts anymore it shouldn't be needed, right?

Yes. This is why I fight for it and trying remove timeouts. It is better to leave the test to work as fast-test. Then mark it as no-fasttest.

I see. The test takes ~6s to complete. If that's too long for a fast-test (I don't know where the limit is) let's add the no-fasttest 👍

Increase the interval to be less optimistic

059e786

Turns out when executing lots of tests in parallel there might be more than 1 min elapsed between the first errors and the second ones.

robot-ch-test-poll4 added the pr-ci label Jun 24, 2024

pamarcos added the can be tested Allows running workflows for external contributors label Jun 24, 2024

devcrafter reviewed Jun 24, 2024

View reviewed changes

Fix 03172_error_log_table_not_empty without any time constraints

fa3295b

Let's get rid of the time constraints by checking the previous number of errors and making sure they're increased.

pamarcos requested a review from devcrafter June 25, 2024 10:50

nikitamikhaylov assigned devcrafter Jun 25, 2024

pamarcos added this pull request to the merge queue Jun 26, 2024

Merged via the queue into ClickHouse:master with commit b28202d Jun 26, 2024

pamarcos deleted the 03172_error_log_table_not_empty branch June 26, 2024 08:41

robot-ch-test-poll1 added the pr-synced-to-cloud The PR is synced to the cloud repo label Jun 26, 2024

pamarcos mentioned this pull request Jun 26, 2024

Prevent 03172_error_log_table_not_empty from running in parallel #65725

Closed

CheSema reviewed Jul 4, 2024

View reviewed changes

CheSema mentioned this pull request Jul 4, 2024

fix flaky 03172_error_log_table_not_empty #66093

Merged

19 tasks

Conversation

pamarcos commented Jun 24, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Changelog category (leave one):

Uh oh!

robot-ch-test-poll4 commented Jun 24, 2024 • edited by robot-ch-test-poll Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

devcrafter commented Jun 24, 2024

Uh oh!

devcrafter left a comment

Choose a reason for hiding this comment

Uh oh!

pamarcos commented Jun 24, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

pamarcos commented Jun 24, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

devcrafter commented Jun 24, 2024

Uh oh!

devcrafter commented Jun 26, 2024

Uh oh!

pamarcos commented Jun 26, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

CheSema commented Jul 4, 2024

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

pamarcos commented Jun 24, 2024 •

edited

Loading

robot-ch-test-poll4 commented Jun 24, 2024 •

edited by robot-ch-test-poll

Loading

pamarcos commented Jun 24, 2024 •

edited

Loading

pamarcos commented Jun 24, 2024 •

edited

Loading

pamarcos commented Jun 26, 2024 •

edited

Loading