2025-10-16T16:37:45.693719Z node 9 :METADATA_PROVIDER WARN: log.cpp:841: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[9:7561859717149655481:2154];send_to=[0:7307199536658146131:7762515];
2025-10-16T16:37:45.693753Z node 9 :METADATA_PROVIDER ERROR: log.cpp:841: fline=accessor_snapshot_base.cpp:71;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-10-16T16:37:45.695053Z node 10 :METADATA_PROVIDER WARN: log.cpp:841: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[10:7561859720283795172:2150];send_to=[0:7307199536658146131:7762515];
2025-10-16T16:37:45.695087Z node 10 :METADATA_PROVIDER ERROR: log.cpp:841: fline=accessor_snapshot_base.cpp:71;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/7v33/001f95/r3tmp/tmpEWFTGw/pdisk_1.dat
2025-10-16T16:37:45.696219Z node 9 :PQ_READ_PROXY DEBUG: caching_service.cpp:44: Direct read cache: : Created
2025-10-16T16:37:45.696498Z node 9 :KQP_PROXY WARN: kqp_finalize_script_service.cpp:135: [ScriptExecutions] [TKqpFinalizeScriptService] Failed to check script execution tables existence, scheme status: LookupError, path: Root/.metadata/script_executions
2025-10-16T16:37:45.697540Z node 10 :PQ_READ_PROXY DEBUG: caching_service.cpp:44: Direct read cache: : Created
2025-10-16T16:37:45.697584Z node 10 :KQP_PROXY WARN: kqp_finalize_script_service.cpp:135: [ScriptExecutions] [TKqpFinalizeScriptService] Failed to check script execution tables existence, scheme status: LookupError, path: Root/.metadata/script_executions
2025-10-16T16:37:45.710694Z node 9 :IMPORT WARN: schemeshard_import.cpp:307: Table profiles were not loaded
2025-10-16T16:37:45.714572Z node 9 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(10, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-16T16:37:45.714590Z node 9 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(10, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-16T16:37:45.715678Z node 9 :HIVE WARN: hive_impl.cpp:811: HIVE#72057594037968897 Handle TEvInterconnect::TEvNodeConnected, NodeId 10 Cookie 10
2025-10-16T16:37:45.715886Z node 9 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(10, (0,0,0,0)) VolatileState: Connecting -> Connected
TServer::EnableGrpc on GrpcPort 3890, node 9
2025-10-16T16:37:45.721977Z node 9 :NET_CLASSIFIER WARN: net_classifier.cpp:190: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/7v33/001f95/r3tmp/yandexjZHogc.tmp
2025-10-16T16:37:45.721986Z node 9 :NET_CLASSIFIER WARN: net_classifier.cpp:196: will try to initialize from file: /home/runner/.ya/build/build_root/7v33/001f95/r3tmp/yandexjZHogc.tmp
2025-10-16T16:37:45.722042Z node 9 :NET_CLASSIFIER WARN: net_classifier.cpp:202: successfully initialized from file: /home/runner/.ya/build/build_root/7v33/001f95/r3tmp/yandexjZHogc.tmp
2025-10-16T16:37:45.722090Z node 9 :NET_CLASSIFIER ERROR: net_classifier.cpp:228: got bad distributable configuration
2025-10-16T16:37:45.724541Z INFO: TTestServer started on Port 10243 GrpcPort 3890
TClient is connected to server localhost:10243
PQClient connected to localhost:3890
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
    ChildrenExist: false
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      Pl...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-10-16T16:37:45.737870Z node 9 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976710657:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_alter_subdomain.cpp:311)
waiting...
waiting...
2025-10-16T16:37:45.752225Z node 9 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710659:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:684)
waiting...
waiting...
waiting...
2025-10-16T16:37:45.794929Z node 9 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(9, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-16T16:37:45.794955Z node 9 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(9, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-16T16:37:45.796552Z node 9 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(9, (0,0,0,0)) VolatileState: Connecting -> Connected
2025-10-16T16:37:45.857304Z node 10 :KQP_PROXY WARN: kqp_finalize_script_service.cpp:135: [ScriptExecutions] [TKqpFinalizeScriptService] Failed to check script execution tables existence, scheme status: PathErrorUnknown, path: Root/.metadata/script_executions
2025-10-16T16:37:45.859604Z node 9 :KQP_PROXY WARN: kqp_finalize_script_service.cpp:135: [ScriptExecutions] [TKqpFinalizeScriptService] Failed to check script execution tables existence, scheme status: PathErrorUnknown, path: Root/.metadata/script_executions
2025-10-16T16:37:46.027333Z node 9 :KQP_WORKLOAD_SERVICE WARN: scheme_actors.cpp:225: [WorkloadService] [TPoolFetcherActor] ActorId: [9:7561859721444623724:2326], DatabaseId: /Root, PoolId: default, Failed to fetch pool info, NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.027361Z node 9 :KQP_WORKLOAD_SERVICE WARN: kqp_workload_service.cpp:263: [WorkloadService] [Service] Failed to fetch pool default, DatabaseId: /Root, status: NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.027369Z node 9 :KQP_WORKLOAD_SERVICE WARN: scheme_actors.cpp:225: [WorkloadService] [TPoolFetcherActor] ActorId: [9:7561859721444623750:2329], DatabaseId: /Root, PoolId: default, Failed to fetch pool info, NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.027401Z node 9 :KQP_WORKLOAD_SERVICE WARN: scheme_actors.cpp:225: [WorkloadService] [TPoolFetcherActor] ActorId: [9:7561859721444623752:2330], DatabaseId: /Root, PoolId: default, Failed to fetch pool info, NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.027412Z node 9 :KQP_WORKLOAD_SERVICE WARN: kqp_workload_service.cpp:263: [WorkloadService] [Service] Failed to fetch pool default, DatabaseId: /Root, status: NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.028032Z node 9 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateResourcePool, opId: 281474976710662:3, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_resource_pool.cpp:179)
2025-10-16T16:37:46.028335Z node 9 :KQP_WORKLOAD_SERVICE WARN: scheme_actors.cpp:225: [WorkloadService] [TPoolFetcherActor] ActorId: [9:7561859721444623785:2333], DatabaseId: /Root, PoolId: default, Failed to fetch pool info, NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.028347Z node 9 :KQP_WORKLOAD_SERVICE WARN: kqp_workload_service.cpp:263: [WorkloadService] [Service] Failed to fetch pool default, DatabaseId: /Root, status: NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.028377Z node 9 :KQP_WORKLOAD_SERVICE WARN: scheme_actors.cpp:225: [WorkloadService] [TPoolFetcherActor] ActorId: [9:7561859721444623787:2334], DatabaseId: /Root, PoolId: default, Failed to fetch pool info, NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.028384Z node 9 :KQP_WORKLOAD_SERVICE WARN: kqp_workload_service.cpp:263: [WorkloadService] [Service] Failed to fetch pool default, DatabaseId: /Root, status: NOT_FOUND, issues: { <main>: Error: Resource pool default not found or you don't have access permissions }
2025-10-16T16:37:46.031989Z node 9 :KQP_WORKLOAD_SERVICE WARN: helpers.h:73: [WorkloadService] [TPoolCreatorActor] ActorId: [9:7561859721444623753:2331], DatabaseId: /Root, PoolId: default, Scheduled retry for error: { <main>: Error: Transaction 281474976710662 completed, doublechecking }
2025-10-16T16:37:46.034221Z node 9 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710663:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:684)
2025-10-16T16:37:46.047564Z node 9 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710664:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:684)
2025-10-16T16:37:46.054723Z node 10 :KQP_COMPILE_ACTOR ERROR: kqp_compile_actor.cpp:570: Compilation failed, self: [10:7561859724578762795:2306], status: SCHEME_ERROR, issues: <main>: Error: Type annotation, code: 1030
    <main>:5:17: Error: At function: KiReadTable!
        <main>:5:17: Error: Cannot find table 'db.[/Root/PQ/Config/V2/Versions]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions., code: 2003
