#2 Added new tests for session_log and fixed the inconsistency between login and logout. by Demilivor · Pull Request #53255 · ClickHouse/ClickHouse

Demilivor · 2023-08-10T04:47:17Z

Preivous PR was here:
#52958 Then the changes from PR were reverted here: #53247

Changes between this and the previous PR:
added the no-debug tag to the 02833_concurrrent_sessions and 02835_drop_user_during_session tests.
These tests require enough performance to run the required actions. I ran 100 times on my machine with the default build and got no failures.

Added several new tests for session_log and fixed the inconsistency of the session_log records between user login and logout.

Changelog category (leave one):

Bug Fix (user-visible misbehavior in an official stable release)

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Fixed the record inconsistency in session_log between login and logout.

Inconsistency comes from this behavior:
During a TCP session, the client authenticates as Alice, with interface 'TCP' (set in TCPHandler::makeSession()) on the server side, and then server calls makeSessionContext() with this client_info.
After session setup, the client sends Protocol::Client::Query packet, the TCP handler accepts it, and then reads client_info.

    ClientInfo client_info = session->getClientInfo(); 
    if (client_tcp_protocol_version >= DBMS_MIN_REVISION_WITH_CLIENT_INFO)
        client_info.read(*in, client_tcp_protocol_version); // <- overwrites interface,  hostname, client_name and several other parameters important for the session_log record.

client_tcp_protocol_version >= DBMS_MIN_REVISION_WITH_CLIENT_INFO is true for our case

This client_info is used for Session::createQueryContext and it can differ from session->getClientInfo().

Session::createQueryContext uses client info from query_context for the Login Success session log record.
Session::~Session uses client info from Session::getClientInfo()

This can lead to these results in the session log:

Login Success: User Alice, HTTP (from query_context) <- Some fields are overwritten by client_info.read() by some not-good clients.
Logout:  User Alice, TCP (from session_context)

This pull request forces using Session::getClientInfo() for login success and logout session_log records.

I think we should verify client_info from the client in TCPHandler. It should validate 'interface' at least, it should not be HTTP, GRPC, or other, host, client_name, and protocol versions also must match between session->getClientInfo() and received client_info.

Demilivor · 2023-08-10T04:55:21Z

Good day @tavplubix could you please be the reviewer in this PR?

Changes between this and the previous PR:
Added the no-debug tag to the 02833_concurrrent_sessions and 02835_drop_user_during_session tests.

robot-clickhouse-ci-1 · 2023-08-10T10:42:57Z

This is an automated comment for commit d499f80 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 🟢 success

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
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	🟢 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
Compatibility check	Checks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help	🟢 success
Docker image for servers	The check to build and optionally push the mentioned image to docker hub	🟢 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. 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 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
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
Push to Dockerhub	The check for building and pushing the CI related docker images to docker hub	🟢 success
SQLancer	Fuzzing tests that detect logical bugs with SQLancer tool	🟢 success
Sqllogic	Run clickhouse on the sqllogic test set against sqlite and checks that all statements are passed	🟢 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
Stress test	Runs stateless functional tests concurrently from several clients to detect concurrency-related errors	🟢 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

alexey-milovidov · 2023-08-10T21:59:46Z

It failed: https://s3.amazonaws.com/clickhouse-test-reports/0/c3c41253281bd3fb7f9209ac9bb4482db6597d6f/integration_tests__asan__[2_6].html

Demilivor · 2023-08-10T22:27:48Z

This fail comes from test_session_log/test.py::test_postgres_session

>       conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
E       psycopg2.OperationalError: connection to server at "172.16.1.2", port 5433 failed: Connection refused
E       	Is the server running on that host and accepting TCP/IP connections?

Postgres connection is failed. ClickHouse server was not even involved in this, It did not even receive a query. I don't see any related error in the clickhouse logs.

Demilivor · 2023-08-10T23:26:44Z

I can't guess why the connection from py_sql to ClickHouse failed, yet it always worked before (no changes in this test were made).

I want to avoid consuming the time of myself and other engineers to create new PRs, review them, and then revert them.
I consider my changes to be useful. Let's find a way out of this situation. I propose making several small pull requests instead of one pool request with bug fixes and tests:

