Flaky coordination_test::describe_semaphore_test

[uslon]

Test coordination_test::describe_semaphore_test tends to fail in an unpredictable manner.
What causes test to crush is this assertion. It seems that one of the concurrent sessions is too late to take a semaphore ticket after it was released.

Here is failed check and

Test output

running 41 tests
test auth_test::wrong_password_test - should panic ... ok
test auth_test::auth_success_test ... ok
test auth_test::wrong_username_test - should panic ... ok
test auth_test::auth_async_success_test ... ok
test client_builder::test::database_from_arg ... ok
test client_builder::test::database_from_path ... ok
test client_builder::test::password_without_username ... ok
test auth_test::password_client_test ... ok
test client_table_test_integration::create_session ... ok
test client_directory_test_integration::create_list_remove_directory ... ok
test client_table_test_integration::execute_data_query ... ok
test client_table_test_integration::execute_data_query_params ... ok
test client_table_test_integration::execute_data_query_field_name ... ok
test client_table_test_integration::query_yson ... ok
test client_table_test_integration::retry_test ... ok
test client_table_test_integration::copy_tables ... ok
test client_table_test_integration::copy_table ... ok
test client_table_test_integration::select_int64_null4 ... ok
test client_table_test_integration::select_int ... ok
test client_table_test_integration::select_optional ... ok
test client_table_test_integration::select_list ... ok
test client_table_test_integration::interactive_transaction ... ok
test client_table_test_integration::select_void_null ... ok
test client_table_test_integration::select_struct ... ok
test client_table_test_integration::scheme_query ... ok
test coordination_test::create_delete_node_test ... ok
test coordination_test::ephemeral_mutex_test ... ok
test coordination_test::mutex_test ... ok
test grpc_wrapper::raw_table_service::value::proto_test::convert_raw_protobuf ... ok
test grpc_wrapper::raw_table_service::value::r#type::type_test::consistent_conversion ... ok
test grpc_wrapper::raw_table_service::value::value_ydb::value_ydb_test::convert_ydb_raw_grpc ... ok
test load_balancer::test::random_load_balancer ... ok
test load_balancer::test::shared_load_balancer ... ok
test load_balancer::test::update_load_balancer_test ... ok
test discovery::test::test_background_discovery ... ok
test session_pool::test::max_active_session ... ok
test topics_test::create_delete_topic_test ... ok
test types_test::test_is_optional ... ok
test coordination_test::describe_semaphore_test ... FAILED
test topics_test::send_message_test ... ok
test client_table_test_integration::stream_query ... ok

failures:

---- coordination_test::describe_semaphore_test stdout ----
2024-03-14T12:15:20.305457Z TRACE describe_semaphore_test:create_client: ydb::test_integration_helper: get client
2024-03-14T12:15:20.305628Z TRACE describe_semaphore_test:create_client: ydb::test_integration_helper: start wait
2024-03-14T12:15:20.305641Z TRACE ydb::client_common: token renewed
2024-03-14T12:15:20.305657Z TRACE describe_semaphore_test:create_client: ydb::client: waiting_token
2024-03-14T12:15:20.305674Z TRACE describe_semaphore_test:create_client: ydb::client: wait discovery
2024-03-14T12:15:20.305688Z TRACE describe_semaphore_test:create_client: ydb::discovery: start discovery shared state
2024-03-14T12:15:20.305699Z TRACE describe_semaphore_test:create_client: ydb::discovery: loop
2024-03-14T12:15:20.305719Z TRACE describe_semaphore_test: ydb::discovery: timer discovery wait token
2024-03-14T12:15:20.305727Z TRACE describe_semaphore_test: ydb::discovery: timer discovery first token done with result: Ok(())
2024-03-14T12:15:20.305750Z TRACE describe_semaphore_test:background_discovery{interval=60s}: ydb::discovery: rekby-discovery
2024-03-14T12:15:20.305768Z TRACE describe_semaphore_test:background_discovery{interval=60s}:discovery_now: ydb::discovery: discovery locking
2024-03-14T12:15:20.305780Z TRACE describe_semaphore_test:background_discovery{interval=60s}:discovery_now: ydb::discovery: creating grpc client
2024-03-14T12:15:20.309661Z TRACE describe_semaphore_test:background_discovery{interval=60s}: ydb::discovery: rekby-res: Ok(())
2024-03-14T12:15:20.309745Z TRACE describe_semaphore_test:create_client: ydb::discovery: loop
2024-03-14T12:15:20.309762Z TRACE describe_semaphore_test:create_client: ydb::discovery: return ok
2024-03-14T12:15:20.309770Z TRACE describe_semaphore_test:create_client: ydb::client: wait balancer
2024-03-14T12:15:20.309874Z TRACE describe_semaphore_test: ydb::grpc_wrapper::raw_coordination_service::client:  $ClientType.drop_node request: {"path":"/local/test_describe_semaphore","operation_params":{"operation_mode":1,"operation_timeout":{"seconds":60,"nanos":0},"cancel_after":{"seconds":60,"nanos":0},"labels":{},"report_cost_info":0}}
2024-03-14T12:15:20.312571Z TRACE describe_semaphore_test: ydb::grpc_wrapper::raw_coordination_service::client:  $ClientType.create_node request: {"path":"/local/test_describe_semaphore","config":{"path":"","self_check_period_millis":0,"session_grace_period_millis":0,"read_consistency_mode":0,"attach_consistency_mode":0,"rate_limiter_counters_mode":0},"operation_params":{"operation_mode":1,"operation_timeout":{"seconds":60,"nanos":0},"cancel_after":{"seconds":60,"nanos":0},"labels":{},"report_cost_info":0}}
2024-03-14T12:15:20.335502Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: session started! SessionStarted { session_id: 1, timeout_millis: 0 }
2024-03-14T12:15:20.335660Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(Ping(PingPong { opaque: 10685316807501029190 }))
2024-03-14T12:15:20.338218Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: session started! SessionStarted { session_id: 2, timeout_millis: 0 }
2024-03-14T12:15:20.339035Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(Ping(PingPong { opaque: 10821633199977610807 }))
2024-03-14T12:15:20.342961Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: session started! SessionStarted { session_id: 3, timeout_millis: 0 }
2024-03-14T12:15:20.343032Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(Ping(PingPong { opaque: 4780101435558417356 }))
2024-03-14T12:15:20.344803Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(CreateSemaphoreResult(RawCreateSemaphoreResult { req_id: 0 }))
2024-03-14T12:15:20.345690Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(DescribeSemaphoreResult(RawDescribeSemaphoreResult { req_id: 0, semaphore_description: SemaphoreDescription { name: "my-resource", data: [], count: 0, limit: 2, ephemeral: false, owners: [], waiters: [] }, watch_added: false }))
2024-03-14T12:15:20.347190Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(AcquireSemaphoreResult(RawAcquireSemaphoreResult { req_id: 0, acquired: true }))
2024-03-14T12:15:20.347757Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(DescribeSemaphoreResult(RawDescribeSemaphoreResult { req_id: 1, semaphore_description: SemaphoreDescription { name: "my-resource", data: [], count: 1, limit: 2, ephemeral: false, owners: [SemaphoreSession { order_id: 1, session_id: 1, timeout_millis: 0, count: 1, data: [] }], waiters: [] }, watch_added: false }))
2024-03-14T12:15:20.349183Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(AcquireSemaphoreResult(RawAcquireSemaphoreResult { req_id: 0, acquired: true }))
2024-03-14T12:15:20.349649Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(DescribeSemaphoreResult(RawDescribeSemaphoreResult { req_id: 2, semaphore_description: SemaphoreDescription { name: "my-resource", data: [], count: 2, limit: 2, ephemeral: false, owners: [SemaphoreSession { order_id: 1, session_id: 1, timeout_millis: 0, count: 1, data: [] }, SemaphoreSession { order_id: 2, session_id: 2, timeout_millis: 0, count: 1, data: [2, 2, 2, 2, 2] }], waiters: [] }, watch_added: false }))
2024-03-14T12:15:20.351098Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(AcquireSemaphorePending(AcquireSemaphorePending { req_id: 0 }))
2024-03-14T12:15:20.552182Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(DescribeSemaphoreResult(RawDescribeSemaphoreResult { req_id: 3, semaphore_description: SemaphoreDescription { name: "my-resource", data: [], count: 2, limit: 2, ephemeral: false, owners: [SemaphoreSession { order_id: 1, session_id: 1, timeout_millis: 0, count: 1, data: [] }, SemaphoreSession { order_id: 2, session_id: 2, timeout_millis: 0, count: 1, data: [2, 2, 2, 2, 2] }], waiters: [SemaphoreSession { order_id: 3, session_id: 3, timeout_millis: 20000, count: 1, data: [3, 3, 3, 3, 3] }] }, watch_added: false }))
2024-03-14T12:15:20.552368Z TRACE describe_semaphore_test: ydb::client_coordination::session::lease: releaseing semaphore my-resource
2024-03-14T12:15:20.552438Z TRACE describe_semaphore_test: ydb::client_coordination::session::lease: releaseing semaphore my-resource
2024-03-14T12:15:20.554060Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(ReleaseSemaphoreResult(RawReleaseSemaphoreResult { req_id: 0, released: true }))
2024-03-14T12:15:20.554122Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(ReleaseSemaphoreResult(RawReleaseSemaphoreResult { req_id: 1, released: false }))
2024-03-14T12:15:20.554204Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(AcquireSemaphoreResult(RawAcquireSemaphoreResult { req_id: 0, acquired: true }))
2024-03-14T12:15:20.554260Z TRACE describe_semaphore_test: ydb::client_coordination::session::lease: semaphore my-resource released
2024-03-14T12:15:20.554399Z TRACE describe_semaphore_test: ydb::client_coordination::session::lease: releaseing semaphore my-resource
2024-03-14T12:15:20.555790Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(ReleaseSemaphoreResult(RawReleaseSemaphoreResult { req_id: 0, released: true }))
2024-03-14T12:15:20.555853Z TRACE describe_semaphore_test: ydb::client_coordination::session::coordination_session: received response: Ok(DescribeSemaphoreResult(RawDescribeSemaphoreResult { req_id: 4, semaphore_description: SemaphoreDescription { name: "my-resource", data: [], count: 1, limit: 2, ephemeral: false, owners: [SemaphoreSession { order_id: 1, session_id: 1, timeout_millis: 0, count: 1, data: [] }], waiters: [] }, watch_added: false }))
2024-03-14T12:15:20.555897Z TRACE describe_semaphore_test: ydb::client_coordination::session::lease: semaphore my-resource released
thread 'coordination_test::describe_semaphore_test' panicked at ydb/src/coordination_test.rs:317:5:
assertion `left == right` failed
  left: 1
 right: 2


failures:
    coordination_test::describe_semaphore_test

test result: FAILED. 40 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 13.96s

error: test failed, to rerun pass `-p ydb --lib`
Error: Process completed with exit code 101.