ydb-python-sdk icon indicating copy to clipboard operation
ydb-python-sdk copied to clipboard

Published 20 hours ago • verified publisher icon ydb-platform

bug: Sometimes python SDK does not connect to cluster

Open SloNN opened this issue 6 months ago • 0 comments

Bug Report

YDB Python SDK version:

3.14

Python SDK (dbapi) sometimes does not connect to running cluster. Logs are below

ydbsuperset.myt.yp-c.yandex.net
*** Found local files:
***   * /home/slonnn/airflow/logs/dag_id=ydb_operator_dag/run_id=manual__2024-08-19T13:32:57.212599+00:00/task_id=get_all_pets/attempt=1.log
[2024-08-19, 13:33:20 UTC] {local_task_job_runner.py:123} ▶ Pre task execution logs
[2024-08-19, 13:33:20 UTC] {sql.py:282} INFO - Executing: SELECT * FROM pet;
[2024-08-19, 13:33:20 UTC] {base.py:84} INFO - Retrieving connection '***_ydb_connection'
[2024-08-19, 13:33:20 UTC] {base.py:84} INFO - Retrieving connection '***_ydb_connection'
[2024-08-19, 13:33:20 UTC] {credentials.py:58} INFO - using login as credentials
[2024-08-19, 13:33:20 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:20 UTC] {resolver.py:176} DEBUG - Preparing initial endpoint to resolve endpoints
[2024-08-19, 13:33:20 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:20 UTC] {resolver.py:186} DEBUG - Resolving endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***
[2024-08-19, 13:33:20 UTC] {credentials.py:111} DEBUG - Start refresh token from metadata
[2024-08-19, 13:33:20 UTC] {credentials.py:113} INFO - Cached token reached refresh_in deadline, current time 1724074400.9028711, deadline 0
[2024-08-19, 13:33:20 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:20 UTC] {connection.py:375} DEBUG - RpcState(Login, 969ed74e-7a52-4448-a98c-c09ce00112c4, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): creating call state
[2024-08-19, 13:33:20 UTC] {connection.py:62} DEBUG - RpcState(Login, 969ed74e-7a52-4448-a98c-c09ce00112c4, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): request = { operation_params { operation_timeout { seconds: 10 } cancel_after { seconds: 10 } } user: "***" password: "***" }
[2024-08-19, 13:33:20 UTC] {connection.py:51} DEBUG - RpcState(Login, 969ed74e-7a52-4448-a98c-c09ce00112c4, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Auth.LoginResult] { token: "eyJhbGciOiJQUzI1NiIsImtpZCI6IjIzIn0.eyJhdWQiOiJcL29sYXAtdGVzdGluZy12bGEtY29tbW9uMiIsImV4cCI6MTcyNDExNzU3MSwiaWF0IjoxNzI0MDc0MzcxLCJzdWIiOiJ0ZXN0In0.nJtjpKb1GvIWg1l5yhP5h2OmtsHpKDOOei1bfzx2OG2hnwtALUmz3-HYLQ1tIR_EEh00K-DtwUeCUlaMRy9U9_RuyRKlvX6zs_RMekTNGOkno25pa3nuqlV1G7cDcxSqrF1OqLvJvHNjCh-rVeX_73s8Pmls0yRPH9j7RGsX_j1A9ZwlE3quga257cN6TWHBZX5gZW15BM1JOwjyX2RdXDJuBbKIPOFuyRO4RF8azD0CsXtu7-m46DZCeo9xCT8YWWpSH6tUNtaJnoa3-wq1-RWChI1NVCKU92_ThtT7Tynn4qRI7262r3pic0JHESq7llSBeBF1I983E6YZcEUoug" } } } }
[2024-08-19, 13:33:20 UTC] {connection.py:498} INFO - Closing channel for endpoint c0fbrdjnem92d2p2q5jn.cluster.***ing.ydb.yandex.net:2135
[2024-08-19, 13:33:21 UTC] {credentials.py:137} INFO - Token refresh successful. current_time 1724074400.9028711, refresh_in 1724074851.1107666
[2024-08-19, 13:33:21 UTC] {connection.py:375} DEBUG - RpcState(ListEndpoints, 81b41b20-81dd-4b5e-b5bc-da7404f2df31, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): creating call state
[2024-08-19, 13:33:21 UTC] {connection.py:62} DEBUG - RpcState(ListEndpoints, 81b41b20-81dd-4b5e-b5bc-da7404f2df31, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): request = { database: "/olap-***ing-vla-common2/kikimr/apkobzev/***" }
[2024-08-19, 13:33:21 UTC] {connection.py:51} DEBUG - RpcState(ListEndpoints, 81b41b20-81dd-4b5e-b5bc-da7404f2df31, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Discovery.ListEndpointsResult] { endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50002 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50004 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50015 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50013 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50016 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50009 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50006 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50001 } self_location: "vla" } } } }
[2024-08-19, 13:33:21 UTC] {resolver.py:156} DEBUG - Resolved endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***: DiscoveryResult <self_location: vla, endpoints [<Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>]>
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {sql.py:509} INFO - Running statement: SELECT * FROM pet;, parameters: None
[2024-08-19, 13:33:21 UTC] {cursor.py:120} INFO - execute sql: SELECT * FROM pet;, params: None
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:260} DEBUG - Active session queue is empty, subscribe waiter for a session
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:262} DEBUG - Subscribe waiter <Future at 0x7f27ba3cb1c0 state=pending>
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:282} DEBUG - Session pool is not large enough (active_count < size: 0 < 5). will create a new session.
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:111} DEBUG - Created session <ydb.table.Session object at 0x7f27ba3cb1f0>
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:238} DEBUG - Preparing session <ydb.table.Session object at 0x7f27ba3cb1f0>
[2024-08-19, 13:33:21 UTC] {connection.py:375} DEBUG - RpcState(CreateSession, b75d239a-6d6c-4e88-a6bd-256d054856e8, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): creating call state
[2024-08-19, 13:33:21 UTC] {connection.py:62} DEBUG - RpcState(CreateSession, b75d239a-6d6c-4e88-a6bd-256d054856e8, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): request = { operation_params { operation_timeout { seconds: 3 } cancel_after { seconds: 3 } } }
[2024-08-19, 13:33:21 UTC] {connection.py:102} DEBUG - RpcState(CreateSession, b75d239a-6d6c-4e88-a6bd-256d054856e8, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): on response callback started
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:51} DEBUG - RpcState(CreateSession, b75d239a-6d6c-4e88-a6bd-256d054856e8, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Table.CreateSessionResult] { session_id: "ydb://session/3?node_id=50016&id=YWI0MjExODQtNjliNzE4YjAtMTAzNWZhOTItMTliMWVkZWM=" } } } }
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:177} DEBUG - Put on session <ydb.table.Session object at 0x7f27ba3cb1f0>
[2024-08-19, 13:33:21 UTC] {_sp_impl.py:195} DEBUG - Replying to waiter with a session <ydb.table.Session object at 0x7f27ba3cb1f0>
[2024-08-19, 13:33:21 UTC] {connection.py:375} DEBUG - RpcState(ExecuteDataQuery, 66c85825-b124-466c-aefa-2beccec33d6f, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): creating call state
[2024-08-19, 13:33:21 UTC] {connection.py:107} DEBUG - RpcState(CreateSession, b75d239a-6d6c-4e88-a6bd-256d054856e8, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): on response callback success
[2024-08-19, 13:33:21 UTC] {connection.py:62} DEBUG - RpcState(ExecuteDataQuery, 66c85825-b124-466c-aefa-2beccec33d6f, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): request = { session_id: "ydb://session/3?node_id=50016&id=YWI0MjExODQtNjliNzE4YjAtMTAzNWZhOTItMTliMWVkZWM=" tx_control { begin_tx { serializable_read_write { } } commit_tx: true } query { yql_text: "SELECT * FROM pet;" } operation_params { operation_timeout { seconds: 600 } cancel_after { seconds: 600 } } }
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:33:21 UTC] {connection.py:498} INFO - Closing channel for endpoint c0fbrdjnem92d2p2q5jn.cluster.***ing.ydb.yandex.net:2135
[2024-08-19, 13:35:17 UTC] {resolver.py:176} DEBUG - Preparing initial endpoint to resolve endpoints
[2024-08-19, 13:35:17 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:35:17 UTC] {resolver.py:186} DEBUG - Resolving endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***
[2024-08-19, 13:35:17 UTC] {connection.py:375} DEBUG - RpcState(ListEndpoints, 7dcdae24-c47c-4d3c-9490-b41130d075b9, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): creating call state
[2024-08-19, 13:35:17 UTC] {connection.py:62} DEBUG - RpcState(ListEndpoints, 7dcdae24-c47c-4d3c-9490-b41130d075b9, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): request = { database: "/olap-***ing-vla-common2/kikimr/apkobzev/***" }
[2024-08-19, 13:35:17 UTC] {connection.py:51} DEBUG - RpcState(ListEndpoints, 7dcdae24-c47c-4d3c-9490-b41130d075b9, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Discovery.ListEndpointsResult] { endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50004 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50001 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50016 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50006 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50015 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50002 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50009 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50013 } self_location: "vla" } } } }
[2024-08-19, 13:35:17 UTC] {resolver.py:156} DEBUG - Resolved endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***: DiscoveryResult <self_location: vla, endpoints [<Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>]>
[2024-08-19, 13:35:17 UTC] {connection.py:498} INFO - Closing channel for endpoint c0fbrdjnem92d2p2q5jn.cluster.***ing.ydb.yandex.net:2135
[2024-08-19, 13:36:34 UTC] {resolver.py:176} DEBUG - Preparing initial endpoint to resolve endpoints
[2024-08-19, 13:36:34 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:36:34 UTC] {resolver.py:186} DEBUG - Resolving endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***
[2024-08-19, 13:36:34 UTC] {connection.py:375} DEBUG - RpcState(ListEndpoints, bf522a27-144a-4074-8a4a-cdc0a5c6edfb, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): creating call state
[2024-08-19, 13:36:34 UTC] {connection.py:62} DEBUG - RpcState(ListEndpoints, bf522a27-144a-4074-8a4a-cdc0a5c6edfb, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): request = { database: "/olap-***ing-vla-common2/kikimr/apkobzev/***" }
[2024-08-19, 13:36:34 UTC] {connection.py:51} DEBUG - RpcState(ListEndpoints, bf522a27-144a-4074-8a4a-cdc0a5c6edfb, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Discovery.ListEndpointsResult] { endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50004 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50015 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50002 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50013 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50001 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50009 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50006 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50016 } self_location: "vla" } } } }
[2024-08-19, 13:36:34 UTC] {resolver.py:156} DEBUG - Resolved endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***: DiscoveryResult <self_location: vla, endpoints [<Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>]>
[2024-08-19, 13:36:34 UTC] {connection.py:498} INFO - Closing channel for endpoint c0fbrdjnem92d2p2q5jn.cluster.***ing.ydb.yandex.net:2135
[2024-08-19, 13:38:03 UTC] {resolver.py:176} DEBUG - Preparing initial endpoint to resolve endpoints
[2024-08-19, 13:38:03 UTC] {connection.py:295} DEBUG - 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')]
[2024-08-19, 13:38:03 UTC] {resolver.py:186} DEBUG - Resolving endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***
[2024-08-19, 13:38:03 UTC] {connection.py:375} DEBUG - RpcState(ListEndpoints, 80217630-2263-47b2-b543-07116283bccc, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): creating call state
[2024-08-19, 13:38:03 UTC] {connection.py:62} DEBUG - RpcState(ListEndpoints, 80217630-2263-47b2-b543-07116283bccc, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): request = { database: "/olap-***ing-vla-common2/kikimr/apkobzev/***" }
[2024-08-19, 13:38:03 UTC] {connection.py:51} DEBUG - RpcState(ListEndpoints, 80217630-2263-47b2-b543-07116283bccc, c0fbrdjnem92d2p2q5jn.cluster.testing.ydb.yandex.net:2135): response = { operation { ready: true status: SUCCESS result { [type.googleapis.com/Ydb.Discovery.ListEndpointsResult] { endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50016 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50009 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50015 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50006 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50001 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50002 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50013 } endpoints { address: "d-c0f2632s1i7mamst8job-ydb-***ing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-***ing-vla.k8s-c.yandex.net" port: 2135 location: "vla" node_id: 50004 } self_location: "vla" } } } }
[2024-08-19, 13:38:03 UTC] {resolver.py:156} DEBUG - Resolved endpoints for database /olap-***ing-vla-common2/kikimr/apkobzev/***: DiscoveryResult <self_location: vla, endpoints [<Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-6.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-5.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-3.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-0.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-4.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-1.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>, <Endpoint d-c0f2632s1i7mamst8job-ydb-testing-vla-0-7.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135, location vla, ssl: False>]>
[2024-08-19, 13:38:03 UTC] {connection.py:498} INFO - Closing channel for endpoint c0fbrdjnem92d2p2q5jn.cluster.***ing.ydb.yandex.net:2135
[2024-08-19, 13:38:21 UTC] {connection.py:51} DEBUG - RpcState(ExecuteDataQuery, 66c85825-b124-466c-aefa-2beccec33d6f, d-c0f2632s1i7mamst8job-ydb-testing-vla-0-2.ydb-cluster-c0fbrdjnem92d2p2q5jn.ydb-testing-vla.k8s-c.yandex.net:2135): response = { operation { ready: true status: TIMEOUT result { [type.googleapis.com/Ydb.Table.ExecuteQueryResult] { tx_meta { id: "01j5ndeam3b2bsjwpyrxyt6vtb" } } } } }
[2024-08-19, 13:38:21 UTC] {_sp_impl.py:177} DEBUG - Put on session <ydb.table.Session object at 0x7f27ba3cb1f0>
[2024-08-19, 13:38:21 UTC] {taskinstance.py:3301} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/_vendor/dbapi/cursor.py", line 44, in wrapper
    return func(*args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/_vendor/dbapi/cursor.py", line 181, in _execute_dml
    return self._retry_operation_in_pool(self._execute_in_session, self.tx_mode, prepared_query, parameters)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/_vendor/dbapi/cursor.py", line 229, in _retry_operation_in_pool
    return self.session_pool.retry_operation_sync(callee, None, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/table.py", line 2367, in retry_operation_sync
    return retry_operation_sync(wrapped_callee, retry_settings)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/retries.py", line 132, in retry_operation_sync
    for next_opt in opt_generator:
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/retries.py", line 93, in retry_operation_impl
    result = YdbRetryOperationFinalResult(callee(*args, **kwargs))
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/table.py", line 2365, in wrapped_callee
    return callee(session, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/_vendor/dbapi/cursor.py", line 220, in _execute_in_session
    return session.transaction(tx_mode).execute(prepared_query, parameters, commit_tx=True)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/table.py", line 2104, in execute
    return self._driver(
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/tracing.py", line 70, in wrapper
    return f(self, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/pool.py", line 443, in __call__
    res = connection(
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/connection.py", line 465, in __call__
    return response if wrap_result is None else wrap_result(rpc_state, response, *wrap_args)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/_session_impl.py", line 20, in decorator
    return func(rpc_state, response_pb, session_state, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/_tx_ctx_impl.py", line 9, in decorator
    return func(rpc_state, response_pb, session_state, tx_state, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/_tx_ctx_impl.py", line 22, in decorator
    return func(rpc_state, response_pb, session_state, tx_state, query, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/_tx_ctx_impl.py", line 165, in wrap_result_and_tx_id
    issues._process_response(response_pb.operation)
  File "/home/slonnn/.local/lib/python3.10/site-packages/ydb/issues.py", line 226, in _process_response
    raise exc_obj(_format_response(response_proto), response_proto.issues)
ydb.issues.Timeout:  (server_code: 400090)
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/models/taskinstance.py", line 767, in _execute_task
    result = _execute_callable(context=context, **execute_callable_kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/models/taskinstance.py", line 733, in _execute_callable
    return ExecutionCallableRunner(
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/utils/operator_helpers.py", line 252, in run
    return self.func(*args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/models/baseoperator.py", line 406, in wrapper
    return func(self, *args, **kwargs)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/common/sql/operators/sql.py", line 288, in execute
    output = hook.run(
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/common/sql/hooks/sql.py", line 456, in run
    self._run_command(cur, sql_statement, parameters)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/common/sql/hooks/sql.py", line 514, in _run_command
    cur.execute(sql_statement)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/ydb.py", line 50, in execute
    return self.delegatee.execute(q, parameters)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/_vendor/dbapi/cursor.py", line 124, in execute
    chunks = self._execute_dml(query, parameters)
  File "/home/slonnn/.local/lib/python3.10/site-packages/airflow/providers/ydb/hooks/_vendor/dbapi/cursor.py", line 64, in wrapper
    raise OperationalError(e.message, original_error=e) from e
airflow.providers.ydb.hooks._vendor.dbapi.errors.OperationalError:  (server_code: 400090)
[2024-08-19, 13:38:21 UTC] {logging_mixin.py:190} INFO - Task instance in failure state
[2024-08-19, 13:38:21 UTC] {logging_mixin.py:190} INFO - Task start:2024-08-19 13:33:20.156400+00:00 end:2024-08-19 13:38:21.193348+00:00 duration:301.036948
[2024-08-19, 13:38:21 UTC] {logging_mixin.py:190} INFO - Task:<Task(YDBExecuteQueryOperator): get_all_pets> dag:<DAG: ydb_operator_dag> dagrun:<DagRun ydb_operator_dag @ 2024-08-19 13:32:57.212599+00:00: manual__2024-08-19T13:32:57.212599+00:00, state:running, queued_at: 2024-08-19 13:32:57.228984+00:00. externally triggered: True>
[2024-08-19, 13:38:21 UTC] {logging_mixin.py:190} INFO - Failure caused by  (server_code: 400090)
[2024-08-19, 13:38:21 UTC] {taskinstance.py:1225} INFO - Marking task as FAILED. dag_id=ydb_operator_dag, task_id=get_all_pets, run_id=manual__2024-08-19T13:32:57.212599+00:00, execution_date=20240819T133257, start_date=20240819T133320, end_date=20240819T133821
[2024-08-19, 13:38:21 UTC] {taskinstance.py:340} ▶ Post task execution logs

SloNN avatar Aug 19 '24 14:08 SloNN