1 for bugfix without tests (all existing tests will continue to work)
One PR for each individual test, including test_session_log/test.py::test_postgres_session. I don't observe any bugs in the test code of test_session_log/test.py::test_postgres_session. This fail looks like a random, occasional error. But If you wish, I may not add this test at all, and PostgreSQL session log verification will not be tested.

alexey-milovidov · 2023-08-11T00:17:03Z

Yes, this will work. Let's submit fixes without unstable parts of the tests first.
It will not allow us to remove the warning about the session log, but we will get at least something.

alexey-milovidov · 2023-08-11T00:19:19Z

This fail looks like a random, occasional error.

Random occasional errors exist in our infrastructure due to hardware failures in AWS, regional outages, and similar, but this is not the case.

alexey-milovidov · 2023-08-11T01:52:00Z

The test has failed four times over a short period:

check_start_time	check_name	test_name	report_url
2023-08-10 20:44:35	Integration tests (asan) [2/6]	test_session_log/test.py::test_postgres_session	https://s3.amazonaws.com/clickhouse-test-reports/0/c3c41253281bd3fb7f9209ac9bb4482db6597d6f/integration_tests__asan__[2_6].html
2023-08-10 20:46:19	Integration tests (asan, analyzer) [2/6]	test_session_log/test.py::test_postgres_session	https://s3.amazonaws.com/clickhouse-test-reports/0/c3c41253281bd3fb7f9209ac9bb4482db6597d6f/integration_tests__asan__analyzer__[2_6].html
2023-08-11 00:49:03	Integration tests (asan, analyzer) [2/6]	test_session_log/test.py::test_postgres_session	https://s3.amazonaws.com/clickhouse-test-reports/0/fd7b92e90aab592594712b074a51ccd00bde5fd5/integration_tests__asan__analyzer__[2_6].html
2023-08-11 00:52:07	Integration tests (tsan) [2/6]	test_session_log/test.py::test_postgres_session	https://s3.amazonaws.com/clickhouse-test-reports/0/fd7b92e90aab592594712b074a51ccd00bde5fd5/integration_tests__tsan__[2_6].html

https://play.clickhouse.com/play?user=play#U0VMRUNUIGNoZWNrX3N0YXJ0X3RpbWUsIGNoZWNrX25hbWUsIHRlc3RfbmFtZSwgcmVwb3J0X3VybApGUk9NIGNoZWNrcwpXSEVSRSBjaGVja19zdGFydF90aW1lID49IG5vdygpIC0gSU5URVJWQUwgMjQgSE9VUgogICAgQU5EIHB1bGxfcmVxdWVzdF9udW1iZXIgPSAwCiAgICBBTkQgdGVzdF9zdGF0dXMgIT0gJ1NLSVBQRUQnCiAgICBBTkQgdGVzdF9zdGF0dXMgTElLRSAnRiUnCiAgICBBTkQgY2hlY2tfc3RhdHVzICE9ICdzdWNjZXNzJwogICAgQU5EIHBvc2l0aW9uKHRlc3RfbmFtZSwgJ3Nlc3Npb25fbG9nJykgPiAwCk9SREVSIEJZIGNoZWNrX3N0YXJ0X3RpbWUKRk9STUFUIE1hcmtkb3du

Demilivor · 2023-08-11T02:04:04Z

Thanks for finding these failures. I Agree that something is wrong, I'm trying to figure it out right now, but I still have no clue why it happens. 4 Failures Is too many.

