2025-10-26 19:25:29,833 - INFO - ya.test - pytest_runtest_setup: ####################################################################################################
2025-10-26 19:25:29,834 - INFO - ya.test - pytest_runtest_setup: test_dynconfig
2025-10-26 19:25:29,834 - INFO - ya.test - pytest_runtest_setup: ####################################################################################################
2025-10-26 19:25:29,834 - INFO - ya.test - pytest_runtest_setup: Test setup
2025-10-26 19:25:29,836 - DEBUG - ydb.connection - channel_factory: Channel options: [('grpc.max_receive_message_length', 64000000), ('grpc.max_send_message_length', 64000000), ('grpc.primary_user_agent', 'python-library'), ('grpc.lb_policy_name', 'round_robin')]
2025-10-26 19:25:29,838 - DEBUG - ydb.resolver.DiscoveryEndpointsResolver - context_resolve: Preparing initial endpoint to resolve endpoints
2025-10-26 19:25:29,840 - DEBUG - ydb.connection - channel_factory: Channel options: [('grpc.max_receive_message_length', 64000000), ('grpc.max_send_message_length', 64000000), ('grpc.primary_user_agent', 'python-library'), ('grpc.lb_policy_name', 'round_robin')]
2025-10-26 19:25:29,844 - INFO - ya.test - pytest_runtest_call: Test call (class_name: test_auditlog.py, test_name: test_dynconfig)
2025-10-26 19:25:29,845 - DEBUG - ydb.table.SessionPool - subscribe: Active session queue is empty, subscribe waiter for a session
2025-10-26 19:25:29,846 - DEBUG - ydb.table.SessionPool - subscribe: Subscribe waiter <Future at 0x6040003ac6b0 state=pending>
2025-10-26 19:25:29,846 - DEBUG - ydb.table.SessionPool - subscribe: Session pool is not large enough (active_count < size: 0 < 100). will create a new session.
2025-10-26 19:25:29,846 - DEBUG - ydb.table.SessionPool - _create: Created session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:29,847 - DEBUG - ydb.table.SessionPool - _prepare: Preparing session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:29,847 - ERROR - ydb.table.SessionPool - _on_session_create: Failed to create session. Put event to a delayed queue. Reason: Couldn't find valid connection
2025-10-26 19:25:29,853 - DEBUG - ydb.resolver.DiscoveryEndpointsResolver - context_resolve: Resolving endpoints for database /Root/test_auditlog.py
2025-10-26 19:25:29,854 - DEBUG - ydb.connection - _prepare_call: RpcState(ListEndpoints, 53ab5f9b-083d-4cf9-9b16-e5011dd642e5, localhost:26286): creating call state
2025-10-26 19:25:29,855 - DEBUG - ydb.connection - _log_request: RpcState(ListEndpoints, 53ab5f9b-083d-4cf9-9b16-e5011dd642e5, localhost:26286): request = { database: "/Root/test_auditlog.py" }
2025-10-26 19:25:29,860 - DEBUG - ydb.connection - _log_response: RpcState(ListEndpoints, 53ab5f9b-083d-4cf9-9b16-e5011dd642e5, localhost:26286): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Discovery.ListEndpointsResult] { endpoints { address: "ghrun-pqq4nwlsgu.auto.internal" port: 3601 service: "legacy" service: "yql" service: "discovery" service: "cms" service: "locking" service: "kesus" service: "pq" service: "pqcd" service: "pqv1" service: "topic" service: "datastreams" service: "scripting" service: "clickhouse_internal" service: "rate_limiter" service: "analytics" service: "export" service: "import" service: "yq" service: "keyvalue" service: "monitoring" service: "auth" service: "query_service" node_id: 50000 } self_location: "1" } } } }
2025-10-26 19:25:29,862 - DEBUG - ydb.resolver.DiscoveryEndpointsResolver - _add_debug_details: Resolved endpoints for database /Root/test_auditlog.py: DiscoveryResult <self_location: 1, endpoints [<Endpoint ghrun-pqq4nwlsgu.auto.internal:3601, location , ssl: False>]>
2025-10-26 19:25:29,863 - DEBUG - ydb.connection - channel_factory: Channel options: [('grpc.max_receive_message_length', 64000000), ('grpc.max_send_message_length', 64000000), ('grpc.primary_user_agent', 'python-library'), ('grpc.lb_policy_name', 'round_robin')]
2025-10-26 19:25:29,886 - INFO - ydb.connection - close: Closing channel for endpoint localhost:26286
2025-10-26 19:25:29,887 - DEBUG - ydb.table.SessionPool - _prepare: Preparing session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:29,887 - DEBUG - ydb.connection - _prepare_call: RpcState(CreateSession, 6979e5f0-c27d-4b14-99c1-a517108c9512, ghrun-pqq4nwlsgu.auto.internal:3601): creating call state
2025-10-26 19:25:29,888 - DEBUG - ydb.connection - _log_request: RpcState(CreateSession, 6979e5f0-c27d-4b14-99c1-a517108c9512, ghrun-pqq4nwlsgu.auto.internal:3601): request = { operation_params { operation_timeout { seconds: 3 } cancel_after { seconds: 3 } } }
2025-10-26 19:25:29,895 - DEBUG - ydb.connection - _on_response_callback: RpcState(CreateSession, 6979e5f0-c27d-4b14-99c1-a517108c9512, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback started
2025-10-26 19:25:29,896 - DEBUG - ydb.connection - _log_response: RpcState(CreateSession, 6979e5f0-c27d-4b14-99c1-a517108c9512, ghrun-pqq4nwlsgu.auto.internal:3601): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Table.CreateSessionResult] { session_id: "ydb://session/3?node_id=50000&id=MmI3NmEwMjgtODgyMTFjMTQtNTk1OTVhMjctMmZiYWFmNjU=" } } } }
2025-10-26 19:25:29,896 - DEBUG - ydb.table.SessionPool - put: Put on session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:29,897 - DEBUG - ydb.table.SessionPool - put: Replying to waiter with a session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:29,898 - DEBUG - ydb.connection - _on_response_callback: RpcState(CreateSession, 6979e5f0-c27d-4b14-99c1-a517108c9512, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback success
2025-10-26 19:25:29,898 - DEBUG - ydb.connection - _prepare_call: RpcState(SetConfig, 700f4205-c8ad-44d0-b9fe-329443effbdb, ghrun-pqq4nwlsgu.auto.internal:3601): creating call state
2025-10-26 19:25:29,899 - DEBUG - ydb.connection - _log_request: RpcState(SetConfig, 700f4205-c8ad-44d0-b9fe-329443effbdb, ghrun-pqq4nwlsgu.auto.internal:3601): request = { operation_params { operation_timeout { seconds: 600 } cancel_after { seconds: 600 } } config: "\n---\nmetadata:\n  kind: MainConfig\n  cluster: \"\"\n  version: 0\nconfig:\n  yaml_config_enabled: true\nallowed_labels:\n  node_id:\n    type: string\n  host:\n    type: string\n  tenant:\n    type: string\nselector_config: []\n    " }
2025-10-26 19:25:29,915 - DEBUG - ydb.connection - _log_response: RpcState(SetConfig, 700f4205-c8ad-44d0-b9fe-329443effbdb, ghrun-pqq4nwlsgu.auto.internal:3601): response = { operation { ready: true status: SUCCESS } }
2025-10-26 19:25:29,916 - DEBUG - ydb.table.SessionPool - put: Put on session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:30,019 - INFO - ya.test - pytest_runtest_teardown: Test teardown
2025-10-26 19:25:30,020 - DEBUG - ydb.table.SessionPool - stop: Requested session pool stop.
2025-10-26 19:25:30,020 - DEBUG - ydb.table.SessionPool - stop: Session pool is under stop, cancelling all in flight waiters.
2025-10-26 19:25:30,021 - DEBUG - ydb.table.SessionPool - stop: Destroying sessions in active queue
2025-10-26 19:25:30,021 - DEBUG - ydb.table.SessionPool - _destroy: Requested session destroy: <ydb.table.Session object at 0x6040003ae6b0>, reason: session-pool-terminated
2025-10-26 19:25:30,024 - DEBUG - ydb.table.SessionPool - _destroy: Session <ydb.table.Session object at 0x6040003ae6b0> is no longer active. Current active count 0.
2025-10-26 19:25:30,025 - DEBUG - ydb.table.SessionPool - _terminate_event: Terminated session pool.
2025-10-26 19:25:30,026 - DEBUG - ydb.connection - _prepare_call: RpcState(DeleteSession, 685d645a-6c21-4b94-9d9f-8e3844358fbd, ghrun-pqq4nwlsgu.auto.internal:3601): creating call state
2025-10-26 19:25:30,027 - DEBUG - ydb.connection - _log_request: RpcState(DeleteSession, 685d645a-6c21-4b94-9d9f-8e3844358fbd, ghrun-pqq4nwlsgu.auto.internal:3601): request = { session_id: "ydb://session/3?node_id=50000&id=MmI3NmEwMjgtODgyMTFjMTQtNTk1OTVhMjctMmZiYWFmNjU=" operation_params { operation_timeout { seconds: 3 } cancel_after { seconds: 3 } } }
2025-10-26 19:25:30,030 - DEBUG - ydb.table.SessionPool - _destroy: Sent delete on session <ydb.table.Session object at 0x6040003ae6b0>
2025-10-26 19:25:30,031 - DEBUG - ydb.table.SessionPool - stop: Destroyed active sessions
2025-10-26 19:25:30,031 - INFO - ydb.connection - close: Closing channel for endpoint localhost:26286
2025-10-26 19:25:30,036 - DEBUG - ydb.connection - _on_response_callback: RpcState(DeleteSession, 685d645a-6c21-4b94-9d9f-8e3844358fbd, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback started
2025-10-26 19:25:30,037 - DEBUG - ydb.connection - _log_response: RpcState(DeleteSession, 685d645a-6c21-4b94-9d9f-8e3844358fbd, ghrun-pqq4nwlsgu.auto.internal:3601): response = { operation { ready: true status: SUCCESS } }
2025-10-26 19:25:30,038 - DEBUG - ydb.connection - _on_response_callback: RpcState(DeleteSession, 685d645a-6c21-4b94-9d9f-8e3844358fbd, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback success
2025-10-26 19:25:30,057 - INFO - ydb.connection - close: Closing channel for endpoint ghrun-pqq4nwlsgu.auto.internal:3601
2025-10-26 19:25:30,089 - INFO - ydb.pool.Discovery - run: Successfully terminated discovery process
2025-10-26 19:25:30,091 - DEBUG - ydb.table.SessionPool - stop: Requested session pool stop.
2025-10-26 19:25:30,091 - DEBUG - ydb.table.SessionPool - stop: Session pool is under stop, cancelling all in flight waiters.
2025-10-26 19:25:30,091 - DEBUG - ydb.table.SessionPool - _terminate_event: Terminated session pool.
2025-10-26 19:25:30,092 - DEBUG - ydb.table.SessionPool - stop: Destroying sessions in active queue
2025-10-26 19:25:30,094 - DEBUG - ydb.table.SessionPool - _destroy: Requested session destroy: <ydb.table.Session object at 0x604000b15ff0>, reason: session-pool-terminated
2025-10-26 19:25:30,094 - DEBUG - ydb.table.SessionPool - _destroy: Session <ydb.table.Session object at 0x604000b15ff0> is no longer active. Current active count 0.
2025-10-26 19:25:30,095 - DEBUG - ydb.connection - _prepare_call: RpcState(DeleteSession, 8779889e-0ecf-44e8-9db2-e7c92a982ac2, ghrun-pqq4nwlsgu.auto.internal:3601): creating call state
2025-10-26 19:25:30,096 - DEBUG - ydb.connection - _log_request: RpcState(DeleteSession, 8779889e-0ecf-44e8-9db2-e7c92a982ac2, ghrun-pqq4nwlsgu.auto.internal:3601): request = { session_id: "ydb://session/3?node_id=50000&id=NjU1MjY2N2EtZDE2OGJkYzAtNDRjOGFkOWYtMzVjOWUwZWY=" operation_params { operation_timeout { seconds: 3 } cancel_after { seconds: 3 } } }
2025-10-26 19:25:30,104 - DEBUG - ydb.connection - _on_response_callback: RpcState(DeleteSession, 8779889e-0ecf-44e8-9db2-e7c92a982ac2, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback started
2025-10-26 19:25:30,105 - DEBUG - ydb.connection - _log_response: RpcState(DeleteSession, 8779889e-0ecf-44e8-9db2-e7c92a982ac2, ghrun-pqq4nwlsgu.auto.internal:3601): response = { operation { ready: true status: SUCCESS } }
2025-10-26 19:25:30,106 - DEBUG - ydb.connection - _on_response_callback: RpcState(DeleteSession, 8779889e-0ecf-44e8-9db2-e7c92a982ac2, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback success
2025-10-26 19:25:30,106 - DEBUG - ydb.table.SessionPool - _destroy: Sent delete on session <ydb.table.Session object at 0x604000b15ff0>
2025-10-26 19:25:30,107 - DEBUG - ydb.table.SessionPool - stop: Destroyed active sessions
2025-10-26 19:25:30,107 - INFO - ydb.connection - close: Closing channel for endpoint localhost:26286
2025-10-26 19:25:30,109 - INFO - ydb.connection - close: Closing channel for endpoint ghrun-pqq4nwlsgu.auto.internal:3601
2025-10-26 19:25:30,109 - INFO - ydb.pool.Discovery - run: Successfully terminated discovery process
2025-10-26 19:25:30,113 - DEBUG - ydb.table.SessionPool - stop: Requested session pool stop.
2025-10-26 19:25:30,114 - DEBUG - ydb.table.SessionPool - stop: Session pool is under stop, cancelling all in flight waiters.
2025-10-26 19:25:30,115 - DEBUG - ydb.table.SessionPool - stop: Destroying sessions in active queue
2025-10-26 19:25:30,115 - DEBUG - ydb.table.SessionPool - _destroy: Requested session destroy: <ydb.table.Session object at 0x604001a893f0>, reason: session-pool-terminated
2025-10-26 19:25:30,116 - DEBUG - ydb.table.SessionPool - _destroy: Session <ydb.table.Session object at 0x604001a893f0> is no longer active. Current active count 0.
2025-10-26 19:25:30,117 - DEBUG - ydb.connection - _prepare_call: RpcState(DeleteSession, d798f74b-4d58-4f4f-84c6-a5dda69f8833, ghrun-pqq4nwlsgu.auto.internal:3601): creating call state
2025-10-26 19:25:30,117 - DEBUG - ydb.connection - _log_request: RpcState(DeleteSession, d798f74b-4d58-4f4f-84c6-a5dda69f8833, ghrun-pqq4nwlsgu.auto.internal:3601): request = { session_id: "ydb://session/3?node_id=50000&id=N2Q5ZmQ2M2QtZDAyYzNjN2EtYWYwMWJkNjctNDUxYWU1MGI=" operation_params { operation_timeout { seconds: 3 } cancel_after { seconds: 3 } } }
2025-10-26 19:25:30,114 - DEBUG - ydb.table.SessionPool - _terminate_event: Terminated session pool.
2025-10-26 19:25:30,121 - DEBUG - ydb.table.SessionPool - _destroy: Sent delete on session <ydb.table.Session object at 0x604001a893f0>
2025-10-26 19:25:30,121 - DEBUG - ydb.table.SessionPool - stop: Destroyed active sessions
2025-10-26 19:25:30,122 - INFO - ydb.connection - close: Closing channel for endpoint localhost:26286
2025-10-26 19:25:30,124 - DEBUG - ydb.connection - _on_response_callback: RpcState(DeleteSession, d798f74b-4d58-4f4f-84c6-a5dda69f8833, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback started
2025-10-26 19:25:30,125 - DEBUG - ydb.connection - _log_response: RpcState(DeleteSession, d798f74b-4d58-4f4f-84c6-a5dda69f8833, ghrun-pqq4nwlsgu.auto.internal:3601): response = { operation { ready: true status: SUCCESS } }
2025-10-26 19:25:30,125 - DEBUG - ydb.connection - _on_response_callback: RpcState(DeleteSession, d798f74b-4d58-4f4f-84c6-a5dda69f8833, ghrun-pqq4nwlsgu.auto.internal:3601): on response callback success
2025-10-26 19:25:30,127 - INFO - ydb.connection - close: Closing channel for endpoint ghrun-pqq4nwlsgu.auto.internal:3601
2025-10-26 19:25:30,129 - INFO - ydb.pool.Discovery - run: Successfully terminated discovery process
2025-10-26 19:25:30,131 - DEBUG - ydb.tests.library.harness.ydb_fixtures - ydb_database_ctx: destroy database /Root/test_auditlog.py: remove path and dismantle internals
2025-10-26 19:25:30,131 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - remove_database: /Root/test_auditlog.py
2025-10-26 19:25:30,131 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - _remove_database_send_op: /Root/test_auditlog.py: send console operation, token None
2025-10-26 19:25:30,144 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - _remove_database_send_op: /Root/test_auditlog.py: response from console: RemoveTenantResponse {
  Response {
    operation {
      id: "ydb://cmsrequest/5?tenant=/Root/test_auditlog.py&cmstid=72057594037936131&txid=1761506730137495&action=2"
    }
  }
}
Status {
  Code: STATUS_CODE_UNSPECIFIED
}

2025-10-26 19:25:30,145 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - _remove_database_wait_op: /Root/test_auditlog.py: wait console operation done
2025-10-26 19:25:30,654 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - _remove_database_wait_op: /Root/test_auditlog.py: console operation done
2025-10-26 19:25:30,654 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - _remove_database_wait_tenant_gone: /Root/test_auditlog.py: wait tenant gone
2025-10-26 19:25:30,663 - DEBUG - ydb.tests.library.harness.kikimr_cluster_interface - _remove_database_wait_tenant_gone: /Root/test_auditlog.py: tenant gone
2025-10-26 19:25:30,664 - DEBUG - ydb.tests.library.harness.ydb_fixtures - ydb_database_ctx: destroy database /Root/test_auditlog.py: stop nodes
2025-10-26 19:25:33,666 - INFO - ydb.tests.library.harness.kikimr_runner - stop: Stopped node localhost:3601/1
2025-10-26 19:25:33,666 - DEBUG - ydb.tests.library.harness.ydb_fixtures - ydb_database_ctx: destroy database /Root/test_auditlog.py: database down
2025-10-26 19:25:33,667 - INFO - ydb.tests.library.harness.ydb_fixtures - ydb_cluster: destroy ydb_cluster for __tests__.test_auditlog
2025-10-26 19:25:40,672 - INFO - ydb.tests.library.harness.kikimr_runner - stop: Stopped node localhost:26286/1
2025-10-26 19:25:40,674 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/3742
2025-10-26 19:25:40,674 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/3677
2025-10-26 19:25:40,675 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/29006
2025-10-26 19:25:40,675 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/3601
2025-10-26 19:25:40,675 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/21677
2025-10-26 19:25:40,676 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/28042
2025-10-26 19:25:40,676 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/26286
2025-10-26 19:25:40,677 - DEBUG - library.python.filelock - release: Ensuring filelock released: /home/runner/.ya/build/port_sync_dir/5425