2025-10-16T16:37:46.054793Z node 10 :KQP_SESSION WARN: kqp_session_actor.cpp:2408: SessionId: ydb://session/3?node_id=10&id=ODBkMzY3MWUtOGE3NTY2N2UtYmM0OWY0OTItZWMxM2Y0Nzc=, ActorId: [10:7561859724578762769:2299], ActorState: ExecuteState, TraceId: 01k7py4xy19s3cqpdsysc2f66m, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-10-16T16:37:46.054948Z node 10 :PERSQUEUE_CLUSTER_TRACKER ERROR: cluster_tracker.cpp:167: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 5 column: 17 } message: "At function: KiReadTable!" end_position { row: 5 column: 17 } severity: 1 issues { position { row: 5 column: 17 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Versions]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 5 column: 17 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2025-10-16T16:37:46.067659Z node 9 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710665:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:684)
=== Init DC: UPSERT INTO `/Root/PQ/Config/V2/Cluster` (name, balancer, local, enabled, weight) VALUES ("dc1", "localhost", true, true, 1000), ("dc2", "dc2.logbroker.yandex.net", false, true, 1000);
2025-10-16T16:37:46.089079Z node 9 :TX_PROXY ERROR: schemereq.cpp:590: Actor# [9:7561859721444624224:3038] txid# 281474976710666, issues: { message: "Check failed: path: \'/Root/.metadata/workload_manager/pools/default\', error: path exist, request accepts it (id: [OwnerId: 72057594046644480, LocalPathId: 9], type: EPathTypeResourcePool, state: EPathStateNoChanges), source_location: ydb/core/tx/schemeshard/schemeshard__operation_create_resource_pool.cpp:92" severity: 1 }
2025-10-16T16:37:46.099912Z node 9 :KQP_EXECUTER ERROR: kqp_planner.cpp:123: TxId: 281474976710667. Ctx: { TraceId: 01k7py4xz33jgfr9cnh3k2pf0y, Database: , SessionId: ydb://session/3?node_id=9&id=ODQ0M2U0MjQtZmYyOWJmMDgtZWQ4ZjdhYWMtODI4MTdkZjk=, PoolId: default, DatabaseId: /Root}. Database not set, use /Root
=== CheckClustersList. Subcribe to ClusterTracker from [9:7561859721444624281:3069] 
2025-10-16T16:37:46.695987Z node 9 :TX_CONVEYOR ERROR: log.cpp:841: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-10-16T16:37:46.696998Z node 10 :TX_CONVEYOR ERROR: log.cpp:841: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-10-16T16:37:50.693658Z node 9 :METADATA_PROVIDER ERROR: log.cpp:841: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[9:7561859717149655481:2154];send_to=[0:7307199536658146131:7762515];
2025-10-16T16:37:50.693708Z node 9 :METADATA_PROVIDER ERROR: log.cpp:841: fline=accessor_snapshot_base.cpp:71;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
2025-10-16T16:37:50.695205Z node 10 :METADATA_PROVIDER ERROR: log.cpp:841: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[10:7561859720283795172:2150];send_to=[0:7307199536658146131:7762515];
2025-10-16T16:37:50.695253Z node 10 :METADATA_PROVIDER ERROR: log.cpp:841: fline=accessor_snapshot_base.cpp:71;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
=== CheckClustersList. Ok
2025-10-16T16:37:51.339264Z node 9 :PQ_READ_PROXY DEBUG: grpc_pq_schema.cpp:132: new create topic request
2025-10-16T16:37:51.346275Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2960: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-10-16T16:37:51.346306Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037894][] pipe [9:7561859742919461149:3291] connected; active server actors: 1
2025-10-16T16:37:51.346454Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1517: [72075186224037894][rt3.dc1--acc--topic3] updating configuration. Deleted partitions []. Added partitions [1, 0]
2025-10-16T16:37:51.346510Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2960: [PQ: 72075186224037893] Handle TEvInterconnect::TEvNodeInfo
2025-10-16T16:37:51.346651Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:940: [72075186224037894][rt3.dc1--acc--topic3] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037894
2025-10-16T16:37:51.347206Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2992: [PQ: 72075186224037893] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-10-16T16:37:51.347244Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:138: [72075186224037894][rt3.dc1--acc--topic3] BALANCER INIT DONE for rt3.dc1--acc--topic3: (0, 72075186224037893) (1, 72075186224037892) 
2025-10-16T16:37:51.347260Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:787: [PQ: 72075186224037893] no config, start with empty partitions and default config
2025-10-16T16:37:51.347274Z node 10 :PERSQUEUE NOTICE: pq_impl.cpp:911: [PQ: 72075186224037893] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-16T16:37:51.347264Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2992: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-10-16T16:37:51.347285Z node 10 :PERSQUEUE INFO: pq_impl.cpp:612: [PQ: 72075186224037893] doesn't have tx writes info
2025-10-16T16:37:51.347322Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:787: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-10-16T16:37:51.347333Z node 9 :PERSQUEUE NOTICE: pq_impl.cpp:911: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-16T16:37:51.347340Z node 9 :PERSQUEUE INFO: pq_impl.cpp:612: [PQ: 72075186224037892] doesn't have tx writes info
2025-10-16T16:37:51.347365Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037893] server connected, pipe [9:7561859742919461218:2449], now have 1 active actors on pipe
2025-10-16T16:37:51.347375Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037893] server connected, pipe [9:7561859742919461148:3290], now have 1 active actors on pipe
2025-10-16T16:37:51.347444Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:402: [72075186224037894][rt3.dc1--acc--topic3] TEvClientConnected TabletId 72075186224037893, NodeId 10, Generation 1
2025-10-16T16:37:51.347506Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037892] server connected, pipe [9:7561859742919461147:3289], now have 1 active actors on pipe
2025-10-16T16:37:51.347516Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037892] server connected, pipe [9:7561859742919461219:2449], now have 1 active actors on pipe
2025-10-16T16:37:51.347535Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:402: [72075186224037894][rt3.dc1--acc--topic3] TEvClientConnected TabletId 72075186224037892, NodeId 9, Generation 1
2025-10-16T16:37:51.347570Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.347727Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.348334Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.348549Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.350068Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037892] server connected, pipe [9:7561859742919461255:3379], now have 1 active actors on pipe
2025-10-16T16:37:51.350120Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037893] server connected, pipe [9:7561859742919461256:3380], now have 1 active actors on pipe
2025-10-16T16:37:51.350158Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.350216Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.350764Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.350955Z node 9 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--acc--topic3:1:Initializer] Start initializing step TInitConfigStep
2025-10-16T16:37:51.350971Z node 9 :PERSQUEUE DEBUG: partition.cpp:1281: [72075186224037892][Partition][1][StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-16T16:37:51.351023Z node 9 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--acc--topic3:1:Initializer] Start initializing step TInitInternalFieldsStep
2025-10-16T16:37:51.351098Z node 9 :PERSQUEUE INFO: partition_init.cpp:1095: [72075186224037892][Partition][1][StateInit] bootstrapping 1 [9:7561859742919461267:2450]
2025-10-16T16:37:51.351113Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.351324Z node 10 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--acc--topic3:0:Initializer] Start initializing step TInitConfigStep
2025-10-16T16:37:51.351338Z node 10 :PERSQUEUE DEBUG: partition.cpp:1281: [72075186224037893][Partition][0][StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-16T16:37:51.351385Z node 10 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--acc--topic3:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-10-16T16:37:51.351430Z node 10 :PERSQUEUE INFO: partition_init.cpp:1095: [72075186224037893][Partition][0][StateInit] bootstrapping 0 [10:7561859746053599638:2374]
2025-10-16T16:37:51.351814Z node 9 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--acc--topic3:1:Initializer] Start initializing step TInitFieldsStep
2025-10-16T16:37:51.351826Z node 9 :PERSQUEUE DEBUG: partition_init.cpp:61: [rt3.dc1--acc--topic3:1:Initializer] Initializing completed.
2025-10-16T16:37:51.351831Z node 9 :PERSQUEUE INFO: partition.cpp:698: [72075186224037892][Partition][1][StateInit] init complete for topic 'rt3.dc1--acc--topic3' partition 1 generation 1 [9:7561859742919461267:2450]
2025-10-16T16:37:51.351837Z node 9 :PERSQUEUE DEBUG: partition.cpp:712: [72075186224037892][Partition][1][StateInit] SYNC INIT topic rt3.dc1--acc--topic3 partitition 1 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-16T16:37:51.352154Z node 9 :PERSQUEUE DEBUG: partition.cpp:4311: [72075186224037892][Partition][1][StateIdle] Process pending events. Count 1
2025-10-16T16:37:51.352165Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.352185Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.352191Z node 9 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-16T16:37:51.352193Z node 9 :PERSQUEUE DEBUG: partition.cpp:2356: [72075186224037892][Partition][1][StateIdle] Still pending for come commits
2025-10-16T16:37:51.352195Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.352196Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.352197Z node 9 :PERSQUEUE DEBUG: partition.cpp:2356: [72075186224037892][Partition][1][StateIdle] Still pending for come commits
2025-10-16T16:37:51.352202Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:911: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 user first-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-16T16:37:51.352254Z node 10 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--acc--topic3:0:Initializer] Start initializing step TInitFieldsStep
2025-10-16T16:37:51.352265Z node 10 :PERSQUEUE DEBUG: partition_init.cpp:61: [rt3.dc1--acc--topic3:0:Initializer] Initializing completed.
2025-10-16T16:37:51.352269Z node 10 :PERSQUEUE INFO: partition.cpp:698: [72075186224037893][Partition][0][StateInit] init complete for topic 'rt3.dc1--acc--topic3' partition 0 generation 1 [10:7561859746053599638:2374]
2025-10-16T16:37:51.352274Z node 10 :PERSQUEUE DEBUG: partition.cpp:712: [72075186224037893][Partition][0][StateInit] SYNC INIT topic rt3.dc1--acc--topic3 partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-16T16:37:51.352290Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.352310Z node 9 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.352603Z node 10 :PERSQUEUE DEBUG: partition.cpp:4311: [72075186224037893][Partition][0][StateIdle] Process pending events. Count 1
2025-10-16T16:37:51.352615Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.352632Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.352634Z node 10 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037893][Partition][0][StateIdle] Batch completed (1)
2025-10-16T16:37:51.352637Z node 10 :PERSQUEUE DEBUG: partition.cpp:2356: [72075186224037893][Partition][0][StateIdle] Still pending for come commits
2025-10-16T16:37:51.352640Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.352642Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.352643Z node 10 :PERSQUEUE DEBUG: partition.cpp:2356: [72075186224037893][Partition][0][StateIdle] Still pending for come commits
2025-10-16T16:37:51.352649Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:911: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 user first-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-16T16:37:51.352747Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.352777Z node 10 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037893][Partition][0][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.353111Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.353155Z node 9 :PERSQUEUE DEBUG: partition.cpp:1385: [72075186224037892][Partition][1][StateIdle] Handle TEvPQ::TEvTxCommit Step 1760632671399, TxId 281474976710674
2025-10-16T16:37:51.353162Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.353163Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.353187Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.353224Z node 9 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-16T16:37:51.353687Z node 9 :PERSQUEUE DEBUG: partition.cpp:2154: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-16T16:37:51.353743Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-16T16:37:51.353754Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.353756Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.353758Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.353762Z node 9 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.353866Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.353893Z node 10 :PERSQUEUE DEBUG: partition.cpp:1385: [72075186224037893][Partition][0][StateIdle] Handle TEvPQ::TEvTxCommit Step 1760632671399, TxId 281474976710674
2025-10-16T16:37:51.353896Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.353898Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.353927Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.353963Z node 10 :PERSQUEUE DEBUG: read.h:275: [72075186224037893][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-16T16:37:51.354007Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:398: [PQ: 72075186224037892] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 1000 LifetimeSeconds: 86400 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1000 BurstSize: 1000 TotalPartitions: 2 ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } SourceIdMaxCounts: 6000000 } PartitionIds: 1 TopicName: "rt3.dc1--acc--topic3" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "acc" Ident: "acc" Topic: "topic3" DC: "dc1" FormatVersion: 0 Codecs { Ids: 0 Ids: 10041 Codecs: "raw" Codecs: "CUSTOM" } TopicPath: "/Root/PQ/rt3.dc1--acc--topic3" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } AllPartitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "first-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } MonitoringProjectId: ""
2025-10-16T16:37:51.354027Z node 9 :PERSQUEUE NOTICE: pq_impl.cpp:911: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-16T16:37:51.354071Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.354519Z node 10 :PERSQUEUE DEBUG: partition.cpp:2154: [72075186224037893][Partition][0][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-16T16:37:51.354564Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037893][Partition][0][StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-16T16:37:51.354571Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.354572Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.354573Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.354576Z node 10 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037893][Partition][0][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.354673Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:398: [PQ: 72075186224037893] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 1000 LifetimeSeconds: 86400 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1000 BurstSize: 1000 TotalPartitions: 2 ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } SourceIdMaxCounts: 6000000 } PartitionIds: 0 TopicName: "rt3.dc1--acc--topic3" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "acc" Ident: "acc" Topic: "topic3" DC: "dc1" FormatVersion: 0 Codecs { Ids: 0 Ids: 10041 Codecs: "raw" Codecs: "CUSTOM" } TopicPath: "/Root/PQ/rt3.dc1--acc--topic3" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "first-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } MonitoringProjectId: ""
2025-10-16T16:37:51.354691Z node 10 :PERSQUEUE NOTICE: pq_impl.cpp:911: [PQ: 72075186224037893] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-16T16:37:51.354735Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.354776Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.354793Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-16T16:37:51.355273Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.355691Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-16T16:37:51.355711Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:3570: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
{ 2025-10-16T16:37:51.356365Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:1043: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
operation { ready: true status: SUCCESS } }
{  }
2025-10-16T16:37:51.357155Z :DEBUG: [] MessageGroupId [src] SessionId [] Write session: try to update token
2025-10-16T16:37:51.357395Z :INFO: [] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-10-16T16:37:51.357400Z :INFO: [] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:3890
2025-10-16T16:37:51.357704Z :DEBUG: [] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "acc/topic3" message_group_id: "src" }
2025-10-16T16:37:51.357877Z node 9 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-16T16:37:51.357884Z node 9 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 1
2025-10-16T16:37:51.358016Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "acc/topic3" message_group_id: "src" }
2025-10-16T16:37:51.358040Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 1 topic: "acc/topic3" message_group_id: "src" from ipv6:[::1]:50772
2025-10-16T16:37:51.358043Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:50772 proto=v1  topic=acc/topic3 durationSec=0
2025-10-16T16:37:51.358045Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-16T16:37:51.358506Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 1 sessionId:  describe result for acl check
2025-10-16T16:37:51.358529Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-16T16:37:51.358531Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-16T16:37:51.358532Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-16T16:37:51.358535Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) StartKqpSession
2025-10-16T16:37:51.358981Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) Select from the table
2025-10-16T16:37:51.381962Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:67: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) RequestPQRB
2025-10-16T16:37:51.382022Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461396:2460] connected; active server actors: 1
2025-10-16T16:37:51.382051Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:80: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=src
2025-10-16T16:37:51.382059Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) Update the table
2025-10-16T16:37:51.382111Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1657: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461396:2460] disconnected.
2025-10-16T16:37:51.382119Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1668: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461396:2460] disconnected; active server actors: 1
2025-10-16T16:37:51.382122Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1693: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461396:2460] disconnected no session
2025-10-16T16:37:51.396250Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-16T16:37:51.396266Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2025-10-16T16:37:51.396269Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [9:7561859742919461365:2460] (SourceId=src, PreferedPartition=(NULL)) Start idle
2025-10-16T16:37:51.396278Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 1 sessionId:  partition: 1 expectedGeneration: (NULL)
2025-10-16T16:37:51.396431Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 9, Generation: 1
2025-10-16T16:37:51.396437Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037892] server connected, pipe [9:7561859742919461418:2460], now have 1 active actors on pipe
2025-10-16T16:37:51.396446Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.396452Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.396479Z node 9 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0 generated for partition 1 topic 'rt3.dc1--acc--topic3' owner src
2025-10-16T16:37:51.396499Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.396508Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.396510Z node 9 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-16T16:37:51.396521Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.396534Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyOwnerOk. Partition: 1
2025-10-16T16:37:51.396554Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.396601Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.396610Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.396629Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.396662Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 1 partition: 1 MaxSeqNo: 0 sessionId: src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0
2025-10-16T16:37:51.397001Z :INFO: [] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1760632671396 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-10-16T16:37:51.397040Z :INFO: [] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0" topic: "acc/topic3" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_UNSPECIFIED
2025-10-16T16:37:51.397151Z :INFO: [] MessageGroupId [src] SessionId [src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0] Write session: close. Timeout = 0 ms
2025-10-16T16:37:51.397156Z :INFO: [] MessageGroupId [src] SessionId [src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0] Write session will now close
2025-10-16T16:37:51.397161Z :DEBUG: [] MessageGroupId [src] SessionId [src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0] Write session: aborting
2025-10-16T16:37:51.397292Z :INFO: [] MessageGroupId [src] SessionId [src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0] Write session: gracefully shut down, all writes complete
2025-10-16T16:37:51.397297Z :DEBUG: [] MessageGroupId [src] SessionId [src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0] Write session: destroy
AddTopic: acc/topic3
===Run query:``DECLARE $version as Int64; DECLARE $path AS Utf8; DECLARE $cluster as Utf8; UPSERT INTO `/Root/PQ/Config/V2/Topics` (path, dc) VALUES ($path, $cluster); UPSERT INTO `/Root/PQ/Config/V2/Versions` (name, version) VALUES ("Topics", $version);`` with topic = acc/topic3, dc = 2025-10-16T16:37:51.397468Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 1 sessionId: src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0 grpc read done: success: 0 data: 
unknown
2025-10-16T16:37:51.397481Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:256: session v1 cookie: 1 sessionId: src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0 grpc read failed
2025-10-16T16:37:51.397487Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:232: session v1 cookie: 1 sessionId: src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0 grpc closed
2025-10-16T16:37:51.397492Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 1 sessionId: src|f0abd9f4-93a025a7-5ae83178-236fbcb7_0 is DEAD
2025-10-16T16:37:51.397761Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2025-10-16T16:37:51.397811Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2746: [PQ: 72075186224037892] server disconnected, pipe [9:7561859742919461418:2460] destroyed
2025-10-16T16:37:51.397823Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][1][StateIdle] TPartition::DropOwner.
2025-10-16T16:37:51.397833Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.397839Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.397841Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.414818Z node 9 :KQP_EXECUTER ERROR: kqp_planner.cpp:123: TxId: 281474976710677. Ctx: { TraceId: 01k7py535723qfqhrrgszdyt1n, Database: , SessionId: ydb://session/3?node_id=9&id=NzgxMTdkNGYtODgwZWNmNDYtODU0NDc3Y2UtNDk0ZjljZWM=, PoolId: default, DatabaseId: /Root}. Database not set, use /Root
===Query complete
2025-10-16T16:37:51.420664Z node 9 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-16T16:37:51.420666Z node 9 :PQ_READ_PROXY DEBUG: grpc_pq_read.h:111: new grpc connection
2025-10-16T16:37:51.420670Z node 9 :PQ_READ_PROXY DEBUG: grpc_pq_read.h:133: new session created cookie 1
2025-10-16T16:37:51.420676Z node 9 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 2
2025-10-16T16:37:51.420694Z node 9 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-16T16:37:51.420695Z node 9 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 3
2025-10-16T16:37:51.420783Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { path: "acc/topic3" producer_id: "A" partition_id: 0 }
2025-10-16T16:37:51.420946Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 2 path: "acc/topic3" producer_id: "A" partition_id: 0 from ipv6:[::1]:47504
2025-10-16T16:37:51.420955Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=2 sessionId= userAgent="topic server" ip=ipv6:[::1]:47504 proto=topic  topic=acc/topic3 durationSec=0
2025-10-16T16:37:51.420958Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-16T16:37:51.420966Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:475: session to partition: 0
2025-10-16T16:37:51.421329Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 2 sessionId:  describe result for acl check
2025-10-16T16:37:51.421359Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-16T16:37:51.421365Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-16T16:37:51.421367Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-16T16:37:51.421371Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [9:7561859742919461464:2485] (SourceId=A, PreferedPartition=0) StartKqpSession
2025-10-16T16:37:51.421906Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [9:7561859742919461464:2485] (SourceId=A, PreferedPartition=0) Select from the table
2025-10-16T16:37:51.423384Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [9:7561859742919461464:2485] (SourceId=A, PreferedPartition=0) Update the table
2025-10-16T16:37:51.426219Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [9:7561859742919461464:2485] (SourceId=A, PreferedPartition=0) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-16T16:37:51.426231Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [9:7561859742919461464:2485] (SourceId=A, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=(NULL)
2025-10-16T16:37:51.426234Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [9:7561859742919461464:2485] (SourceId=A, PreferedPartition=0) Start idle
2025-10-16T16:37:51.426241Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-16T16:37:51.426463Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037893 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037893, NodeId 10, Generation: 1
2025-10-16T16:37:51.426416Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037893] server connected, pipe [9:7561859742919461493:2485], now have 1 active actors on pipe
2025-10-16T16:37:51.426506Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.426516Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037893] got client message batch for topic 'rt3.dc1--acc--topic3' partition 0
2025-10-16T16:37:51.426539Z node 10 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0 generated for partition 0 topic 'rt3.dc1--acc--topic3' owner A
2025-10-16T16:37:51.426553Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.426557Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.426560Z node 10 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037893][Partition][0][StateIdle] Batch completed (1)
2025-10-16T16:37:51.426569Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.426584Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-10-16T16:37:51.426601Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.426748Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.426755Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037893] got client message batch for topic 'rt3.dc1--acc--topic3' partition 0
2025-10-16T16:37:51.426765Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.426845Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0
===Got response: status: SUCCESS init_response { session_id: "A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0" supported_codecs { codecs: 1 codecs: 0 } }
2025-10-16T16:37:51.427262Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 2 sessionId: A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-16T16:37:51.427349Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037893 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-16T16:37:51.427475Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.427483Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037893] got client message batch for topic 'rt3.dc1--acc--topic3' partition 0
2025-10-16T16:37:51.427497Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-10-16T16:37:51.427550Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037893 (partition=0) Received event: NActors::IEventHandle
2025-10-16T16:37:51.427635Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.427642Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037893] got client message batch for topic 'rt3.dc1--acc--topic3' partition 0
2025-10-16T16:37:51.427738Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 1 partNo : 0 messageNo: 1 size 67 offset: -1
2025-10-16T16:37:51.427746Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 2 partNo : 0 messageNo: 1 size 68 offset: -1
2025-10-16T16:37:51.427750Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 3 partNo : 0 messageNo: 1 size 69 offset: -1
2025-10-16T16:37:51.427754Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 4 partNo : 0 messageNo: 1 size 70 offset: -1
2025-10-16T16:37:51.427757Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 5 partNo : 0 messageNo: 1 size 71 offset: -1
2025-10-16T16:37:51.427762Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 6 partNo : 0 messageNo: 1 size 72 offset: -1
2025-10-16T16:37:51.427765Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 7 partNo : 0 messageNo: 1 size 73 offset: -1
2025-10-16T16:37:51.427768Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 8 partNo : 0 messageNo: 1 size 74 offset: -1
2025-10-16T16:37:51.427774Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 9 partNo : 0 messageNo: 1 size 75 offset: -1
2025-10-16T16:37:51.427778Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037893] got client message topic: rt3.dc1--acc--topic3 partition: 0 SourceId: '\0A' SeqNo: 10 partNo : 0 messageNo: 1 size 76 offset: -1
2025-10-16T16:37:51.427786Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037893][Partition][0][StateIdle] Received TPartition::TEvWrite
2025-10-16T16:37:51.427810Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.427823Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.427829Z node 10 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037893][Partition][0][StateIdle] Batch completed (10)
2025-10-16T16:37:51.427848Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 1 partNo 0
2025-10-16T16:37:51.427884Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 136 count 1 nextOffset 1 batches 1
2025-10-16T16:37:51.427896Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 2 partNo 0
2025-10-16T16:37:51.427901Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 241 count 2 nextOffset 2 batches 1
2025-10-16T16:37:51.427904Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 3 partNo 0
2025-10-16T16:37:51.427909Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 347 count 3 nextOffset 3 batches 1
2025-10-16T16:37:51.427912Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 4 partNo 0
2025-10-16T16:37:51.427915Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 4 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 454 count 4 nextOffset 4 batches 1
2025-10-16T16:37:51.427918Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 5 partNo 0
2025-10-16T16:37:51.427922Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 5 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 562 count 5 nextOffset 5 batches 1
2025-10-16T16:37:51.427925Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 6 partNo 0
2025-10-16T16:37:51.427929Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 6 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 671 count 6 nextOffset 6 batches 1
2025-10-16T16:37:51.427931Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 7 partNo 0
2025-10-16T16:37:51.427936Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 7 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 781 count 7 nextOffset 7 batches 1
2025-10-16T16:37:51.427939Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 8 partNo 0
2025-10-16T16:37:51.427943Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 8 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 892 count 8 nextOffset 8 batches 1
2025-10-16T16:37:51.427947Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 9 partNo 0
2025-10-16T16:37:51.427953Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 9 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 1004 count 9 nextOffset 9 batches 1
2025-10-16T16:37:51.427974Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob processing sourceId '\0A' seqNo 10 partNo 0
2025-10-16T16:37:51.427979Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 part blob complete sourceId '\0A' seqNo 10 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 1117 count 10 nextOffset 10 batches 1
2025-10-16T16:37:51.427981Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.428027Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037893][Partition][0][StateIdle] Add new write blob: topic 'rt3.dc1--acc--topic3' partition 0 compactOffset 0,10 HeadOffset 0 endOffset 0 curOffset 10 d0000000000_00000000000000000000_00000_0000000010_00000? size 892 WTime 1760632671427
2025-10-16T16:37:51.428050Z node 10 :PERSQUEUE DEBUG: read.h:275: [72075186224037893][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-16T16:37:51.428063Z node 10 :PERSQUEUE DEBUG: read.h:313: [72075186224037893][PQCacheProxy]CacheProxy. Passthrough blob. Partition 0 offset 0 partNo 0 count 10 size 892
2025-10-16T16:37:51.428809Z node 10 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 0 offset 0 count 10 size 892 actorID [10:7561859746053599621:2374]
2025-10-16T16:37:51.428838Z node 10 :PERSQUEUE DEBUG: partition.cpp:2154: [72075186224037893][Partition][0][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-16T16:37:51.428855Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037893][Partition][0][StateIdle] TPartition::HandleWriteResponse writeNewSize# 735 WriteNewSizeFromSupportivePartitions# 0
2025-10-16T16:37:51.428861Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428863Z node 10 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037893' partition 0 offset 0 partno 0 count 10 parts 0 suffix '63' size 892
2025-10-16T16:37:51.428868Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-10-16T16:37:51.428872Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428878Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 2, partNo: 0, Offset: 1 is stored on disk
2025-10-16T16:37:51.428880Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428884Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 3, partNo: 0, Offset: 2 is stored on disk
2025-10-16T16:37:51.428887Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428891Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 4, partNo: 0, Offset: 3 is stored on disk
2025-10-16T16:37:51.428893Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428896Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 5, partNo: 0, Offset: 4 is stored on disk
2025-10-16T16:37:51.428898Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428901Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 6, partNo: 0, Offset: 5 is stored on disk
2025-10-16T16:37:51.428903Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428906Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 7, partNo: 0, Offset: 6 is stored on disk
2025-10-16T16:37:51.428908Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428913Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 8, partNo: 0, Offset: 7 is stored on disk
2025-10-16T16:37:51.428915Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428918Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 9, partNo: 0, Offset: 8 is stored on disk
2025-10-16T16:37:51.428921Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037893][Partition][0][StateIdle] TPartition::ReplyWrite. Partition: 0
2025-10-16T16:37:51.428924Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037893][Partition][0][StateIdle] Answering for message sourceid: '\0A', Topic: 'rt3.dc1--acc--topic3', Partition: 0, SeqNo: 10, partNo: 0, Offset: 9 is stored on disk
2025-10-16T16:37:51.428946Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:911: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 user first-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-16T16:37:51.428957Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:953: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 user first-consumer send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-10-16T16:37:51.428961Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.428963Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.428965Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.428971Z node 10 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037893][Partition][0][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.428999Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-10-16T16:37:51.429031Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:868: [72075186224037893][Partition][0][StateIdle] read cookie 3 Topic 'rt3.dc1--acc--topic3' partition 0 user first-consumer offset 0 count 1 size 1024000 endOffset 10 max time lag 0ms effective offset 0
2025-10-16T16:37:51.429048Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:1082: [72075186224037893][Partition][0][StateIdle] read cookie 3 added 1 blobs, size 892 count 10 last offset 0, current partition end offset: 10
2025-10-16T16:37:51.429054Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:1108: [72075186224037893][Partition][0][StateIdle] Reading cookie 3. Send blob request.
2025-10-16T16:37:51.429062Z node 10 :PERSQUEUE DEBUG: cache_eviction.h:497: Got data from cache. Partition 0 offset 0 partno 0 count 10 parts_count 0 source 1 size 892 accessed 0 times before, last time 2025-10-16T16:37:51.000000Z
2025-10-16T16:37:51.429068Z node 10 :PERSQUEUE DEBUG: read.h:126: [72075186224037893][PQCacheProxy]Reading cookie 3. All 1 blobs are from cache.
2025-10-16T16:37:51.429078Z node 10 :PERSQUEUE DEBUG: pq_l2_cache.cpp:201: PQ Cache (L2). Touched. Tablet '72075186224037893' partition 0 offset 0 partno 0 count 10 parts 0 suffix '63'
2025-10-16T16:37:51.429080Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:574: FormAnswer for 1 blobs
2025-10-16T16:37:51.429074Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037893 (partition=0) Received event: NActors::IEventHandle
2025-10-16T16:37:51.429111Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:491: FormAnswer processing batch offset 0 totakecount 10 count 10 size 872 from pos 0 cbcount 10
2025-10-16T16:37:51.429129Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:1003: Topic 'rt3.dc1--acc--topic3' partition 0 user first-consumer readTimeStamp done, result 1760632671427 queuesize 0 startOffset 0
===Got response: status: SUCCESS write_response { acks { seq_no: 1 written { } } acks { seq_no: 2 written { offset: 1 } } acks { seq_no: 3 written { offset: 2 } } acks { seq_no: 4 written { offset: 3 } } acks { seq_no: 5 written { offset: 4 } } acks { seq_no: 6 written { offset: 5 } } acks { seq_no: 7 written { offset: 6 } } acks { seq_no: 8 written { offset: 7 } } acks { seq_no: 9 written { offset: 8 } } acks { seq_no: 10 written { offset: 9 } } write_statistics { persisting_time { nanos: 1000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } } }
2025-10-16T16:37:51.429510Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 3 sessionId:  grpc read done: success: 1 data: init_request { path: "acc/topic3" producer_id: "B" partition_id: 1 }
2025-10-16T16:37:51.429544Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 3 path: "acc/topic3" producer_id: "B" partition_id: 1 from ipv6:[::1]:47504
2025-10-16T16:37:51.429552Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=3 sessionId= userAgent="topic server" ip=ipv6:[::1]:47504 proto=topic  topic=acc/topic3 durationSec=0
2025-10-16T16:37:51.429556Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-16T16:37:51.429568Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:475: session to partition: 1
2025-10-16T16:37:51.429953Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 3 sessionId:  describe result for acl check
2025-10-16T16:37:51.429986Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-16T16:37:51.429988Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-16T16:37:51.429990Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-16T16:37:51.429993Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [9:7561859742919461496:2486] (SourceId=B, PreferedPartition=1) StartKqpSession
2025-10-16T16:37:51.430554Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [9:7561859742919461496:2486] (SourceId=B, PreferedPartition=1) Select from the table
2025-10-16T16:37:51.431924Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [9:7561859742919461496:2486] (SourceId=B, PreferedPartition=1) Update the table
2025-10-16T16:37:51.434426Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [9:7561859742919461496:2486] (SourceId=B, PreferedPartition=1) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-16T16:37:51.434437Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [9:7561859742919461496:2486] (SourceId=B, PreferedPartition=1) ReplyResult: Partition=1, SeqNo=(NULL)
2025-10-16T16:37:51.434441Z node 9 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [9:7561859742919461496:2486] (SourceId=B, PreferedPartition=1) Start idle
2025-10-16T16:37:51.434448Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 3 sessionId:  partition: 1 expectedGeneration: (NULL)
2025-10-16T16:37:51.434589Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 9, Generation: 1
2025-10-16T16:37:51.434591Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037892] server connected, pipe [9:7561859742919461525:2486], now have 1 active actors on pipe
2025-10-16T16:37:51.434598Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.434603Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.434626Z node 9 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie B|c17a313-3e0df584-d4d5d228-82f6b6c2_0 generated for partition 1 topic 'rt3.dc1--acc--topic3' owner B
2025-10-16T16:37:51.434633Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.434637Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.434640Z node 9 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-16T16:37:51.434648Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.434658Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyOwnerOk. Partition: 1
2025-10-16T16:37:51.434669Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.434727Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.434736Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.434754Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.434785Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 3 partition: 1 MaxSeqNo: 0 sessionId: B|c17a313-3e0df584-d4d5d228-82f6b6c2_0
===Got response: status: SUCCESS init_response { session_id: "B|c17a313-3e0df584-d4d5d228-82f6b6c2_0" partition_id: 1 supported_codecs { codecs: 1 codecs: 0 } }
2025-10-16T16:37:51.435230Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 3 sessionId: B|c17a313-3e0df584-d4d5d228-82f6b6c2_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-16T16:37:51.435327Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-16T16:37:51.435367Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.435375Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.435393Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2025-10-16T16:37:51.435413Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-16T16:37:51.435439Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.435444Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.435539Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 1 partNo : 0 messageNo: 1 size 68 offset: -1
2025-10-16T16:37:51.435549Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 2 partNo : 0 messageNo: 1 size 69 offset: -1
2025-10-16T16:37:51.435553Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 3 partNo : 0 messageNo: 1 size 70 offset: -1
2025-10-16T16:37:51.435556Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 4 partNo : 0 messageNo: 1 size 71 offset: -1
2025-10-16T16:37:51.435560Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 5 partNo : 0 messageNo: 1 size 72 offset: -1
2025-10-16T16:37:51.435563Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 6 partNo : 0 messageNo: 1 size 73 offset: -1
2025-10-16T16:37:51.435566Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 7 partNo : 0 messageNo: 1 size 74 offset: -1
2025-10-16T16:37:51.435570Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 8 partNo : 0 messageNo: 1 size 75 offset: -1
2025-10-16T16:37:51.435579Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 9 partNo : 0 messageNo: 1 size 76 offset: -1
2025-10-16T16:37:51.435583Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2010: [PQ: 72075186224037892] got client message topic: rt3.dc1--acc--topic3 partition: 1 SourceId: '\0B' SeqNo: 10 partNo : 0 messageNo: 1 size 77 offset: -1
2025-10-16T16:37:51.435591Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-16T16:37:51.435610Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.435624Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.435630Z node 9 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037892][Partition][1][StateIdle] Batch completed (10)
2025-10-16T16:37:51.435652Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 1 partNo 0
2025-10-16T16:37:51.435689Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 137 count 1 nextOffset 1 batches 1
2025-10-16T16:37:51.435700Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 2 partNo 0
2025-10-16T16:37:51.435705Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 243 count 2 nextOffset 2 batches 1
2025-10-16T16:37:51.435714Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 3 partNo 0
2025-10-16T16:37:51.435719Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 350 count 3 nextOffset 3 batches 1
2025-10-16T16:37:51.435723Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 4 partNo 0
2025-10-16T16:37:51.435727Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 4 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 458 count 4 nextOffset 4 batches 1
2025-10-16T16:37:51.435731Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 5 partNo 0
2025-10-16T16:37:51.435735Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 5 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 567 count 5 nextOffset 5 batches 1
2025-10-16T16:37:51.435738Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 6 partNo 0
2025-10-16T16:37:51.435742Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 6 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 677 count 6 nextOffset 6 batches 1
2025-10-16T16:37:51.435746Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 7 partNo 0
2025-10-16T16:37:51.435749Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 7 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 788 count 7 nextOffset 7 batches 1
2025-10-16T16:37:51.435752Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 8 partNo 0
2025-10-16T16:37:51.435756Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 8 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 900 count 8 nextOffset 8 batches 1
2025-10-16T16:37:51.435759Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 9 partNo 0
2025-10-16T16:37:51.435765Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 9 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 1013 count 9 nextOffset 9 batches 1
2025-10-16T16:37:51.435768Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob processing sourceId '\0B' seqNo 10 partNo 0
2025-10-16T16:37:51.435772Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 part blob complete sourceId '\0B' seqNo 10 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 1127 count 10 nextOffset 10 batches 1
2025-10-16T16:37:51.435775Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.435823Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--acc--topic3' partition 1 compactOffset 0,10 HeadOffset 0 endOffset 0 curOffset 10 d0000000001_00000000000000000000_00000_0000000010_00000? size 902 WTime 1760632671435
2025-10-16T16:37:51.435846Z node 9 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-16T16:37:51.435862Z node 9 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 0 partNo 0 count 10 size 902
2025-10-16T16:37:51.436533Z node 9 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 0 count 10 size 902 actorID [9:7561859742919461208:2450]
2025-10-16T16:37:51.436557Z node 9 :PERSQUEUE DEBUG: partition.cpp:2154: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-16T16:37:51.436571Z node 9 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 0 partno 0 count 10 parts 0 suffix '63' size 902
2025-10-16T16:37:51.436573Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 745 WriteNewSizeFromSupportivePartitions# 0
2025-10-16T16:37:51.436580Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436587Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-10-16T16:37:51.436598Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436603Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 2, partNo: 0, Offset: 1 is stored on disk
2025-10-16T16:37:51.436606Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436612Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 3, partNo: 0, Offset: 2 is stored on disk
2025-10-16T16:37:51.436614Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436619Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 4, partNo: 0, Offset: 3 is stored on disk
2025-10-16T16:37:51.436621Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436626Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 5, partNo: 0, Offset: 4 is stored on disk
2025-10-16T16:37:51.436628Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436633Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 6, partNo: 0, Offset: 5 is stored on disk
2025-10-16T16:37:51.436635Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436639Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 7, partNo: 0, Offset: 6 is stored on disk
2025-10-16T16:37:51.436642Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436645Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 8, partNo: 0, Offset: 7 is stored on disk
2025-10-16T16:37:51.436648Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436651Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 9, partNo: 0, Offset: 8 is stored on disk
2025-10-16T16:37:51.436654Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-16T16:37:51.436657Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0B', Topic: 'rt3.dc1--acc--topic3', Partition: 1, SeqNo: 10, partNo: 0, Offset: 9 is stored on disk
2025-10-16T16:37:51.436680Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:911: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 user first-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-16T16:37:51.436691Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:953: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 user first-consumer send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-10-16T16:37:51.436694Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.436697Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.436699Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.436705Z node 9 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.436725Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2025-10-16T16:37:51.436759Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:868: [72075186224037892][Partition][1][StateIdle] read cookie 3 Topic 'rt3.dc1--acc--topic3' partition 1 user first-consumer offset 0 count 1 size 1024000 endOffset 10 max time lag 0ms effective offset 0
2025-10-16T16:37:51.436768Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-16T16:37:51.436779Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:1082: [72075186224037892][Partition][1][StateIdle] read cookie 3 added 1 blobs, size 902 count 10 last offset 0, current partition end offset: 10
2025-10-16T16:37:51.436782Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:1108: [72075186224037892][Partition][1][StateIdle] Reading cookie 3. Send blob request.
2025-10-16T16:37:51.436791Z node 9 :PERSQUEUE DEBUG: cache_eviction.h:497: Got data from cache. Partition 1 offset 0 partno 0 count 10 parts_count 0 source 1 size 902 accessed 0 times before, last time 2025-10-16T16:37:51.000000Z
2025-10-16T16:37:51.436802Z node 9 :PERSQUEUE DEBUG: read.h:126: [72075186224037892][PQCacheProxy]Reading cookie 3. All 1 blobs are from cache.
2025-10-16T16:37:51.436810Z node 9 :PERSQUEUE DEBUG: pq_l2_cache.cpp:201: PQ Cache (L2). Touched. Tablet '72075186224037892' partition 1 offset 0 partno 0 count 10 parts 0 suffix '63'
2025-10-16T16:37:51.436815Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:574: FormAnswer for 1 blobs
2025-10-16T16:37:51.436846Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:491: FormAnswer processing batch offset 0 totakecount 10 count 10 size 882 from pos 0 cbcount 10
2025-10-16T16:37:51.436864Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:1003: Topic 'rt3.dc1--acc--topic3' partition 1 user first-consumer readTimeStamp done, result 1760632671435 queuesize 0 startOffset 0
===Got response: status: SUCCESS write_response { acks { seq_no: 1 written { } } acks { seq_no: 2 written { offset: 1 } } acks { seq_no: 3 written { offset: 2 } } acks { seq_no: 4 written { offset: 3 } } acks { seq_no: 5 written { offset: 4 } } acks { seq_no: 6 written { offset: 5 } } acks { seq_no: 7 written { offset: 6 } } acks { seq_no: 8 written { offset: 7 } } acks { seq_no: 9 written { offset: 8 } } acks { seq_no: 10 written { offset: 9 } } partition_id: 1 write_statistics { persisting_time { nanos: 1000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } } }
2025-10-16T16:37:51.437171Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { path: "acc/topic3" } consumer: "user" } }
2025-10-16T16:37:51.437223Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:929: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 read init: from# ipv6:[::1]:47504, request# { init_request { topics_read_settings { path: "acc/topic3" } consumer: "user" } }
2025-10-16T16:37:51.437320Z node 9 :PQ_READ_PROXY DEBUG: read_init_auth_actor.cpp:41: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 auth for : user
2025-10-16T16:37:51.437459Z node 9 :PQ_READ_PROXY DEBUG: read_init_auth_actor.cpp:131: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 Handle describe topics response
2025-10-16T16:37:51.437485Z node 9 :PQ_READ_PROXY DEBUG: read_init_auth_actor.cpp:68: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 auth is DEAD
2025-10-16T16:37:51.437492Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:1046: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 auth ok: topics# 1, initDone# 0
2025-10-16T16:37:51.437734Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:1217: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 register session: topic# rt3.dc1--acc--topic3
===Got response: status: SUCCESS init_response { session_id: "shared/user_9_1_18239581844137993165_v1" }
2025-10-16T16:37:51.437802Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461533:2484] connected; active server actors: 1
2025-10-16T16:37:51.437812Z node 9 :PERSQUEUE_READ_BALANCER NOTICE: read_balancer__balancing.cpp:1704: [72075186224037894][rt3.dc1--acc--topic3] consumer "user" register session for pipe [9:7561859742919461533:2484] session shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.437820Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:637: [72075186224037894][rt3.dc1--acc--topic3] consumer user register readable partition 0
2025-10-16T16:37:51.437829Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:667: [72075186224037894][rt3.dc1--acc--topic3] consumer user family created family=1 (Status=Free, Partitions=[0])
2025-10-16T16:37:51.437835Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:637: [72075186224037894][rt3.dc1--acc--topic3] consumer user register readable partition 1
2025-10-16T16:37:51.437841Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:667: [72075186224037894][rt3.dc1--acc--topic3] consumer user family created family=2 (Status=Free, Partitions=[1])
2025-10-16T16:37:51.437847Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:869: [72075186224037894][rt3.dc1--acc--topic3] consumer user register reading session ReadingSession "shared/user_9_1_18239581844137993165_v1" (Sender=[9:7561859742919461460:2484], Pipe=[9:7561859742919461533:2484], Partitions=[], ActiveFamilyCount=0)
2025-10-16T16:37:51.437851Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1184: [72075186224037894][rt3.dc1--acc--topic3] consumer user rebalancing was scheduled
2025-10-16T16:37:51.437860Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1256: [72075186224037894][rt3.dc1--acc--topic3] consumer user balancing. Sessions=1, Families=2, UnradableFamilies=2 [2 (1), 1 (0), ], RequireBalancing=0 []
2025-10-16T16:37:51.437872Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1303: [72075186224037894][rt3.dc1--acc--topic3] consumer user balancing family=2 (Status=Free, Partitions=[1]) for ReadingSession "shared/user_9_1_18239581844137993165_v1" (Sender=[9:7561859742919461460:2484], Pipe=[9:7561859742919461533:2484], Partitions=[], ActiveFamilyCount=0)
2025-10-16T16:37:51.437881Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:547: [72075186224037894][rt3.dc1--acc--topic3] consumer user family 2 status Active partitions [1] session "shared/user_9_1_18239581844137993165_v1" sender [9:7561859742919461460:2484] lock partition 1 for ReadingSession "shared/user_9_1_18239581844137993165_v1" (Sender=[9:7561859742919461460:2484], Pipe=[9:7561859742919461533:2484], Partitions=[], ActiveFamilyCount=1) generation 1 step 1
2025-10-16T16:37:51.437900Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1303: [72075186224037894][rt3.dc1--acc--topic3] consumer user balancing family=1 (Status=Free, Partitions=[0]) for ReadingSession "shared/user_9_1_18239581844137993165_v1" (Sender=[9:7561859742919461460:2484], Pipe=[9:7561859742919461533:2484], Partitions=[], ActiveFamilyCount=1)
2025-10-16T16:37:51.437909Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:547: [72075186224037894][rt3.dc1--acc--topic3] consumer user family 1 status Active partitions [0] session "shared/user_9_1_18239581844137993165_v1" sender [9:7561859742919461460:2484] lock partition 0 for ReadingSession "shared/user_9_1_18239581844137993165_v1" (Sender=[9:7561859742919461460:2484], Pipe=[9:7561859742919461533:2484], Partitions=[], ActiveFamilyCount=2) generation 1 step 2
2025-10-16T16:37:51.437915Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1323: [72075186224037894][rt3.dc1--acc--topic3] consumer user start rebalancing. familyCount=2, sessionCount=1, desiredFamilyCount=2, allowPlusOne=0
2025-10-16T16:37:51.437920Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1400: [72075186224037894][rt3.dc1--acc--topic3] consumer user balancing duration: 0.000053s
2025-10-16T16:37:51.438148Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:1335: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 assign: record# { Partition: 1 TabletId: 72075186224037892 Topic: "rt3.dc1--acc--topic3" Generation: 1 Step: 1 Session: "shared/user_9_1_18239581844137993165_v1" ClientId: "user" PipeClient { RawX1: 7561859742919461533 RawX2: 4503638282078644 } Path: "/Root/PQ/rt3.dc1--acc--topic3" }
2025-10-16T16:37:51.438173Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:1143: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 INITING TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1)
2025-10-16T16:37:51.438180Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:1335: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 assign: record# { Partition: 0 TabletId: 72075186224037893 Topic: "rt3.dc1--acc--topic3" Generation: 1 Step: 2 Session: "shared/user_9_1_18239581844137993165_v1" ClientId: "user" PipeClient { RawX1: 7561859742919461533 RawX2: 4503638282078644 } Path: "/Root/PQ/rt3.dc1--acc--topic3" }
2025-10-16T16:37:51.438189Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438192Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:1143: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 INITING TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2)
2025-10-16T16:37:51.438219Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 995f4c59-d947cc73-1c3ca916-4a80206b
2025-10-16T16:37:51.438234Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037892] server connected, pipe [9:7561859742919461536:2495], now have 1 active actors on pipe
2025-10-16T16:37:51.438237Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:983: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1, pipe: [9:7561859742919461536:2495]
2025-10-16T16:37:51.438243Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.438247Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.438250Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438256Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:1747: [PQ: 72075186224037892] Created session shared/user_9_1_18239581844137993165_v1 on pipe: [9:7561859742919461536:2495]
2025-10-16T16:37:51.438270Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.438278Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.438279Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 82c4629e-f6986bf5-18c99906-7d13db3e
2025-10-16T16:37:51.438280Z node 9 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-16T16:37:51.438288Z node 9 :PQ_READ_PROXY DEBUG: caching_service.cpp:283: Direct read cache: registered server session: shared/user_9_1_18239581844137993165_v1:1 with generation 1
2025-10-16T16:37:51.438293Z node 9 :PERSQUEUE DEBUG: partition.cpp:3708: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 1 user user session is set to 0 (startOffset 0) session shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.438296Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.438297Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438309Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 38fb216f-b6711123-8ca5d3e7-7f30b978
2025-10-16T16:37:51.438315Z node 9 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-16T16:37:51.438333Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:983: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037893 Generation: 1, pipe: [9:7561859742919461538:2496]
2025-10-16T16:37:51.438342Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438357Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 4b700cbd-5523f584-7d052c1b-f1cda5b
2025-10-16T16:37:51.438373Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438329Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2721: [PQ: 72075186224037893] server connected, pipe [9:7561859742919461538:2496], now have 1 active actors on pipe
2025-10-16T16:37:51.438391Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 38de83d-9312d19d-9616ea20-9a05de5b
2025-10-16T16:37:51.438404Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.438399Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438414Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# d2455087-7ef42c34-2bfc51ca-37289ac
2025-10-16T16:37:51.438409Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037893] got client message batch for topic 'rt3.dc1--acc--topic3' partition 0
2025-10-16T16:37:51.438426Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438417Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:1747: [PQ: 72075186224037893] Created session shared/user_9_1_18239581844137993165_v1 on pipe: [9:7561859742919461538:2496]
2025-10-16T16:37:51.438436Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.438441Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.438443Z node 10 :PERSQUEUE DEBUG: partition.cpp:2340: [72075186224037893][Partition][0][StateIdle] Batch completed (1)
2025-10-16T16:37:51.438445Z node 10 :PQ_READ_PROXY DEBUG: caching_service.cpp:283: Direct read cache: registered server session: shared/user_9_1_18239581844137993165_v1:2 with generation 1
2025-10-16T16:37:51.438465Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 215322c7-f7ed480c-20cdf62b-3ae986cd
2025-10-16T16:37:51.438475Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438467Z node 10 :PERSQUEUE DEBUG: partition.cpp:3708: [72075186224037893][Partition][0][StateIdle] Topic 'rt3.dc1--acc--topic3' partition 0 user user session is set to 0 (startOffset 0) session shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.438470Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.438489Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# 145cac4-bbff56ee-819cb703-e51d4526
2025-10-16T16:37:51.438498Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438493Z node 10 :PERSQUEUE DEBUG: read.h:275: [72075186224037893][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-16T16:37:51.438512Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# b256ea88-df4298d7-ae97b9d4-79b1a8c5
2025-10-16T16:37:51.438520Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256 } }
2025-10-16T16:37:51.438559Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1839: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got read request: guid# ca236f79-27f53ac-9afffe14-1a1ffad1
2025-10-16T16:37:51.438910Z node 9 :PERSQUEUE DEBUG: partition.cpp:2154: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-16T16:37:51.439156Z node 10 :PERSQUEUE DEBUG: partition.cpp:2154: [72075186224037893][Partition][0][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-16T16:37:51.439312Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-16T16:37:51.439323Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.439324Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.439326Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.439332Z node 9 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.439343Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-16T16:37:51.439413Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:663: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 10 SizeLag: 902 WriteTimestampEstimateMS: 1760632671436 ClientHasAnyCommits: false } Cookie: 18446744073709551615 }
2025-10-16T16:37:51.439425Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:694: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 INIT DONE TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 10 readOffset 0 committedOffset 0
2025-10-16T16:37:51.439443Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1434: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 sending to client partition status
2025-10-16T16:37:51.439539Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037893][Partition][0][StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-16T16:37:51.439564Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.439567Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
===Expect 1st start part, Got response: 2025-10-16T16:37:51.439569Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.439575Z node 10 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037893][Partition][0][StateIdle] No data for blobs compaction
2025-10-16T16:37:51.439587Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
status: SUCCESS start_partition_session_request { partition_session { partition_session_id: 1 path: "acc/topic3" partition_id: 1 } partition_offsets { end: 10 } }
2025-10-16T16:37:51.439682Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:663: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 10 SizeLag: 892 WriteTimestampEstimateMS: 1760632671428 ClientHasAnyCommits: false } Cookie: 18446744073709551615 }
2025-10-16T16:37:51.439691Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:694: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 INIT DONE TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 10 readOffset 0 committedOffset 0
2025-10-16T16:37:51.439702Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1434: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 sending to client partition status
===Expect 2nd start part, Got response: status: SUCCESS start_partition_session_request { partition_session { partition_session_id: 2 path: "acc/topic3" } partition_offsets { end: 10 } }
2025-10-16T16:37:51.439926Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 1 } }
2025-10-16T16:37:51.439959Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:539: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 0, commitOffset# (empty maybe)
2025-10-16T16:37:51.439973Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 1124134 } }
2025-10-16T16:37:51.439993Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:1023: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 Start reading TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 10 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-16T16:37:51.440002Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:969: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) ready for read with readOffset 0 endOffset 10
2025-10-16T16:37:51.440003Z node 9 :PQ_READ_PROXY WARN: read_session_actor.cpp:532: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got irrelevant StartRead from client: partition# 1124134, offset# 0
2025-10-16T16:37:51.440012Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2332: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 0, endOffset# 10, WTime# 0, sizeLag# 902
2025-10-16T16:37:51.440014Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2343: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1TEvPartitionReady. Aval parts: 1
2025-10-16T16:37:51.440022Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2266: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 performing read request: guid# f7cac828-ee1415b7-c182bd5a-912e05d3, from# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1), count# 12, size# 1082, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-16T16:37:51.440042Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:1395: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 READ FROM TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1)maxCount 12 maxSize 1082 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 10 ClientCommitOffset 0 committedOffset 0 Guid f7cac828-ee1415b7-c182bd5a-912e05d3
2025-10-16T16:37:51.440067Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.440076Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--acc--topic3' partition 1
2025-10-16T16:37:51.440116Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:868: [72075186224037892][Partition][1][StateIdle] read cookie 4 Topic 'rt3.dc1--acc--topic3' partition 1 user user offset 0 count 12 size 1082 endOffset 10 max time lag 0ms effective offset 0
2025-10-16T16:37:51.440139Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:1082: [72075186224037892][Partition][1][StateIdle] read cookie 4 added 1 blobs, size 902 count 10 last offset 0, current partition end offset: 10
2025-10-16T16:37:51.440148Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:1108: [72075186224037892][Partition][1][StateIdle] Reading cookie 4. Send blob request.
2025-10-16T16:37:51.440156Z node 9 :PERSQUEUE DEBUG: cache_eviction.h:497: Got data from cache. Partition 1 offset 0 partno 0 count 10 parts_count 0 source 1 size 902 accessed 1 times before, last time 2025-10-16T16:37:51.000000Z
2025-10-16T16:37:51.440168Z node 9 :PERSQUEUE DEBUG: read.h:126: [72075186224037892][PQCacheProxy]Reading cookie 4. All 1 blobs are from cache.
2025-10-16T16:37:51.440177Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:574: FormAnswer for 1 blobs
2025-10-16T16:37:51.440184Z node 9 :PERSQUEUE DEBUG: pq_l2_cache.cpp:201: PQ Cache (L2). Touched. Tablet '72075186224037892' partition 1 offset 0 partno 0 count 10 parts 0 suffix '63'
2025-10-16T16:37:51.440209Z node 9 :PERSQUEUE DEBUG: partition_read.cpp:491: FormAnswer processing batch offset 0 totakecount 10 count 10 size 882 from pos 0 cbcount 10
2025-10-16T16:37:51.440301Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.440418Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:663: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 10 Result { Offset: 0 Data: "... 68 bytes ..." SourceId: "\000B" SeqNo: 1 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 1 PartitionKey: "" ExplicitHash: "" } Result { Offset: 1 Data: "... 69 bytes ..." SourceId: "\000B" SeqNo: 2 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 2 PartitionKey: "" ExplicitHash: "" } Result { Offset: 2 Data: "... 70 bytes ..." SourceId: "\000B" SeqNo: 3 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 3 PartitionKey: "" ExplicitHash: "" } Result { Offset: 3 Data: "... 71 bytes ..." SourceId: "\000B" SeqNo: 4 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 4 Data: "... 72 bytes ..." SourceId: "\000B" SeqNo: 5 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 5 PartitionKey: "" ExplicitHash: "" } Result { Offset: 5 Data: "... 73 bytes ..." SourceId: "\000B" SeqNo: 6 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 6 PartitionKey: "" ExplicitHash: "" } Result { Offset: 6 Data: "... 74 bytes ..." SourceId: "\000B" SeqNo: 7 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 7 PartitionKey: "" ExplicitHash: "" } Result { Offset: 7 Data: "... 75 bytes ..." SourceId: "\000B" SeqNo: 8 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 8 PartitionKey: "" ExplicitHash: "" } Result { Offset: 8 Data: "... 76 bytes ..." SourceId: "\000B" SeqNo: 9 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 9 PartitionKey: "" ExplicitHash: "" } Result { Offset: 9 Data: "... 77 bytes ..." SourceId: "\000B" SeqNo: 10 WriteTimestampMS: 1760632671435 CreateTimestampMS: 1760632671435 UncompressedSize: 10 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 1 SizeLag: 18446744073709551423 RealReadOffset: 9 WaitQuotaTimeMs: 0 EndOffset: 10 StartOffset: 0 } Cookie: 0 }
2025-10-16T16:37:51.440454Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:1277: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 1 from offset 10
2025-10-16T16:37:51.440464Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:901: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 after read state TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 10 ReadOffset 10 ReadGuid f7cac828-ee1415b7-c182bd5a-912e05d3 has messages 1
2025-10-16T16:37:51.440491Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1940: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 read done: guid# f7cac828-ee1415b7-c182bd5a-912e05d3, partition# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 1(assignId:1), size# 444
2025-10-16T16:37:51.440502Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2102: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 response to read: guid# f7cac828-ee1415b7-c182bd5a-912e05d3
2025-10-16T16:37:51.440529Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2145: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 Process answer. Aval parts: 0
2025-10-16T16:37:51.452478Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.452497Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.452500Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.452975Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.452990Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.452992Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
Got read response { status: SUCCESS read_response { partition_data { partition_session_id: 1 batches { message_data { seq_no: 1 created_at { seconds: 1760632671 nanos: 435000000 } data: "y" uncompressed_size: 1 message_group_id: "B" } message_data { offset: 1 seq_no: 2 created_at { seconds: 1760632671 nanos: 435000000 } data: "yy" uncompressed_size: 2 message_group_id: "B" } message_data { offset: 2 seq_no: 3 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyy" uncompressed_size: 3 message_group_id: "B" } message_data { offset: 3 seq_no: 4 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyy" uncompressed_size: 4 message_group_id: "B" } message_data { offset: 4 seq_no: 5 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyyy" uncompressed_size: 5 message_group_id: "B" } message_data { offset: 5 seq_no: 6 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyyyy" uncompressed_size: 6 message_group_id: "B" } message_data { offset: 6 seq_no: 7 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyyyyy" uncompressed_size: 7 message_group_id: "B" } message_data { offset: 7 seq_no: 8 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyyyyyy" uncompressed_size: 8 message_group_id: "B" } message_data { offset: 8 seq_no: 9 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyyyyyyy" uncompressed_size: 9 message_group_id: "B" } message_data { offset: 9 seq_no: 10 created_at { seconds: 1760632671 nanos: 435000000 } data: "yyyyyyyyyy" uncompressed_size: 10 message_group_id: "B" } producer_id: "B" write_session_meta { key: "_ip" value: "ipv6:[::1]:47504" } write_session_meta { key: "ident" value: "acc" } write_session_meta { key: "logtype" value: "topic3" } write_session_meta { key: "server" value: "ipv6:[::1]:47504" } codec: 10042 written_at { seconds: 1760632671 nanos: 435000000 } } } bytes_size: 444 } }
2025-10-16T16:37:51.540280Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 2 } }
2025-10-16T16:37:51.540403Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:539: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 0, commitOffset# (empty maybe)
2025-10-16T16:37:51.540430Z node 9 :PQ_READ_PROXY INFO: partition_actor.cpp:1023: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 Start reading TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 10 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-16T16:37:51.540436Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:969: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) ready for read with readOffset 0 endOffset 10
2025-10-16T16:37:51.540454Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2332: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 0, endOffset# 10, WTime# 0, sizeLag# 892
2025-10-16T16:37:51.540461Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2343: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1TEvPartitionReady. Aval parts: 1
2025-10-16T16:37:51.540476Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2266: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 performing read request: guid# 73cfcb0a-e74bbb64-4f8904a-e1c37e34, from# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2), count# 12, size# 1070, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-16T16:37:51.540514Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:1395: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 READ FROM TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2)maxCount 12 maxSize 1070 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 10 ClientCommitOffset 0 committedOffset 0 Guid 73cfcb0a-e74bbb64-4f8904a-e1c37e34
2025-10-16T16:37:51.540735Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--acc--topic3' requestId: <none>
2025-10-16T16:37:51.540751Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2635: [PQ: 72075186224037893] got client message batch for topic 'rt3.dc1--acc--topic3' partition 0
2025-10-16T16:37:51.540798Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:868: [72075186224037893][Partition][0][StateIdle] read cookie 4 Topic 'rt3.dc1--acc--topic3' partition 0 user user offset 0 count 12 size 1070 endOffset 10 max time lag 0ms effective offset 0
2025-10-16T16:37:51.540817Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:1082: [72075186224037893][Partition][0][StateIdle] read cookie 4 added 1 blobs, size 892 count 10 last offset 0, current partition end offset: 10
2025-10-16T16:37:51.540824Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:1108: [72075186224037893][Partition][0][StateIdle] Reading cookie 4. Send blob request.
2025-10-16T16:37:51.540832Z node 10 :PERSQUEUE DEBUG: cache_eviction.h:497: Got data from cache. Partition 0 offset 0 partno 0 count 10 parts_count 0 source 1 size 892 accessed 1 times before, last time 2025-10-16T16:37:51.000000Z
2025-10-16T16:37:51.540843Z node 10 :PERSQUEUE DEBUG: read.h:126: [72075186224037893][PQCacheProxy]Reading cookie 4. All 1 blobs are from cache.
2025-10-16T16:37:51.540854Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:574: FormAnswer for 1 blobs
2025-10-16T16:37:51.540875Z node 10 :PERSQUEUE DEBUG: pq_l2_cache.cpp:201: PQ Cache (L2). Touched. Tablet '72075186224037893' partition 0 offset 0 partno 0 count 10 parts 0 suffix '63'
2025-10-16T16:37:51.540886Z node 10 :PERSQUEUE DEBUG: partition_read.cpp:491: FormAnswer processing batch offset 0 totakecount 10 count 10 size 872 from pos 0 cbcount 10
2025-10-16T16:37:51.541022Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--acc--topic3' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-16T16:37:51.541328Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:663: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) initDone 1 event { CmdReadResult { MaxOffset: 10 Result { Offset: 0 Data: "... 67 bytes ..." SourceId: "\000A" SeqNo: 1 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 1 PartitionKey: "" ExplicitHash: "" } Result { Offset: 1 Data: "... 68 bytes ..." SourceId: "\000A" SeqNo: 2 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 2 PartitionKey: "" ExplicitHash: "" } Result { Offset: 2 Data: "... 69 bytes ..." SourceId: "\000A" SeqNo: 3 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 3 PartitionKey: "" ExplicitHash: "" } Result { Offset: 3 Data: "... 70 bytes ..." SourceId: "\000A" SeqNo: 4 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 4 Data: "... 71 bytes ..." SourceId: "\000A" SeqNo: 5 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 5 PartitionKey: "" ExplicitHash: "" } Result { Offset: 5 Data: "... 72 bytes ..." SourceId: "\000A" SeqNo: 6 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 6 PartitionKey: "" ExplicitHash: "" } Result { Offset: 6 Data: "... 73 bytes ..." SourceId: "\000A" SeqNo: 7 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 7 PartitionKey: "" ExplicitHash: "" } Result { Offset: 7 Data: "... 74 bytes ..." SourceId: "\000A" SeqNo: 8 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 8 PartitionKey: "" ExplicitHash: "" } Result { Offset: 8 Data: "... 75 bytes ..." SourceId: "\000A" SeqNo: 9 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 9 PartitionKey: "" ExplicitHash: "" } Result { Offset: 9 Data: "... 76 bytes ..." SourceId: "\000A" SeqNo: 10 WriteTimestampMS: 1760632671427 CreateTimestampMS: 1760632671427 UncompressedSize: 10 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 1 SizeLag: 18446744073709551423 RealReadOffset: 9 WaitQuotaTimeMs: 0 EndOffset: 10 StartOffset: 0 } Cookie: 0 }
2025-10-16T16:37:51.541381Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:1277: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 1 from offset 10
2025-10-16T16:37:51.541395Z node 9 :PQ_READ_PROXY DEBUG: partition_actor.cpp:901: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 after read state TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 10 ReadOffset 10 ReadGuid 73cfcb0a-e74bbb64-4f8904a-e1c37e34 has messages 1
2025-10-16T16:37:51.541433Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:1940: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 read done: guid# 73cfcb0a-e74bbb64-4f8904a-e1c37e34, partition# TopicId: Topic rt3.dc1--acc--topic3 in dc dc1 in database: Root, partition 0(assignId:2), size# 443
2025-10-16T16:37:51.541450Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2102: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 response to read: guid# 73cfcb0a-e74bbb64-4f8904a-e1c37e34
2025-10-16T16:37:51.541554Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:2145: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 Process answer. Aval parts: 0
Got read response { status: SUCCESS read_response { partition_data { partition_session_id: 2 batches { message_data { seq_no: 1 created_at { seconds: 1760632671 nanos: 427000000 } data: "x" uncompressed_size: 1 message_group_id: "A" } message_data { offset: 1 seq_no: 2 created_at { seconds: 1760632671 nanos: 427000000 } data: "xx" uncompressed_size: 2 message_group_id: "A" } message_data { offset: 2 seq_no: 3 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxx" uncompressed_size: 3 message_group_id: "A" } message_data { offset: 3 seq_no: 4 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxx" uncompressed_size: 4 message_group_id: "A" } message_data { offset: 4 seq_no: 5 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxxx" uncompressed_size: 5 message_group_id: "A" } message_data { offset: 5 seq_no: 6 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxxxx" uncompressed_size: 6 message_group_id: "A" } message_data { offset: 6 seq_no: 7 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxxxxx" uncompressed_size: 7 message_group_id: "A" } message_data { offset: 7 seq_no: 8 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxxxxxx" uncompressed_size: 8 message_group_id: "A" } message_data { offset: 8 seq_no: 9 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxxxxxxx" uncompressed_size: 9 message_group_id: "A" } message_data { offset: 9 seq_no: 10 created_at { seconds: 1760632671 nanos: 427000000 } data: "xxxxxxxxxx" uncompressed_size: 10 message_group_id: "A" } producer_id: "A" write_session_meta { key: "_ip" value: "ipv6:[::1]:47504" } write_session_meta { key: "ident" value: "acc" } write_session_meta { key: "logtype" value: "topic3" } write_session_meta { key: "server" value: "ipv6:[::1]:47504" } codec: 1 written_at { seconds: 1760632671 nanos: 427000000 } } } bytes_size: 443 } }
2025-10-16T16:37:51.542027Z node 9 :PQ_READ_PROXY DEBUG: read_session_actor.cpp:122: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read done: success# 0, data# {  }
2025-10-16T16:37:51.542037Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:125: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc read failed
2025-10-16T16:37:51.542042Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:92: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 grpc closed
2025-10-16T16:37:51.542058Z node 9 :PQ_READ_PROXY INFO: read_session_actor.cpp:383: session cookie 1 consumer shared/user session shared/user_9_1_18239581844137993165_v1 is DEAD
2025-10-16T16:37:51.542131Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 3 sessionId: B|c17a313-3e0df584-d4d5d228-82f6b6c2_0 grpc read done: success: 0 data: 
2025-10-16T16:37:51.542140Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:256: session v1 cookie: 3 sessionId: B|c17a313-3e0df584-d4d5d228-82f6b6c2_0 grpc read failed
2025-10-16T16:37:51.542146Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:232: session v1 cookie: 3 sessionId: B|c17a313-3e0df584-d4d5d228-82f6b6c2_0 grpc closed
2025-10-16T16:37:51.542150Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 3 sessionId: B|c17a313-3e0df584-d4d5d228-82f6b6c2_0 is DEAD
2025-10-16T16:37:51.542202Z node 9 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 2 sessionId: A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0 grpc read done: success: 0 data: 
2025-10-16T16:37:51.542209Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:256: session v1 cookie: 2 sessionId: A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0 grpc read failed
2025-10-16T16:37:51.542216Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:232: session v1 cookie: 2 sessionId: A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0 grpc closed
2025-10-16T16:37:51.542220Z node 9 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 2 sessionId: A|99bd2aba-e797070b-ff61a56f-bf16b8d5_0 is DEAD
2025-10-16T16:37:51.542259Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2257: [PQ: 72075186224037893] Destroy direct read session shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.542282Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2746: [PQ: 72075186224037893] server disconnected, pipe [9:7561859742919461538:2496] destroyed
2025-10-16T16:37:51.542298Z node 10 :PQ_READ_PROXY DEBUG: caching_service.cpp:139: Direct read cache: server session deregistered: shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.542288Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2025-10-16T16:37:51.542314Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2257: [PQ: 72075186224037892] Destroy direct read session shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.542319Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2746: [PQ: 72075186224037892] server disconnected, pipe [9:7561859742919461536:2495] destroyed
2025-10-16T16:37:51.542325Z node 9 :PERSQUEUE DEBUG: pq_impl.cpp:2746: [PQ: 72075186224037892] server disconnected, pipe [9:7561859742919461525:2486] destroyed
2025-10-16T16:37:51.542332Z node 9 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][1][StateIdle] TPartition::DropOwner.
2025-10-16T16:37:51.542340Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.542344Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.542346Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.542355Z node 9 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037893 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-10-16T16:37:51.542368Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1657: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461533:2484] disconnected.
2025-10-16T16:37:51.542372Z node 9 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1668: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461533:2484] disconnected; active server actors: 1
2025-10-16T16:37:51.542375Z node 9 :PERSQUEUE_READ_BALANCER NOTICE: read_balancer__balancing.cpp:1677: [72075186224037894][rt3.dc1--acc--topic3] pipe [9:7561859742919461533:2484] client user disconnected session shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.542378Z node 9 :PQ_READ_PROXY DEBUG: caching_service.cpp:139: Direct read cache: server session deregistered: shared/user_9_1_18239581844137993165_v1
2025-10-16T16:37:51.542442Z node 10 :PERSQUEUE DEBUG: pq_impl.cpp:2746: [PQ: 72075186224037893] server disconnected, pipe [9:7561859742919461493:2485] destroyed
2025-10-16T16:37:51.542469Z node 10 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037893][Partition][0][StateIdle] TPartition::DropOwner.
2025-10-16T16:37:51.542476Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.542479Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.542481Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.552815Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.552829Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.552832Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.553313Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.553327Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.553329Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.653190Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.653216Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.653219Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.653655Z node 10 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037893][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.653683Z node 10 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037893][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.653687Z node 10 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037893][Partition][0][StateIdle] Try persist
2025-10-16T16:37:51.753507Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.753522Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.753524Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-16T16:37:51.853871Z node 9 :PERSQUEUE DEBUG: partition.cpp:2327: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-16T16:37:51.853888Z node 9 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-16T16:37:51.853890Z node 9 :PERSQUEUE DEBUG: partition.cpp:2359: [72075186224037892][Partition][1][StateIdle] Try persist