Clickhouse definitely listens to PostgreSQL `0.0.0.0:5433

2023.08.10 21:16:32.670516 [ 1 ] {} <Information> Application: Listening for PostgreSQL compatibility protocol: 0.0.0.0:5433

But in every log, I see the same error:

E       psycopg2.OperationalError: connection to server at "172.16.1.2", port 5433 failed: Connection refused
E        Is the server running on that host and accepting TCP/IP connections?

Clickhouse server logs do not contain anything that could help me find the root cause of the problem.

Demilivor · 2023-08-11T02:29:38Z

This is my test server log: valid_log.txt

When the Postgres connection is established, I see this message:
2023.08.10 04:29:48.123985 [ 10 ] {} <Trace> PostgreSQLHandlerFactory: PostgreSQL connection. Id: 0. Address: 172.16.1.1:62290

This message might catch an eye, but it is always contained in the log:
2023.08.10 04:29:46.845817 [ 8 ] {} <Information> TCPHandler: Client has not sent any data. I don't think it relates to the PostgreSQL connection.

Demilivor · 2023-08-11T03:48:57Z

Bug fix PR:
#53302

Demilivor · 2023-08-11T04:25:58Z

Separate pull requests for each individual test:

Added test for session_log using remote and mysql sessions Added test for session_log using remote and mysql sessions #53304
Added integration test for session_log using concurrrent GRPC/PostgreSQL/MySQL sessions Added integration test for session_log using concurrrent GRPC/PostgreSQL/MySQL sessions #53305
Added test for session_log using concurrrent TCP/HTTP/MySQL sessions Added test for session_log using concurrrent TCP/HTTP/MySQL sessions #53306
Added test for session_log dropping user/role/profile currently used in active session Added test for session_log dropping user/role/profile currently used in active session #53307

I will unmark those changes as 'DRAFT' after bugfix PR will be merged

Demilivor · 2023-08-15T08:15:45Z

ClickHouse several PostgreSQL tests broken:

https://github.com/ClickHouse/ClickHouse/blob/33763e7e50d283d2ad08b7e831c9494c9043ba2f/tests/analyzer_integration_broken_tests.txt#L98C6-L98C25

ClickHouse/tests/analyzer_integration_broken_tests.txt

Line 85 in 33763e7

test_storage_postgresql/test.py::test_postgres_select_insert

These tests use psycopg2 library for Postgres communication. For my purposes, it is not necessary to use it, but it is the easiest way to achieve my goal.

P.S. Another test, max session for user also uses this library:

ClickHouse/tests/integration/test_profile_max_sessions_for_user/test.py

Lines 127 to 133 in 33763e7

    
           def postgres_session(id): 
        
               ch = py_psql.connect( 
        
                   host=instance.ip_address, 
        
                   port=POSTGRES_SERVER_PORT, 
        
                   user=TEST_USER, 
        
                   password=TEST_PASSWORD, 
        
                   database="default",

I can rewrite the test using native PostgreSQL client psql.

Demilivor added 2 commits August 10, 2023 03:45

Added new tests for session_log and bugfix

b8be7ee

moved notified_session_log_about_login=true line

7b0036d

This was referenced Aug 10, 2023

Added new tests for session_log and fixed the inconsistency between login and logout. #52958

Merged

Added session_log events to text_log #53142

Closed

reverted change in test

d499f80

tavplubix self-assigned this Aug 10, 2023

tavplubix added the can be tested Allows running workflows for external contributors label Aug 10, 2023

robot-clickhouse-ci-1 added the pr-bugfix Pull request with bugfix, not backported by default label Aug 10, 2023

tavplubix approved these changes Aug 10, 2023

View reviewed changes

robot-ch-test-poll3 merged commit c3c4125 into ClickHouse:master Aug 10, 2023

alexey-milovidov mentioned this pull request Aug 10, 2023

Revert "#2 Added new tests for session_log and fixed the inconsistency between login and logout." #53294

Merged

Demilivor mentioned this pull request Aug 11, 2023

#3 Fixed inconsistency between login success and logout #53302

Merged

alexey-milovidov mentioned this pull request Aug 11, 2023

Bring back **garbage** dns tests #53286

Merged

1 task

Conversation

Demilivor commented Aug 10, 2023

Changelog category (leave one):

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Uh oh!

Demilivor commented Aug 10, 2023

Uh oh!

robot-clickhouse-ci-1 commented Aug 10, 2023 • edited by robot-ch-test-poll3 Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

alexey-milovidov commented Aug 10, 2023

Uh oh!

Demilivor commented Aug 10, 2023

Uh oh!

Demilivor commented Aug 10, 2023

Uh oh!

alexey-milovidov commented Aug 11, 2023

Uh oh!

alexey-milovidov commented Aug 11, 2023

Uh oh!

alexey-milovidov commented Aug 11, 2023

Uh oh!

Demilivor commented Aug 11, 2023

Uh oh!

Demilivor commented Aug 11, 2023

Uh oh!

Demilivor commented Aug 11, 2023

Uh oh!

Demilivor commented Aug 11, 2023

Uh oh!

Demilivor commented Aug 15, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

robot-clickhouse-ci-1 commented Aug 10, 2023 •

edited by robot-ch-test-poll3

Loading