2025-10-26T18:06:22.045329Z node 1 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[1:7565593405772594119:4106];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:22.045420Z node 1 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-10-26T18:06:22.134447Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache created
2025-10-26T18:06:22.152237Z node 2 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[2:7565593407270345051:8194];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:22.156374Z node 2 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-10-26T18:06:22.300908Z node 1 :PQ_READ_PROXY DEBUG: Direct read cache created
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/70hy/000513/r3tmp/tmpJOynT7/pdisk_1.dat
2025-10-26T18:06:22.787585Z node 1 :IMPORT WARN: Table profiles were not loaded
2025-10-26T18:06:22.837884Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(1, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-26T18:06:22.838042Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(1, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-26T18:06:22.843870Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(2, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-26T18:06:22.843963Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(2, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-26T18:06:22.848935Z node 1 :HIVE WARN: HIVE#72057594037968897 Handle TEvInterconnect::TEvNodeConnected, NodeId 2 Cookie 2
2025-10-26T18:06:22.850229Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(1, (0,0,0,0)) VolatileState: Connecting -> Connected
2025-10-26T18:06:22.851226Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(2, (0,0,0,0)) VolatileState: Connecting -> Connected
TServer::EnableGrpc on GrpcPort 17330, node 1
2025-10-26T18:06:23.087419Z node 1 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/70hy/000513/r3tmp/yandexcCeKbY.tmp
2025-10-26T18:06:23.087446Z node 1 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/70hy/000513/r3tmp/yandexcCeKbY.tmp
2025-10-26T18:06:23.087612Z node 1 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/70hy/000513/r3tmp/yandexcCeKbY.tmp
2025-10-26T18:06:23.087742Z node 1 :NET_CLASSIFIER ERROR: got bad distributable configuration
2025-10-26T18:06:23.209560Z INFO: TTestServer started on Port 61120 GrpcPort 17330
TClient is connected to server localhost:61120
PQClient connected to localhost:17330
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
    }
  }
  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
      PlanResolution: 7
      Coo...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-10-26T18:06:23.537370Z node 1 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976715657:0, at schemeshard:  72057594046644480
waiting...
waiting...
2025-10-26T18:06:23.617298Z node 1 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715659:0, at schemeshard:  72057594046644480
waiting...
waiting...
waiting...
2025-10-26T18:06:26.236722Z node 1 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [1:7565593422952464313:4303], status: SCHEME_ERROR, issues: <main>: Error: Type annotation, code: 1030
    <main>:3:16: Error: At function: KiReadTable!
        <main>:3:16: Error: Cannot find table 'db.[/Root/PQ/Config/V2/Cluster]' 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-26T18:06:26.238843Z node 1 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=1&id=MTAwODkxNTQtNmIyMzZlMGEtMWMwNTFjZTEtNDJhODMwOGU=, ActorId: [1:7565593422952464311:4295], ActorState: ExecuteState, TraceId: 01k8gv6f7qf806gkxf3kmnhyba, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-10-26T18:06:26.240336Z node 1 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715662:0, at schemeshard:  72057594046644480
2025-10-26T18:06:26.243085Z node 1 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 3 column: 16 } message: "At function: KiReadTable!" end_position { row: 3 column: 16 } severity: 1 issues { position { row: 3 column: 16 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Cluster]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 3 column: 16 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2025-10-26T18:06:26.251516Z node 2 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [2:7565593424450214560:8366], status: SCHEME_ERROR, issues: <main>: Error: Type annotation, code: 1030
    <main>:3:16: Error: At function: KiReadTable!
        <main>:3:16: Error: Cannot find table 'db.[/Root/PQ/Config/V2/Cluster]' 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-26T18:06:26.253078Z node 2 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=2&id=ZDE0OGRlYWMtYzdlYzQ4ZDQtZDgyOGMzNWQtNjRhMGJiMDU=, ActorId: [2:7565593424450214558:8389], ActorState: ExecuteState, TraceId: 01k8gv6f7w6rz2ns214barvsgj, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-10-26T18:06:26.253872Z node 2 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 3 column: 16 } message: "At function: KiReadTable!" end_position { row: 3 column: 16 } severity: 1 issues { position { row: 3 column: 16 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Cluster]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 3 column: 16 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2025-10-26T18:06:26.316068Z node 1 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715663:0, at schemeshard:  72057594046644480
2025-10-26T18:06:26.446654Z node 1 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715664:0, at schemeshard:  72057594046644480
=== 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-26T18:06:26.710262Z node 1 :KQP_EXECUTER ERROR: TxId: 281474976715665. Ctx: { TraceId: 01k8gv6fq7d3eg0rwdrpbq1krt, Database: , DatabaseId: /Root, SessionId: ydb://session/3?node_id=1&id=NDNiNzQ5ZWItNWNmNDVhNmEtZTE5NmE5MTktMmQzZWYxYTA=, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
=== CheckClustersList. Subcribe to ClusterTracker from [1:7565593422952464741:12324] 
2025-10-26T18:06:27.048097Z node 1 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[1:7565593405772594119:4106];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:27.048202Z node 1 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
2025-10-26T18:06:27.151830Z node 2 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[2:7565593407270345051:8194];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:27.151950Z node 2 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
=== CheckClustersList. Ok
CreateTopicNoLegacy: /Root/PQ/rt3.dc1--demo
Create topic: /Root/PQ/rt3.dc1--demo
AddTopic: /Root/PQ/rt3.dc1--demo
===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 = /Root/PQ/rt3.dc1/demo, dc = unknown
2025-10-26T18:06:32.710768Z node 1 :PQ_READ_PROXY DEBUG: new Create topic request
2025-10-26T18:06:32.765842Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic  pipe [1:7565593448722269140:8562] connected; active server actors: 1
2025-10-26T18:06:32.766135Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo updating configuration. Deleted partitions []. Added partitions [0]
2025-10-26T18:06:32.772358Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-10-26T18:06:32.776945Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: BALANCER INIT DONE for rt3.dc1--demo: (0, 72075186224037892) 
2025-10-26T18:06:32.777385Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037893 topic rt3.dc1--demo TEvClientConnected TabletId 72057594046644480, NodeId 1, Generation 2
2025-10-26T18:06:32.801148Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-10-26T18:06:32.801517Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-10-26T18:06:32.810779Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-10-26T18:06:32.811063Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] doesn't have tx info
2025-10-26T18:06:32.811107Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-10-26T18:06:32.811152Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-10-26T18:06:32.811203Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Txs.size=0, PlannedTxs.size=0
2025-10-26T18:06:32.811250Z node 2 :PERSQUEUE NOTICE: Tablet 72075186224037892 disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-26T18:06:32.811291Z node 2 :PERSQUEUE INFO: Tablet 72075186224037892 doesn't have tx writes info
2025-10-26T18:06:32.814970Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593448722269166:2042], now have 1 active actors on pipe
2025-10-26T18:06:32.815000Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593448722269139:8548], now have 1 active actors on pipe
2025-10-26T18:06:32.816010Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037893 topic rt3.dc1--demo TEvClientConnected TabletId 72075186224037892, NodeId 2, Generation 1
2025-10-26T18:06:32.834466Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7565593405772594452 RawX2: 4294979628 } TxId: 281474976715677 Config { TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 9223372036854775807 LifetimeSeconds: 64800 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 2097152 BurstSize: 2097152 TotalPartitions: 1 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--demo" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "unknown" Ident: "unknown" Topic: "demo" DC: "dc1" ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } ReadRuleServiceTypes: "data-streams" FormatVersion: 0 Codecs { } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--demo" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 } } }
2025-10-26T18:06:32.834676Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Propose TxId 281474976715677, WriteId (empty maybe)
2025-10-26T18:06:32.834709Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state UNKNOWN
2025-10-26T18:06:32.834729Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State UNKNOWN
2025-10-26T18:06:32.834765Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] schedule TEvProposeTransactionResult(PREPARED)
2025-10-26T18:06:32.834796Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState PREPARING
2025-10-26T18:06:32.834897Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715677
2025-10-26T18:06:32.835420Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] save tx TxId: 281474976715677 State: PREPARED MinStep: 1761501992712 MaxStep: 18446744073709551615 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 9223372036854775807 LifetimeSeconds: 64800 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 2097152 BurstSize: 2097152 TotalPartitions: 1 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--demo" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "unknown" Ident: "unknown" Topic: "demo" DC: "dc1" ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } ReadRuleServiceTypes: "data-streams" FormatVersion: 0 Codecs { } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--demo" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593405772594452 RawX2: 4294979628 }
2025-10-26T18:06:32.835599Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:32.841233Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:32.841286Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARING
2025-10-26T18:06:32.841306Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State PREPARING
2025-10-26T18:06:32.841328Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState PREPARED
2025-10-26T18:06:32.845294Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037892 TxId: 281474976715677
2025-10-26T18:06:32.851052Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593448722269203:8440], now have 1 active actors on pipe
2025-10-26T18:06:32.856456Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715677 AckTo { RawX1: 7565593405772594693 RawX2: 4294975520 } } Step: 1761501992894 MediatorID: 72057594046382081 TabletID: 72075186224037892
2025-10-26T18:06:32.856546Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARED
2025-10-26T18:06:32.856568Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State PREPARED
2025-10-26T18:06:32.856593Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState PLANNING
2025-10-26T18:06:32.856626Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] PlanStep 1761501992894, PlanTxId 281474976715677
2025-10-26T18:06:32.856667Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715677
2025-10-26T18:06:32.857183Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] save tx TxId: 281474976715677 State: PLANNED MinStep: 1761501992712 MaxStep: 18446744073709551615 Step: 1761501992894 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 9223372036854775807 LifetimeSeconds: 64800 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 2097152 BurstSize: 2097152 TotalPartitions: 1 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--demo" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "unknown" Ident: "unknown" Topic: "demo" DC: "dc1" ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } ReadRuleServiceTypes: "data-streams" FormatVersion: 0 Codecs { } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--demo" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593405772594452 RawX2: 4294979628 }
2025-10-26T18:06:32.857371Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:32.865735Z node 1 :KQP_EXECUTER ERROR: TxId: 281474976715680. Ctx: { TraceId: 01k8gv6nrq5wr3vwe5tjwgyakm, Database: , DatabaseId: /Root, SessionId: ydb://session/3?node_id=1&id=YzhkNTlhNmYtNTA1MmFhOTgtMTQ5MzgyNDktNjA1NGY2ZA==, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
2025-10-26T18:06:32.867691Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:32.867746Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state PLANNING
2025-10-26T18:06:32.867762Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State PLANNING
2025-10-26T18:06:32.867794Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState PLANNED
2025-10-26T18:06:32.867814Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from PLANNING to PLANNED
2025-10-26T18:06:32.867830Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxQueue.size 1
2025-10-26T18:06:32.867850Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] New ExecStep 1761501992894, ExecTxId 281474976715677
2025-10-26T18:06:32.868983Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState CALCULATING
2025-10-26T18:06:32.869027Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from PLANNED to CALCULATING
2025-10-26T18:06:32.869101Z node 2 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--demo' partition 0. Step TInitConfigStep
2025-10-26T18:06:32.869164Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:32.869493Z node 2 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--demo' partition 0. Step TInitInternalFieldsStep
2025-10-26T18:06:32.870474Z node 2 :PERSQUEUE INFO: bootstrapping 0 [2:7565593450220018768:8384]
2025-10-26T18:06:32.873769Z node 2 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--demo' partition 0. Completed.
2025-10-26T18:06:32.873808Z node 2 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--demo' partition 0 generation 1 [2:7565593450220018768:8384]
2025-10-26T18:06:32.873838Z node 2 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--demo partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:32.875392Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:32.875636Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:32.875861Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501992894, TxId 281474976715677, Partition 0
2025-10-26T18:06:32.875881Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:32.875901Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] Partition responses 1/1
2025-10-26T18:06:32.875924Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-10-26T18:06:32.875946Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State CALCULATING
2025-10-26T18:06:32.875970Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 State CALCULATING FrontTxId 281474976715677
2025-10-26T18:06:32.875994Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-10-26T18:06:32.876019Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState CALCULATED
2025-10-26T18:06:32.876065Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from CALCULATING to CALCULATED
2025-10-26T18:06:32.876088Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715677
2025-10-26T18:06:32.876649Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] save tx TxId: 281474976715677 State: CALCULATED MinStep: 1761501992712 MaxStep: 18446744073709551615 Step: 1761501992894 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 9223372036854775807 LifetimeSeconds: 64800 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 2097152 BurstSize: 2097152 TotalPartitions: 1 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--demo" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "unknown" Ident: "unknown" Topic: "demo" DC: "dc1" ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } ReadRuleServiceTypes: "data-streams" FormatVersion: 0 Codecs { } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--demo" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593405772594452 RawX2: 4294979628 }
2025-10-26T18:06:32.876823Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:32.888376Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:32.888418Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATED
2025-10-26T18:06:32.888441Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State CALCULATED
2025-10-26T18:06:32.888465Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 State CALCULATED FrontTxId 281474976715677
2025-10-26T18:06:32.888491Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState WAIT_RS
2025-10-26T18:06:32.888515Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from CALCULATED to WAIT_RS
2025-10-26T18:06:32.888548Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-10-26T18:06:32.888569Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] HaveParticipantsDecision 1
2025-10-26T18:06:32.888603Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState EXECUTING
2025-10-26T18:06:32.888626Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from WAIT_RS to EXECUTING
2025-10-26T18:06:32.888645Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 0, Expected 1
2025-10-26T18:06:32.888843Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501992894, TxId 281474976715677
2025-10-26T18:06:32.889360Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:32.892841Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:32.892883Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1761501992894, TxId 281474976715677, Partition 0
2025-10-26T18:06:32.892911Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-10-26T18:06:32.892933Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State EXECUTING
2025-10-26T18:06:32.892960Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 State EXECUTING FrontTxId 281474976715677
2025-10-26T18:06:32.892980Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-10-26T18:06:32.893009Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId: 281474976715677 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-10-26T18:06:32.893048Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] complete TxId 281474976715677
2025-10-26T18:06:32.893566Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 9223372036854775807 LifetimeSeconds: 64800 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 2097152 BurstSize: 2097152 TotalPartitions: 1 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--demo" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "unknown" Ident: "unknown" Topic: "demo" DC: "dc1" ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } ReadRuleServiceTypes: "data-streams" FormatVersion: 0 Codecs { } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--demo" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 Important: false }
2025-10-26T18:06:32.893732Z node 2 :PERSQUEUE NOTICE: Tablet 72075186224037892 disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-26T18:06:32.893887Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] delete partitions for TxId 281474976715677
2025-10-26T18:06:32.893929Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState EXECUTED
2025-10-26T18:06:32.893998Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from EXECUTING to EXECUTED
2025-10-26T18:06:32.894035Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715677
2025-10-26T18:06:32.894628Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] save tx TxId: 281474976715677 State: EXECUTED MinStep: 1761501992712 MaxStep: 18446744073709551615 Step: 1761501992894 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 MaxSizeInPartition: 9223372036854775807 LifetimeSeconds: 64800 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 2097152 BurstSize: 2097152 TotalPartitions: 1 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--demo" Version: 0 LocalDC: true RequireAuthWrite: true RequireAuthRead: true Producer: "unknown" Ident: "unknown" Topic: "demo" DC: "dc1" ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } ReadRuleServiceTypes: "data-streams" FormatVersion: 0 Codecs { } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--demo" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593405772594452 RawX2: 4294979628 }
2025-10-26T18:06:32.894961Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
===Query complete
Create topic result: 1 
2025-10-26T18:06:32.916943Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:32.916991Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTED
2025-10-26T18:06:32.917006Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State EXECUTED
2025-10-26T18:06:32.917023Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 State EXECUTED FrontTxId 281474976715677
2025-10-26T18:06:32.917042Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TPersQueue::SendEvReadSetAckToSenders
2025-10-26T18:06:32.917072Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState WAIT_RS_ACKS
2025-10-26T18:06:32.917089Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677 moved from EXECUTED to WAIT_RS_ACKS
2025-10-26T18:06:32.917117Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] PredicateAcks: 0/0
2025-10-26T18:06:32.917125Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-10-26T18:06:32.917141Z node 2 :PERSQUEUE DEBUG: [TxId: 281474976715677] PredicateAcks: 0/0
2025-10-26T18:06:32.917161Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] add an TxId 281474976715677 to the list for deletion
2025-10-26T18:06:32.917184Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, NewState DELETING
2025-10-26T18:06:32.917212Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] delete key for TxId 281474976715677
2025-10-26T18:06:32.917287Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:32.922007Z node 1 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpModifyACL, opId: 281474976715681:0, at schemeshard:  72057594046644480
2025-10-26T18:06:32.924699Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:32.924726Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state DELETING
2025-10-26T18:06:32.924738Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976715677, State DELETING
2025-10-26T18:06:32.924758Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] delete TxId 281474976715677
2025-10-26T18:06:32.935468Z node 1 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:32.935510Z node 1 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2025-10-26T18:06:32.943656Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "12345678" }
2025-10-26T18:06:32.943845Z node 1 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "topic1" message_group_id: "12345678" from ipv6:[::1]:52244
2025-10-26T18:06:32.943862Z node 1 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:52244 proto=v1  topic=topic1 durationSec=0
2025-10-26T18:06:32.943878Z node 1 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:32.945586Z node 1 :PQ_WRITE_PROXY INFO: session v1 error cookie: 1 reason: no path 'Root/PQ/rt3.dc1--topic1', Marker# PQ15 sessionId: 
2025-10-26T18:06:32.946090Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  is DEAD
Finish: 0 
2025-10-26T18:06:32.949097Z node 1 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:32.949120Z node 1 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2025-10-26T18:06:32.949861Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } }
2025-10-26T18:06:32.950030Z node 1 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } from ipv6:[::1]:52244
2025-10-26T18:06:32.950043Z node 1 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:52244 proto=v1  topic=/Root/PQ/rt3.dc1--demo durationSec=0
2025-10-26T18:06:32.950052Z node 1 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:32.952529Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2025-10-26T18:06:32.952771Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:32.952781Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:32.952792Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:32.952809Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:32.955245Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:33.109382Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) RequestPQRB
2025-10-26T18:06:33.109890Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236644:4302] connected; active server actors: 1
2025-10-26T18:06:33.110062Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=source-id
2025-10-26T18:06:33.110092Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:33.110924Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236644:4302] disconnected; active server actors: 1
2025-10-26T18:06:33.110962Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236644:4302] disconnected no session
2025-10-26T18:06:33.223264Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:33.223344Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2025-10-26T18:06:33.223377Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593448722269298:4302] (SourceId=source-id, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:33.223419Z node 1 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-26T18:06:33.224466Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 2, Generation: 1
2025-10-26T18:06:33.225713Z node 1 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0
2025-10-26T18:06:33.224353Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236667:4302], now have 1 active actors on pipe
2025-10-26T18:06:33.224653Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.224675Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.224768Z node 2 :PERSQUEUE INFO: new Cookie source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 generated for partition 0 topic 'rt3.dc1--demo' owner source-id
2025-10-26T18:06:33.224863Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2025-10-26T18:06:33.224917Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.225380Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.225391Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.225465Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.227712Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 2 created_at_ms: 1761501993228 sent_at_ms: 1761501993228 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.233935Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.234299Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.235147Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.234796Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.234831Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.234923Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-10-26T18:06:33.235499Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.235509Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.235751Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 2 partNo : 0 messageNo: 1 size 92 offset: -1
2025-10-26T18:06:33.235945Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 2 partNo 0
2025-10-26T18:06:33.255567Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 169 count 1 nextOffset 1 batches 1
2025-10-26T18:06:33.256094Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 d0000000000_00000000000000000000_00000_0000000001_00000| size 157 WTime 1761501993255
2025-10-26T18:06:33.256278Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.259385Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.259437Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.259482Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 2, partNo: 0, Offset: 0 is stored on disk
2025-10-26T18:06:33.259504Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-10-26T18:06:33.259629Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:33.259647Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-10-26T18:06:33.259777Z node 2 :PERSQUEUE DEBUG: read cookie 0 Topic 'rt3.dc1--demo' partition 0 user user offset 0 count 1 size 1024000 endOffset 1 max time lag 0ms effective offset 0
2025-10-26T18:06:33.259795Z node 2 :PERSQUEUE DEBUG: read cookie 0 added 0 blobs, size 0 count 0 last offset 0
2025-10-26T18:06:33.259833Z node 2 :PERSQUEUE DEBUG: Reading cookie 0. All data is from uncompacted head.
2025-10-26T18:06:33.259854Z node 2 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:33.259942Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user readTimeStamp done, result 1761501993235 queuesize 0 startOffset 0
2025-10-26T18:06:33.260184Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
request: { write_request { sequence_numbers: 3 created_at_ms: 1761501993264 sent_at_ms: 1761501993264 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.264403Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  update_token_request [content omitted]
2025-10-26T18:06:33.266073Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.266330Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.266899Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.266931Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.267016Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 2  requestId: <none> cookie: 2
2025-10-26T18:06:33.267236Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.267553Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.267579Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.267626Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 3 partNo : 0 messageNo: 3 size 92 offset: -1
2025-10-26T18:06:33.267775Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 3 partNo 0
2025-10-26T18:06:33.268892Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 169 count 1 nextOffset 2 batches 1
2025-10-26T18:06:33.269199Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 1,1 HeadOffset 0 endOffset 1 curOffset 2 d0000000000_00000000000000000001_00000_0000000001_00000| size 157 WTime 1761501993268
2025-10-26T18:06:33.269330Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.273850Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.273895Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.273927Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 3, partNo: 0, Offset: 1 is stored on disk
2025-10-26T18:06:33.274087Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 3  requestId: <none> cookie: 2
2025-10-26T18:06:33.274334Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.275696Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 4 created_at_ms: 1761501993276 sent_at_ms: 1761501993276 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.276633Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.276866Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.277436Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.277469Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.277564Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 4  requestId: <none> cookie: 3
2025-10-26T18:06:33.277965Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.278382Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.278403Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.278446Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 4 partNo : 0 messageNo: 5 size 92 offset: -1
2025-10-26T18:06:33.278596Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 4 partNo 0
2025-10-26T18:06:33.280892Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 4 partNo 0 FormedBlobsCount 0 NewHead: Offset 2 PartNo 0 PackedSize 169 count 1 nextOffset 3 batches 1
2025-10-26T18:06:33.281276Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 2,1 HeadOffset 0 endOffset 2 curOffset 3 d0000000000_00000000000000000002_00000_0000000001_00000| size 157 WTime 1761501993280
2025-10-26T18:06:33.281420Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.284519Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.284574Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.284603Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 4, partNo: 0, Offset: 2 is stored on disk
2025-10-26T18:06:33.284756Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 5  requestId: <none> cookie: 3
2025-10-26T18:06:33.285245Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.286590Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 5 created_at_ms: 1761501993287 sent_at_ms: 1761501993287 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.287565Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.287778Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.288323Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.288351Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.288441Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 6  requestId: <none> cookie: 4
2025-10-26T18:06:33.288784Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.289160Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.289178Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.289225Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 5 partNo : 0 messageNo: 7 size 92 offset: -1
2025-10-26T18:06:33.289376Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 5 partNo 0
2025-10-26T18:06:33.293581Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 5 partNo 0 FormedBlobsCount 0 NewHead: Offset 3 PartNo 0 PackedSize 169 count 1 nextOffset 4 batches 1
2025-10-26T18:06:33.294033Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 3,1 HeadOffset 0 endOffset 3 curOffset 4 d0000000000_00000000000000000003_00000_0000000001_00000| size 157 WTime 1761501993292
2025-10-26T18:06:33.294185Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.297494Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.296913Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.296949Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.296979Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 5, partNo: 0, Offset: 3 is stored on disk
2025-10-26T18:06:33.297156Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 7  requestId: <none> cookie: 4
2025-10-26T18:06:33.298872Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read done: success: 0 data: 
2025-10-26T18:06:33.298904Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 grpc read failed
2025-10-26T18:06:33.299065Z node 1 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0
2025-10-26T18:06:33.299081Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source-id|d53d5f79-28a2fa46-bc2b1859-5c5ae08a_0 is DEAD
2025-10-26T18:06:33.299483Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
1 0 
2025-10-26T18:06:33.300284Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236667:4302] destroyed
2025-10-26T18:06:33.300337Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-10-26T18:06:33.302026Z node 1 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:33.302053Z node 1 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2025-10-26T18:06:33.302467Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId:  grpc read done: success: 1 data: init_request { topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } }
2025-10-26T18:06:33.302610Z node 1 :PQ_WRITE_PROXY INFO: session request cookie: 3 topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } from ipv6:[::1]:52244
2025-10-26T18:06:33.302624Z node 1 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:52244 proto=v1  topic=/Root/PQ/rt3.dc1--demo durationSec=0
2025-10-26T18:06:33.302632Z node 1 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:33.303962Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2025-10-26T18:06:33.304130Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.304143Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.304151Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.304179Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236678:4313] (SourceId=source-id, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:33.306053Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236678:4313] (SourceId=source-id, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:33.315314Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236678:4313] (SourceId=source-id, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:33.328828Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236678:4313] (SourceId=source-id, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:33.328875Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236678:4313] (SourceId=source-id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-10-26T18:06:33.328891Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236678:4313] (SourceId=source-id, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:33.328918Z node 1 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-26T18:06:33.330276Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236703:4313], now have 1 active actors on pipe
2025-10-26T18:06:33.330534Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 2, Generation: 1
2025-10-26T18:06:33.330811Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.330837Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.330922Z node 2 :PERSQUEUE INFO: new Cookie source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 generated for partition 0 topic 'rt3.dc1--demo' owner source-id
2025-10-26T18:06:33.331005Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2025-10-26T18:06:33.331053Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.331655Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.331672Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.331734Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.332052Z node 1 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 0 MaxSeqNo: 5 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.333772Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 6 created_at_ms: 1761501993334 sent_at_ms: 1761501993334 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.334771Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.334998Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.335442Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.335468Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.335538Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-10-26T18:06:33.335928Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.336904Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.336926Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.336969Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 6 partNo : 0 messageNo: 1 size 92 offset: -1
2025-10-26T18:06:33.337120Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 6 partNo 0
2025-10-26T18:06:33.339064Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 6 partNo 0 FormedBlobsCount 0 NewHead: Offset 4 PartNo 0 PackedSize 169 count 1 nextOffset 5 batches 1
2025-10-26T18:06:33.339493Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 4,1 HeadOffset 0 endOffset 4 curOffset 5 d0000000000_00000000000000000004_00000_0000000001_00000| size 157 WTime 1761501993339
2025-10-26T18:06:33.339651Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.344693Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.344734Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.344767Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 6, partNo: 0, Offset: 4 is stored on disk
2025-10-26T18:06:33.344919Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 1  requestId: <none> cookie: 1
update user token request: { update_token_request { token: "x-user-x@builtin" } }
request: { write_request { sequence_numbers: 7 created_at_ms: 1761501993347 sent_at_ms: 1761501993347 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.348317Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.348347Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.348430Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 2  requestId: <none> cookie: 2
2025-10-26T18:06:33.345565Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.346948Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  update_token_request [content omitted]
2025-10-26T18:06:33.349018Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.347778Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.347976Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.349038Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.349080Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 7 partNo : 0 messageNo: 3 size 92 offset: -1
2025-10-26T18:06:33.348675Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.349225Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 7 partNo 0
2025-10-26T18:06:33.351045Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 7 partNo 0 FormedBlobsCount 0 NewHead: Offset 5 PartNo 0 PackedSize 169 count 1 nextOffset 6 batches 1
2025-10-26T18:06:33.351453Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 5,1 HeadOffset 0 endOffset 5 curOffset 6 d0000000000_00000000000000000005_00000_0000000001_00000| size 157 WTime 1761501993350
2025-10-26T18:06:33.351593Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.355434Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.355473Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.355504Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 7, partNo: 0, Offset: 5 is stored on disk
2025-10-26T18:06:33.355663Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 3  requestId: <none> cookie: 2
2025-10-26T18:06:33.356061Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.357384Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 8 created_at_ms: 1761501993357 sent_at_ms: 1761501993357 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.358214Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.358410Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.359792Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.359821Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.359895Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 4  requestId: <none> cookie: 3
2025-10-26T18:06:33.363197Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.363685Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.363713Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.363758Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 8 partNo : 0 messageNo: 5 size 92 offset: -1
2025-10-26T18:06:33.363968Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 8 partNo 0
2025-10-26T18:06:33.411404Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 8 partNo 0 FormedBlobsCount 0 NewHead: Offset 6 PartNo 0 PackedSize 169 count 1 nextOffset 7 batches 1
2025-10-26T18:06:33.411839Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 6,1 HeadOffset 0 endOffset 6 curOffset 7 d0000000000_00000000000000000006_00000_0000000001_00000| size 157 WTime 1761501993411
2025-10-26T18:06:33.412030Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.416652Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.416697Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.416735Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 8, partNo: 0, Offset: 6 is stored on disk
2025-10-26T18:06:33.416912Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 5  requestId: <none> cookie: 3
2025-10-26T18:06:33.417345Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.419234Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 9 created_at_ms: 1761501993419 sent_at_ms: 1761501993419 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.420181Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.420402Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.420788Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.420819Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.420895Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 6  requestId: <none> cookie: 4
2025-10-26T18:06:33.425834Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.426465Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.426499Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.426549Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 9 partNo : 0 messageNo: 7 size 92 offset: -1
2025-10-26T18:06:33.426721Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 9 partNo 0
2025-10-26T18:06:33.428598Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 9 partNo 0 FormedBlobsCount 0 NewHead: Offset 7 PartNo 0 PackedSize 169 count 1 nextOffset 8 batches 1
2025-10-26T18:06:33.429022Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 7,1 HeadOffset 0 endOffset 7 curOffset 8 d0000000000_00000000000000000007_00000_0000000001_00000| size 157 WTime 1761501993428
2025-10-26T18:06:33.429172Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.432141Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.432178Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.432208Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 9, partNo: 0, Offset: 7 is stored on disk
2025-10-26T18:06:33.432392Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 7  requestId: <none> cookie: 4
2025-10-26T18:06:33.432820Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.433962Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read done: success: 0 data: 
2025-10-26T18:06:33.433981Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 grpc read failed
2025-10-26T18:06:33.434135Z node 1 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0
2025-10-26T18:06:33.434150Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: source-id|33077deb-8f511aa2-24d4be2b-c68aeea0_0 is DEAD
2025-10-26T18:06:33.434486Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
1 0 
2025-10-26T18:06:33.434958Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236703:4313] destroyed
2025-10-26T18:06:33.434996Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-10-26T18:06:33.436220Z node 1 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:33.436247Z node 1 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2025-10-26T18:06:33.436643Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } }
2025-10-26T18:06:33.436778Z node 1 :PQ_WRITE_PROXY INFO: session request cookie: 4 topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } from ipv6:[::1]:52244
2025-10-26T18:06:33.436796Z node 1 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:52244 proto=v1  topic=/Root/PQ/rt3.dc1--demo durationSec=0
2025-10-26T18:06:33.436808Z node 1 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:33.438159Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2025-10-26T18:06:33.438315Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.438323Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.438331Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.438345Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236716:4296] (SourceId=source-id, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:33.440297Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236716:4296] (SourceId=source-id, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:33.448211Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236716:4296] (SourceId=source-id, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:33.456534Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236716:4296] (SourceId=source-id, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:33.456581Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236716:4296] (SourceId=source-id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-10-26T18:06:33.456598Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236716:4296] (SourceId=source-id, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:33.456630Z node 1 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-26T18:06:33.457278Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236742:4296], now have 1 active actors on pipe
2025-10-26T18:06:33.457472Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 2, Generation: 1
2025-10-26T18:06:33.457743Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.457770Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.457842Z node 2 :PERSQUEUE INFO: new Cookie source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 generated for partition 0 topic 'rt3.dc1--demo' owner source-id
2025-10-26T18:06:33.457919Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2025-10-26T18:06:33.457974Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.458390Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.458411Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.458480Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.458703Z node 1 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 0 MaxSeqNo: 9 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.459981Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 10 created_at_ms: 1761501993460 sent_at_ms: 1761501993460 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.460939Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.461148Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.461679Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.461723Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.461797Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-10-26T18:06:33.462082Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.462445Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.462463Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.462505Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 10 partNo : 0 messageNo: 1 size 92 offset: -1
2025-10-26T18:06:33.462645Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 10 partNo 0
2025-10-26T18:06:33.465020Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 10 partNo 0 FormedBlobsCount 0 NewHead: Offset 8 PartNo 0 PackedSize 169 count 1 nextOffset 9 batches 1
2025-10-26T18:06:33.465440Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 8,1 HeadOffset 0 endOffset 8 curOffset 9 d0000000000_00000000000000000008_00000_0000000001_00000| size 157 WTime 1761501993465
2025-10-26T18:06:33.465608Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.470550Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.470596Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.470642Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 10, partNo: 0, Offset: 8 is stored on disk
2025-10-26T18:06:33.470827Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-10-26T18:06:33.471553Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.473705Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 11 created_at_ms: 1761501993474 sent_at_ms: 1761501993474 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.474500Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.474745Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.475148Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.475178Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.475269Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 2  requestId: <none> cookie: 2
2025-10-26T18:06:33.475621Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.475954Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.475975Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.476022Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 11 partNo : 0 messageNo: 3 size 92 offset: -1
2025-10-26T18:06:33.476178Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 11 partNo 0
2025-10-26T18:06:33.498383Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 11 partNo 0 FormedBlobsCount 0 NewHead: Offset 9 PartNo 0 PackedSize 169 count 1 nextOffset 10 batches 1
2025-10-26T18:06:33.498823Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 9,1 HeadOffset 0 endOffset 9 curOffset 10 d0000000000_00000000000000000009_00000_0000000001_00000| size 157 WTime 1761501993498
2025-10-26T18:06:33.498997Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.502869Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.502918Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.502953Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 11, partNo: 0, Offset: 9 is stored on disk
2025-10-26T18:06:33.503151Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 3  requestId: <none> cookie: 2
2025-10-26T18:06:33.503519Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.505198Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 12 created_at_ms: 1761501993505 sent_at_ms: 1761501993505 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.506245Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.507027Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.507060Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.507137Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 4  requestId: <none> cookie: 3
2025-10-26T18:06:33.506537Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.507449Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.508078Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.508103Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.508148Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 12 partNo : 0 messageNo: 5 size 92 offset: -1
2025-10-26T18:06:33.508303Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 12 partNo 0
2025-10-26T18:06:33.509813Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 12 partNo 0 FormedBlobsCount 0 NewHead: Offset 10 PartNo 0 PackedSize 169 count 1 nextOffset 11 batches 1
2025-10-26T18:06:33.510223Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 10,1 HeadOffset 0 endOffset 10 curOffset 11 d0000000000_00000000000000000010_00000_0000000001_00000| size 157 WTime 1761501993509
2025-10-26T18:06:33.510385Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.514766Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.514810Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.514845Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 12, partNo: 0, Offset: 10 is stored on disk
2025-10-26T18:06:33.515022Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 5  requestId: <none> cookie: 3
2025-10-26T18:06:33.515561Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
request: { write_request { sequence_numbers: 13 created_at_ms: 1761501993519 sent_at_ms: 1761501993519 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.518680Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  update_token_request [content omitted]
2025-10-26T18:06:33.519414Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.519625Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.520162Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.520198Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.520353Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 6  requestId: <none> cookie: 4
2025-10-26T18:06:33.524280Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.524765Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.524798Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.524910Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 13 partNo : 0 messageNo: 7 size 92 offset: -1
2025-10-26T18:06:33.525089Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 13 partNo 0
2025-10-26T18:06:33.526696Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 13 partNo 0 FormedBlobsCount 0 NewHead: Offset 11 PartNo 0 PackedSize 169 count 1 nextOffset 12 batches 1
2025-10-26T18:06:33.527115Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 11,1 HeadOffset 0 endOffset 11 curOffset 12 d0000000000_00000000000000000011_00000_0000000001_00000| size 157 WTime 1761501993527
2025-10-26T18:06:33.527265Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.531181Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.531228Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.531262Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 13, partNo: 0, Offset: 11 is stored on disk
2025-10-26T18:06:33.531741Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 7  requestId: <none> cookie: 4
2025-10-26T18:06:33.533877Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.535912Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read done: success: 0 data: 
2025-10-26T18:06:33.535937Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 grpc read failed
2025-10-26T18:06:33.536096Z node 1 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0
2025-10-26T18:06:33.536110Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source-id|85adeaf3-2ef4c171-9b0e3a22-3d387bef_0 is DEAD
2025-10-26T18:06:33.536404Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
1 0 
2025-10-26T18:06:33.536844Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236742:4296] destroyed
2025-10-26T18:06:33.536894Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-10-26T18:06:33.538234Z node 1 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:33.538256Z node 1 :PQ_WRITE_PROXY DEBUG: new session created cookie 5
2025-10-26T18:06:33.538687Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId:  grpc read done: success: 1 data: init_request { topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } }
2025-10-26T18:06:33.538809Z node 1 :PQ_WRITE_PROXY INFO: session request cookie: 5 topic: "/Root/PQ/rt3.dc1--demo" message_group_id: "source-id" session_meta { key: "key" value: "value" } from ipv6:[::1]:52244
2025-10-26T18:06:33.538821Z node 1 :PQ_WRITE_PROXY INFO: write session:  cookie=5 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:52244 proto=v1  topic=/Root/PQ/rt3.dc1--demo durationSec=0
2025-10-26T18:06:33.538828Z node 1 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:33.540175Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId:  describe result for acl check
2025-10-26T18:06:33.540331Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.540339Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.540348Z node 1 :PQ_PARTITION_CHOOSER DEBUG: 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-26T18:06:33.540366Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236754:4337] (SourceId=source-id, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:33.542424Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236754:4337] (SourceId=source-id, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:33.550620Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236754:4337] (SourceId=source-id, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:33.560212Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236754:4337] (SourceId=source-id, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:33.560244Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236754:4337] (SourceId=source-id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-10-26T18:06:33.560255Z node 1 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [1:7565593453017236754:4337] (SourceId=source-id, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:33.560275Z node 1 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 5 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-26T18:06:33.561589Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 2, Generation: 1
2025-10-26T18:06:33.561759Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236776:4337], now have 1 active actors on pipe
2025-10-26T18:06:33.561832Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.561849Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.561904Z node 2 :PERSQUEUE INFO: new Cookie source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 generated for partition 0 topic 'rt3.dc1--demo' owner source-id
2025-10-26T18:06:33.561973Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2025-10-26T18:06:33.562021Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.562441Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.562459Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.562563Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.562768Z node 1 :PQ_WRITE_PROXY INFO: session inited cookie: 5 partition: 0 MaxSeqNo: 13 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.563907Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 14 created_at_ms: 1761501993564 sent_at_ms: 1761501993564 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.564573Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.564796Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.565037Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.565064Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.565131Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-10-26T18:06:33.565278Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.565529Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.565558Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.565601Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 14 partNo : 0 messageNo: 1 size 92 offset: -1
2025-10-26T18:06:33.565767Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 14 partNo 0
2025-10-26T18:06:33.582081Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 14 partNo 0 FormedBlobsCount 0 NewHead: Offset 12 PartNo 0 PackedSize 169 count 1 nextOffset 13 batches 1
2025-10-26T18:06:33.582531Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 12,1 HeadOffset 0 endOffset 12 curOffset 13 d0000000000_00000000000000000012_00000_0000000001_00000| size 157 WTime 1761501993581
2025-10-26T18:06:33.582724Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.585941Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.585988Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.586018Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 14, partNo: 0, Offset: 12 is stored on disk
2025-10-26T18:06:33.586198Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-10-26T18:06:33.586667Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.589330Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 15 created_at_ms: 1761501993589 sent_at_ms: 1761501993589 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.590138Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.590343Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.590659Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.590698Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.590784Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 2  requestId: <none> cookie: 2
2025-10-26T18:06:33.591346Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.591878Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.591899Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.591942Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 15 partNo : 0 messageNo: 3 size 92 offset: -1
2025-10-26T18:06:33.592104Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 15 partNo 0
2025-10-26T18:06:33.594052Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 15 partNo 0 FormedBlobsCount 0 NewHead: Offset 13 PartNo 0 PackedSize 169 count 1 nextOffset 14 batches 1
2025-10-26T18:06:33.594718Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 0,14 HeadOffset 0 endOffset 13 curOffset 14 d0000000000_00000000000000000000_00000_0000000014_00000| size 2198 WTime 1761501993594
2025-10-26T18:06:33.595013Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.600545Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.600584Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.600626Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 15, partNo: 0, Offset: 13 is stored on disk
2025-10-26T18:06:33.600781Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 3  requestId: <none> cookie: 2
2025-10-26T18:06:33.601223Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.602598Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 16 created_at_ms: 1761501993602 sent_at_ms: 1761501993602 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.603533Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.603763Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.605081Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.605111Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.605190Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 4  requestId: <none> cookie: 3
2025-10-26T18:06:33.608391Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.608801Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.608829Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.609009Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 16 partNo : 0 messageNo: 5 size 92 offset: -1
2025-10-26T18:06:33.609188Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 16 partNo 0
2025-10-26T18:06:33.610748Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 16 partNo 0 FormedBlobsCount 0 NewHead: Offset 14 PartNo 0 PackedSize 169 count 1 nextOffset 15 batches 1
2025-10-26T18:06:33.611148Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 14,1 HeadOffset 0 endOffset 14 curOffset 15 d0000000000_00000000000000000014_00000_0000000001_00000| size 157 WTime 1761501993611
2025-10-26T18:06:33.611295Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.615273Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.615314Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.615348Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 16, partNo: 0, Offset: 14 is stored on disk
2025-10-26T18:06:33.615513Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 5  requestId: <none> cookie: 3
2025-10-26T18:06:33.615936Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
update user token request: { update_token_request { token: "x-user-x@builtin" } }
2025-10-26T18:06:33.617183Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 17 created_at_ms: 1761501993617 sent_at_ms: 1761501993617 message_sizes: 4 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 4 blocks_headers: "\000" blocks_data: "data" } }
2025-10-26T18:06:33.618303Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:33.618563Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:33.618943Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.618974Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.619053Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 6  requestId: <none> cookie: 4
2025-10-26T18:06:33.619375Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.619696Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.619715Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.619757Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--demo partition: 0 SourceId: '\0source-id' SeqNo: 17 partNo : 0 messageNo: 7 size 92 offset: -1
2025-10-26T18:06:33.619908Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob processing sourceId '\0source-id' seqNo 17 partNo 0
2025-10-26T18:06:33.621433Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 part blob complete sourceId '\0source-id' seqNo 17 partNo 0 FormedBlobsCount 0 NewHead: Offset 15 PartNo 0 PackedSize 169 count 1 nextOffset 16 batches 1
2025-10-26T18:06:33.621860Z node 2 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--demo' partition 0 compactOffset 15,1 HeadOffset 0 endOffset 15 curOffset 16 d0000000000_00000000000000000015_00000_0000000001_00000| size 157 WTime 1761501993621
2025-10-26T18:06:33.622006Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.625027Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 102 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.625082Z node 2 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2025-10-26T18:06:33.625111Z node 2 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source-id', Topic: 'rt3.dc1--demo', Partition: 0, SeqNo: 17, partNo: 0, Offset: 15 is stored on disk
2025-10-26T18:06:33.625262Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 7  requestId: <none> cookie: 4
2025-10-26T18:06:33.625553Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2025-10-26T18:06:33.626650Z node 1 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read done: success: 0 data: 
2025-10-26T18:06:33.626667Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 grpc read failed
2025-10-26T18:06:33.626818Z node 1 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0
2025-10-26T18:06:33.626832Z node 1 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: source-id|919f5b95-58910618-ad4c51dc-241bf3ba_0 is DEAD
2025-10-26T18:06:33.627125Z node 1 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
1 0 
2025-10-26T18:06:33.630752Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236776:4337] destroyed
2025-10-26T18:06:33.630817Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-10-26T18:06:33.637673Z :INFO: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] Starting read session
2025-10-26T18:06:33.637753Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] Starting session to cluster null (localhost:17330)
2025-10-26T18:06:33.638976Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] In Reconnect, ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.639011Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] New values: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.639040Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] Reconnecting session to cluster null in 0.000000s
2025-10-26T18:06:33.643967Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] Successfully connected. Initializing session
2025-10-26T18:06:33.646185Z node 1 :PQ_READ_PROXY DEBUG: new grpc connection
2025-10-26T18:06:33.646215Z node 1 :PQ_READ_PROXY DEBUG: new session created cookie 1
2025-10-26T18:06:33.647541Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { topic: "demo" } read_only_original: true consumer: "user" read_params { max_read_size: 104857600 } } }
2025-10-26T18:06:33.647817Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 read init: from# ipv6:[::1]:52264, request# { init_request { topics_read_settings { topic: "demo" } read_only_original: true consumer: "user" read_params { max_read_size: 104857600 } } }
2025-10-26T18:06:33.648296Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 auth for : user
2025-10-26T18:06:33.648924Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 Handle describe topics response
2025-10-26T18:06:33.649074Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 auth is DEAD
2025-10-26T18:06:33.649163Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 auth ok: topics# 1, initDone# 0
2025-10-26T18:06:33.650195Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 register session: topic# rt3.dc1--demo
2025-10-26T18:06:33.650978Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236793:4346] connected; active server actors: 1
2025-10-26T18:06:33.651079Z node 1 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--demo consumer "user" register session for pipe [1:7565593453017236793:4346] session shared/user_1_1_4195187847210434545_v1
2025-10-26T18:06:33.651142Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user register readable partition 0
2025-10-26T18:06:33.651214Z :INFO: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] Server session id: shared/user_1_1_4195187847210434545_v1
2025-10-26T18:06:33.651213Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user family created family=1 (Status=Free, Partitions=[0])
2025-10-26T18:06:33.651270Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo consumer user register reading session ReadingSession "shared/user_1_1_4195187847210434545_v1" (Sender=[1:7565593453017236790:4346], Pipe=[1:7565593453017236793:4346], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:33.651302Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user rebalancing was scheduled
2025-10-26T18:06:33.651358Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing. Sessions=1, Families=1, UnradableFamilies=1 [1 (0), ], RequireBalancing=0 []
2025-10-26T18:06:33.651416Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing family=1 (Status=Free, Partitions=[0]) for ReadingSession "shared/user_1_1_4195187847210434545_v1" (Sender=[1:7565593453017236790:4346], Pipe=[1:7565593453017236793:4346], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:33.651532Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo consumer user family 1 status Active partitions [0] session "shared/user_1_1_4195187847210434545_v1" sender [1:7565593453017236790:4346] lock partition 0 for ReadingSession "shared/user_1_1_4195187847210434545_v1" (Sender=[1:7565593453017236790:4346], Pipe=[1:7565593453017236793:4346], Partitions=[], ActiveFamilyCount=1) generation 1 step 1
2025-10-26T18:06:33.651607Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user start rebalancing. familyCount=1, sessionCount=1, desiredFamilyCount=1, allowPlusOne=0
2025-10-26T18:06:33.651638Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing duration: 0.000249s
2025-10-26T18:06:33.652472Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 assign: record# { Partition: 0 TabletId: 72075186224037892 Topic: "rt3.dc1--demo" Generation: 1 Step: 1 Session: "shared/user_1_1_4195187847210434545_v1" ClientId: "user" PipeClient { RawX1: 7565593453017236793 RawX2: 4503603922342138 } Path: "/Root/PQ/rt3.dc1--demo" }
2025-10-26T18:06:33.652560Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 grpc read done: success# 1, data# { read { } }
2025-10-26T18:06:33.652678Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 got read request: guid# 83065c58-6eaa7cff-dd1e9440-53e550a7
2025-10-26T18:06:33.652778Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 INITING TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)
2025-10-26T18:06:33.653097Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.653852Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:33.653732Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236796:4334], now have 1 active actors on pipe
2025-10-26T18:06:33.654002Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.654027Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.654050Z node 2 :PERSQUEUE DEBUG: Created session shared/user_1_1_4195187847210434545_v1 on pipe: [1:7565593453017236796:4334]
2025-10-26T18:06:33.654172Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user session is set to 0 (startOffset 0) session shared/user_1_1_4195187847210434545_v1
2025-10-26T18:06:33.654192Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_1_1_4195187847210434545_v1:1 with generation 1
2025-10-26T18:06:33.654309Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.656797Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.656864Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:33.663676Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 16 WriteTimestampMS: 1761501993235 CreateTimestampMS: 1761501993228 SizeLag: 2512 WriteTimestampEstimateMS: 1761501993630 } Cookie: 18446744073709551615 }
2025-10-26T18:06:33.663739Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 INIT DONE TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 readOffset 0 committedOffset 0
2025-10-26T18:06:33.663844Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 sending to client partition status
TCreatePartitionStreamEvent: CreatePartitionStream { PartitionStreamId: 1 TopicPath: demo Cluster: dc1 PartitionId: 0 CommittedOffset: 0 EndOffset: 16 }
2025-10-26T18:06:33.664710Z :INFO: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] Confirm partition stream create. Partition stream id: 1. Cluster: "dc1". Topic: "demo". Partition: 0. Read offset: (empty maybe)
2025-10-26T18:06:33.665270Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 grpc read done: success# 1, data# { start_read { topic { path: "demo" } cluster: "dc1" assign_id: 1 } }
2025-10-26T18:06:33.666009Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 0, commitOffset# 0
2025-10-26T18:06:33.666106Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 Start reading TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 readOffset 0 committedOffset 0 clientCommitOffset 0 clientReadOffset 0
2025-10-26T18:06:33.666134Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) ready for read with readOffset 0 endOffset 16
2025-10-26T18:06:33.666205Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 0, endOffset# 16, WTime# 1761501993235, sizeLag# 2512
2025-10-26T18:06:33.666224Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1TEvPartitionReady. Aval parts: 1
2025-10-26T18:06:33.666277Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 performing read request: guid# 83065c58-6eaa7cff-dd1e9440-53e550a7, from# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), count# 19, size# 3014, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-26T18:06:33.666360Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 READ FROM TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)maxCount 19 maxSize 3014 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 16 ClientCommitOffset 0 committedOffset 0 Guid 83065c58-6eaa7cff-dd1e9440-53e550a7
2025-10-26T18:06:33.666910Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user Reading of the partition 0 was started by user.
2025-10-26T18:06:33.667139Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.667173Z node 2 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2025-10-26T18:06:33.667176Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.667279Z node 2 :PERSQUEUE DEBUG: read cookie 1 Topic 'rt3.dc1--demo' partition 0 user user offset 0 count 19 size 3014 endOffset 16 max time lag 0ms effective offset 0
2025-10-26T18:06:33.667297Z node 2 :PERSQUEUE DEBUG: read cookie 1 added 0 blobs, size 0 count 0 last offset 0
2025-10-26T18:06:33.667394Z node 2 :PERSQUEUE DEBUG: Reading cookie 1. All data is from uncompacted head.
2025-10-26T18:06:33.667421Z node 2 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:33.667657Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:33.670054Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 16 Result { Offset: 0 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 2 WriteTimestampMS: 1761501993235 CreateTimestampMS: 1761501993228 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 1 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 3 WriteTimestampMS: 1761501993267 CreateTimestampMS: 1761501993264 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 2 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 4 WriteTimestampMS: 1761501993278 CreateTimestampMS: 1761501993276 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 3 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 5 WriteTimestampMS: 1761501993288 CreateTimestampMS: 1761501993287 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 4 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 6 WriteTimestampMS: 1761501993336 CreateTimestampMS: 1761501993334 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 5 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 7 WriteTimestampMS: 1761501993348 CreateTimestampMS: 1761501993347 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 6 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 8 WriteTimestampMS: 1761501993362 CreateTimestampMS: 1761501993357 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 7 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 9 WriteTimestampMS: 1761501993425 CreateTimestampMS: 1761501993419 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 8 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 10 WriteTimestampMS: 1761501993462 CreateTimestampMS: 1761501993460 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 9 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 11 WriteTimestampMS: 1761501993472 CreateTimestampMS: 1761501993474 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 10 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 12 WriteTimestampMS: 1761501993508 CreateTimestampMS: 1761501993505 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 11 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 13 WriteTimestampMS: 1761501993525 CreateTimestampMS: 1761501993519 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 12 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 14 WriteTimestampMS: 1761501993565 CreateTimestampMS: 1761501993564 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 13 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 15 WriteTimestampMS: 1761501993591 CreateTimestampMS: 1761501993589 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 14 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 16 WriteTimestampMS: 1761501993609 CreateTimestampMS: 1761501993602 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 15 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 17 WriteTimestampMS: 1761501993619 CreateTimestampMS: 1761501993617 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 320 RealReadOffset: 15 WaitQuotaTimeMs: 0 } Cookie: 0 }
2025-10-26T18:06:33.670525Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) wait data in partition inited, cookie 1 from offset16
2025-10-26T18:06:33.670557Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 after read state TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 ReadOffset 16 ReadGuid 83065c58-6eaa7cff-dd1e9440-53e550a7 has messages 1
2025-10-26T18:06:33.670643Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 read done: guid# 83065c58-6eaa7cff-dd1e9440-53e550a7, partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), size# 2314
2025-10-26T18:06:33.670675Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 response to read: guid# 83065c58-6eaa7cff-dd1e9440-53e550a7
2025-10-26T18:06:33.670846Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 Process answer. Aval parts: 0
2025-10-26T18:06:33.671792Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.672193Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 grpc read done: success# 1, data# { read { } }
2025-10-26T18:06:33.672309Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 got read request: guid# e99695d0-caca59bd-535c3a10-5661f77f
2025-10-26T18:06:33.672471Z :DEBUG: [] Decompression task done. Partition/PartitionSessionId: 0 (0-15)
2025-10-26T18:06:33.689848Z :DEBUG: [] Take Data. Partition 0. Read: {0, 0} (0-0)
2025-10-26T18:06:33.689918Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] The application data is transferred to the client. Number of messages 1, size 4 bytes
TDataReceivedEvent: DataReceived { PartitionStreamId: 1 PartitionId: 0 Message { Data: ..4 bytes.. Partition stream id: 1 Cluster: "dc1". Topic: "demo" Partition: 0 PartitionKey: "" Information: { Offset: 0 SeqNo: 2 MessageGroupId: "source-id" CreateTime: 2025-10-26T18:06:33.228000Z WriteTime: 2025-10-26T18:06:33.235000Z Ip: "ipv6:[::1]:52244" UncompressedSize: 4 Meta: { "ident": "unknown", "key": "value", "logtype": "unknown", "server": "ipv6:[::1]:52244" } } } }
2025-10-26T18:06:33.690052Z :DEBUG: [] Take Data. Partition 0. Read: {1, 0} (1-1)
2025-10-26T18:06:33.690089Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] The application data is transferred to the client. Number of messages 1, size 4 bytes
TDataReceivedEvent: DataReceived { PartitionStreamId: 1 PartitionId: 0 Message { Data: ..4 bytes.. Partition stream id: 1 Cluster: "dc1". Topic: "demo" Partition: 0 PartitionKey: "" Information: { Offset: 1 SeqNo: 3 MessageGroupId: "source-id" CreateTime: 2025-10-26T18:06:33.264000Z WriteTime: 2025-10-26T18:06:33.267000Z Ip: "ipv6:[::1]:52244" UncompressedSize: 4 Meta: { "ident": "unknown", "key": "value", "logtype": "unknown", "server": "ipv6:[::1]:52244" } } } }
2025-10-26T18:06:33.715300Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236836:8664], now have 1 active actors on pipe
2025-10-26T18:06:33.715719Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7565593453017236833 RawX2: 4503603922342113 } TxId: 281474976715690 Data { Operations { PartitionId: 0 Begin: 0 End: 2 Consumer: "user" Path: "/Root/PQ/rt3.dc1--demo" } Op: Commit SendingShards: 72075186224037892 ReceivingShards: 72075186224037892 Immediate: true }
2025-10-26T18:06:33.715765Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] immediate transaction
2025-10-26T18:06:33.715875Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::CommitWriteOperations TxId: (empty maybe)
2025-10-26T18:06:33.715909Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] schedule TEvPersQueue::TEvProposeTransactionResult(COMPLETE), reason=
2025-10-26T18:06:33.716076Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.719585Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.719671Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTransactionCompleted WriteId (empty maybe)
2025-10-26T18:06:33.739835Z :INFO: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] Closing read session. Close timeout: 0.000000s
2025-10-26T18:06:33.739895Z :INFO: [] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): null:demo:0:1:15:0
2025-10-26T18:06:33.739927Z :INFO: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] Counters: { Errors: 0 CurrentSessionLifetimeMs: 102 BytesRead: 64 MessagesRead: 16 BytesReadCompressed: 64 BytesInflightUncompressed: 56 BytesInflightCompressed: 0 BytesInflightTotal: 56 MessagesInflight: 14 }
2025-10-26T18:06:33.740055Z :NOTICE: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Close with zero timeout " }
2025-10-26T18:06:33.740363Z :DEBUG: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] [null] Abort session to cluster
2025-10-26T18:06:33.740872Z :NOTICE: [] [] [d915f3d0-ef2d3df9-98804ae8-32297ef3] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Aborted " }
2025-10-26T18:06:33.746883Z node 1 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 grpc read done: success# 0, data# {  }
2025-10-26T18:06:33.746916Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 grpc read failed
2025-10-26T18:06:33.746943Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 grpc closed
2025-10-26T18:06:33.746972Z node 1 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_1_1_4195187847210434545_v1 is DEAD
2025-10-26T18:06:33.755214Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236793:4346] disconnected; active server actors: 1
2025-10-26T18:06:33.757186Z node 2 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_1_1_4195187847210434545_v1
2025-10-26T18:06:33.757239Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236796:4334] destroyed
2025-10-26T18:06:33.758924Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_1_1_4195187847210434545_v1
2025-10-26T18:06:33.755248Z node 1 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236793:4346] client user disconnected session shared/user_1_1_4195187847210434545_v1
2025-10-26T18:06:33.766012Z :INFO: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] Starting read session
2025-10-26T18:06:33.766067Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] Starting session to cluster null (localhost:17330)
2025-10-26T18:06:33.767432Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] In Reconnect, ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.767467Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] New values: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.767504Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] Reconnecting session to cluster null in 0.000000s
2025-10-26T18:06:33.779610Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] Successfully connected. Initializing session
2025-10-26T18:06:33.782328Z node 1 :PQ_READ_PROXY DEBUG: new grpc connection
2025-10-26T18:06:33.782357Z node 1 :PQ_READ_PROXY DEBUG: new session created cookie 2
2025-10-26T18:06:33.782909Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { topic: "demo" } read_only_original: true consumer: "user" read_params { max_read_size: 104857600 } } }
2025-10-26T18:06:33.783095Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 read init: from# ipv6:[::1]:52320, request# { init_request { topics_read_settings { topic: "demo" } read_only_original: true consumer: "user" read_params { max_read_size: 104857600 } } }
2025-10-26T18:06:33.783414Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 auth for : user
2025-10-26T18:06:33.783837Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 Handle describe topics response
2025-10-26T18:06:33.783946Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 auth is DEAD
2025-10-26T18:06:33.784029Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 auth ok: topics# 1, initDone# 0
2025-10-26T18:06:33.784848Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 register session: topic# rt3.dc1--demo
2025-10-26T18:06:33.785081Z :INFO: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] Server session id: shared/user_1_2_240122148395822027_v1
2025-10-26T18:06:33.785335Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.785565Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc read done: success# 1, data# { read { } }
2025-10-26T18:06:33.785732Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 got read request: guid# 4dc72014-1f2825b0-23526a86-3466836b
2025-10-26T18:06:33.785793Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236852:4322] connected; active server actors: 1
2025-10-26T18:06:33.785823Z node 1 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--demo consumer "user" register session for pipe [1:7565593453017236852:4322] session shared/user_1_2_240122148395822027_v1
2025-10-26T18:06:33.785852Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user register readable partition 0
2025-10-26T18:06:33.785894Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user family created family=1 (Status=Free, Partitions=[0])
2025-10-26T18:06:33.785928Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo consumer user register reading session ReadingSession "shared/user_1_2_240122148395822027_v1" (Sender=[1:7565593453017236849:4322], Pipe=[1:7565593453017236852:4322], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:33.785950Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user rebalancing was scheduled
2025-10-26T18:06:33.785986Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing. Sessions=1, Families=1, UnradableFamilies=1 [1 (0), ], RequireBalancing=0 []
2025-10-26T18:06:33.786029Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing family=1 (Status=Free, Partitions=[0]) for ReadingSession "shared/user_1_2_240122148395822027_v1" (Sender=[1:7565593453017236849:4322], Pipe=[1:7565593453017236852:4322], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:33.786089Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo consumer user family 1 status Active partitions [0] session "shared/user_1_2_240122148395822027_v1" sender [1:7565593453017236849:4322] lock partition 0 for ReadingSession "shared/user_1_2_240122148395822027_v1" (Sender=[1:7565593453017236849:4322], Pipe=[1:7565593453017236852:4322], Partitions=[], ActiveFamilyCount=1) generation 1 step 2
2025-10-26T18:06:33.786137Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user start rebalancing. familyCount=1, sessionCount=1, desiredFamilyCount=1, allowPlusOne=0
2025-10-26T18:06:33.786157Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing duration: 0.000153s
2025-10-26T18:06:33.786815Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 assign: record# { Partition: 0 TabletId: 72075186224037892 Topic: "rt3.dc1--demo" Generation: 1 Step: 2 Session: "shared/user_1_2_240122148395822027_v1" ClientId: "user" PipeClient { RawX1: 7565593453017236852 RawX2: 4503603922342114 } Path: "/Root/PQ/rt3.dc1--demo" }
2025-10-26T18:06:33.786876Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 INITING TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)
2025-10-26T18:06:33.787522Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236855:4331], now have 1 active actors on pipe
2025-10-26T18:06:33.787745Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:33.787948Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.787979Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.788001Z node 2 :PERSQUEUE DEBUG: Created session shared/user_1_2_240122148395822027_v1 on pipe: [1:7565593453017236855:4331]
2025-10-26T18:06:33.788104Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user session is set to 2 (startOffset 0) session shared/user_1_2_240122148395822027_v1
2025-10-26T18:06:33.788234Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.788775Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_1_2_240122148395822027_v1:1 with generation 1
2025-10-26T18:06:33.791203Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.791273Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:33.791767Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 2 EndOffset: 16 WriteTimestampMS: 1761501993278 CreateTimestampMS: 1761501993276 SizeLag: 314 WriteTimestampEstimateMS: 1761501993718 } Cookie: 18446744073709551615 }
2025-10-26T18:06:33.791807Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 INIT DONE TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 readOffset 2 committedOffset 2
2025-10-26T18:06:33.791875Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 sending to client partition status
TCreatePartitionStreamEvent: CreatePartitionStream { PartitionStreamId: 1 TopicPath: demo Cluster: dc1 PartitionId: 0 CommittedOffset: 2 EndOffset: 16 }
2025-10-26T18:06:33.793824Z :INFO: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] Confirm partition stream create. Partition stream id: 1. Cluster: "dc1". Topic: "demo". Partition: 0. Read offset: (empty maybe)
2025-10-26T18:06:33.794437Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc read done: success# 1, data# { start_read { topic { path: "demo" } cluster: "dc1" assign_id: 1 } }
2025-10-26T18:06:33.804922Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.798859Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 0, commitOffset# 0
2025-10-26T18:06:33.804967Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.805076Z node 2 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2025-10-26T18:06:33.805937Z node 2 :PERSQUEUE DEBUG: read cookie 2 Topic 'rt3.dc1--demo' partition 0 user user offset 2 count 16 size 376 endOffset 16 max time lag 0ms effective offset 2
2025-10-26T18:06:33.805976Z node 2 :PERSQUEUE DEBUG: read cookie 2 added 0 blobs, size 0 count 0 last offset 2
2025-10-26T18:06:33.798932Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 Start reading TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 readOffset 2 committedOffset 2 clientCommitOffset 0 clientReadOffset 0
2025-10-26T18:06:33.806042Z node 2 :PERSQUEUE DEBUG: Reading cookie 2. All data is from uncompacted head.
2025-10-26T18:06:33.798951Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) ready for read with readOffset 2 endOffset 16
2025-10-26T18:06:33.806061Z node 2 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:33.799003Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 2, endOffset# 16, WTime# 1761501993278, sizeLag# 314
2025-10-26T18:06:33.806189Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 2
2025-10-26T18:06:33.799018Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1TEvPartitionReady. Aval parts: 1
2025-10-26T18:06:33.803938Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 performing read request: guid# 4dc72014-1f2825b0-23526a86-3466836b, from# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), count# 16, size# 376, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-26T18:06:33.804059Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 READ FROM TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)maxCount 16 maxSize 376 maxTimeLagMs 0 readTimestampMs 0 readOffset 2 EndOffset 16 ClientCommitOffset 2 committedOffset 2 Guid 4dc72014-1f2825b0-23526a86-3466836b
2025-10-26T18:06:33.805045Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user Reading of the partition 0 was started by user.
2025-10-26T18:06:33.808916Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 16 Result { Offset: 2 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 4 WriteTimestampMS: 1761501993278 CreateTimestampMS: 1761501993276 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 3 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 5 WriteTimestampMS: 1761501993288 CreateTimestampMS: 1761501993287 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 4 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 6 WriteTimestampMS: 1761501993336 CreateTimestampMS: 1761501993334 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 18446744073709551519 RealReadOffset: 4 WaitQuotaTimeMs: 0 } Cookie: 2 }
2025-10-26T18:06:33.809097Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) ready for read with readOffset 5 endOffset 16
2025-10-26T18:06:33.809128Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 after read state TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 ReadOffset 5 ReadGuid 4dc72014-1f2825b0-23526a86-3466836b has messages 1
2025-10-26T18:06:33.809193Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 5, endOffset# 16, WTime# 1761501993336, sizeLag# 18446744073709551519
2025-10-26T18:06:33.809211Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1TEvPartitionReady. Aval parts: 0
2025-10-26T18:06:33.809244Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 read done: guid# 4dc72014-1f2825b0-23526a86-3466836b, partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), size# 470
2025-10-26T18:06:33.809270Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 response to read: guid# 4dc72014-1f2825b0-23526a86-3466836b
2025-10-26T18:06:33.809569Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 Process answer. Aval parts: 1
2025-10-26T18:06:33.810442Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.810674Z :DEBUG: [] Decompression task done. Partition/PartitionSessionId: 0 (2-4)
2025-10-26T18:06:33.810832Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc read done: success# 1, data# { read { } }
2025-10-26T18:06:33.811623Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.811658Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.811706Z node 2 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2025-10-26T18:06:33.811780Z node 2 :PERSQUEUE DEBUG: read cookie 3 Topic 'rt3.dc1--demo' partition 0 user user offset 5 count 13 size 26214400 endOffset 16 max time lag 0ms effective offset 5
2025-10-26T18:06:33.811814Z node 2 :PERSQUEUE DEBUG: read cookie 3 added 0 blobs, size 0 count 0 last offset 5
2025-10-26T18:06:33.811890Z node 2 :PERSQUEUE DEBUG: Reading cookie 3. All data is from uncompacted head.
2025-10-26T18:06:33.811908Z node 2 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:33.812262Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 5
2025-10-26T18:06:33.810966Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 got read request: guid# f6bfceee-a3c19c1f-5d3b4008-bfda0098
2025-10-26T18:06:33.811034Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 performing read request: guid# f6bfceee-a3c19c1f-5d3b4008-bfda0098, from# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), count# 13, size# 104857600, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-26T18:06:33.811087Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 READ FROM TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)maxCount 13 maxSize 104857600 maxTimeLagMs 0 readTimestampMs 0 readOffset 5 EndOffset 16 ClientCommitOffset 2 committedOffset 2 Guid f6bfceee-a3c19c1f-5d3b4008-bfda0098
2025-10-26T18:06:33.814522Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 16 Result { Offset: 5 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 7 WriteTimestampMS: 1761501993348 CreateTimestampMS: 1761501993347 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 6 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 8 WriteTimestampMS: 1761501993362 CreateTimestampMS: 1761501993357 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 7 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 9 WriteTimestampMS: 1761501993425 CreateTimestampMS: 1761501993419 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 8 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 10 WriteTimestampMS: 1761501993462 CreateTimestampMS: 1761501993460 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 9 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 11 WriteTimestampMS: 1761501993472 CreateTimestampMS: 1761501993474 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 10 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 12 WriteTimestampMS: 1761501993508 CreateTimestampMS: 1761501993505 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 11 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 13 WriteTimestampMS: 1761501993525 CreateTimestampMS: 1761501993519 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 12 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 14 WriteTimestampMS: 1761501993565 CreateTimestampMS: 1761501993564 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 13 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 15 WriteTimestampMS: 1761501993591 CreateTimestampMS: 1761501993589 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 14 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 16 WriteTimestampMS: 1761501993609 CreateTimestampMS: 1761501993602 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } Result { Offset: 15 Data: "... 92 bytes ..." SourceId: "\000source-id" SeqNo: 17 WriteTimestampMS: 1761501993619 CreateTimestampMS: 1761501993617 UncompressedSize: 4 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 18446744073709550423 RealReadOffset: 15 WaitQuotaTimeMs: 0 } Cookie: 5 }
2025-10-26T18:06:33.814884Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) wait data in partition inited, cookie 1 from offset16
2025-10-26T18:06:33.814916Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 after read state TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 ReadOffset 16 ReadGuid f6bfceee-a3c19c1f-5d3b4008-bfda0098 has messages 1
2025-10-26T18:06:33.815053Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 read done: guid# f6bfceee-a3c19c1f-5d3b4008-bfda0098, partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), size# 1606
2025-10-26T18:06:33.815082Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 response to read: guid# f6bfceee-a3c19c1f-5d3b4008-bfda0098
2025-10-26T18:06:33.815339Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 Process answer. Aval parts: 0
2025-10-26T18:06:33.816073Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.816278Z :DEBUG: [] Decompression task done. Partition/PartitionSessionId: 0 (5-15)
2025-10-26T18:06:33.817109Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc read done: success# 1, data# { read { } }
2025-10-26T18:06:33.817253Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 got read request: guid# 89a910f-3f8b85ae-3778fba7-f3a12371
2025-10-26T18:06:33.828156Z :DEBUG: [] Take Data. Partition 0. Read: {0, 0} (2-2)
2025-10-26T18:06:33.828216Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] The application data is transferred to the client. Number of messages 1, size 4 bytes
TDataReceivedEvent: DataReceived { PartitionStreamId: 1 PartitionId: 0 Message { Data: ..4 bytes.. Partition stream id: 1 Cluster: "dc1". Topic: "demo" Partition: 0 PartitionKey: "" Information: { Offset: 2 SeqNo: 4 MessageGroupId: "source-id" CreateTime: 2025-10-26T18:06:33.276000Z WriteTime: 2025-10-26T18:06:33.278000Z Ip: "ipv6:[::1]:52244" UncompressedSize: 4 Meta: { "ident": "unknown", "key": "value", "logtype": "unknown", "server": "ipv6:[::1]:52244" } } } }
2025-10-26T18:06:33.828337Z :DEBUG: [] Take Data. Partition 0. Read: {1, 0} (3-3)
2025-10-26T18:06:33.828367Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] The application data is transferred to the client. Number of messages 1, size 4 bytes
TDataReceivedEvent: DataReceived { PartitionStreamId: 1 PartitionId: 0 Message { Data: ..4 bytes.. Partition stream id: 1 Cluster: "dc1". Topic: "demo" Partition: 0 PartitionKey: "" Information: { Offset: 3 SeqNo: 5 MessageGroupId: "source-id" CreateTime: 2025-10-26T18:06:33.287000Z WriteTime: 2025-10-26T18:06:33.288000Z Ip: "ipv6:[::1]:52244" UncompressedSize: 4 Meta: { "ident": "unknown", "key": "value", "logtype": "unknown", "server": "ipv6:[::1]:52244" } } } }
2025-10-26T18:06:33.832494Z :INFO: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] Closing read session. Close timeout: 0.000000s
2025-10-26T18:06:33.832554Z :INFO: [] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): null:demo:0:1:15:2
2025-10-26T18:06:33.832582Z :INFO: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] Counters: { Errors: 0 CurrentSessionLifetimeMs: 66 BytesRead: 56 MessagesRead: 14 BytesReadCompressed: 56 BytesInflightUncompressed: 48 BytesInflightCompressed: 0 BytesInflightTotal: 48 MessagesInflight: 12 }
2025-10-26T18:06:33.832659Z :NOTICE: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Close with zero timeout " }
2025-10-26T18:06:33.832943Z :DEBUG: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] [null] Abort session to cluster
2025-10-26T18:06:33.833706Z :NOTICE: [] [] [1a14ebd1-92c82e73-85728fd3-578a700d] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Aborted " }
2025-10-26T18:06:33.834335Z node 1 :PQ_READ_PROXY DEBUG: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc read done: success# 0, data# {  }
2025-10-26T18:06:33.834364Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc read failed
2025-10-26T18:06:33.834385Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 grpc closed
2025-10-26T18:06:33.834414Z node 1 :PQ_READ_PROXY INFO: session cookie 2 consumer shared/user session shared/user_1_2_240122148395822027_v1 is DEAD
2025-10-26T18:06:33.835383Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236852:4322] disconnected; active server actors: 1
2025-10-26T18:06:33.835402Z node 1 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236852:4322] client user disconnected session shared/user_1_2_240122148395822027_v1
2025-10-26T18:06:33.835656Z node 2 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_1_2_240122148395822027_v1
2025-10-26T18:06:33.835697Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236855:4331] destroyed
2025-10-26T18:06:33.836058Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_1_2_240122148395822027_v1
2025-10-26T18:06:33.849608Z :INFO: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] Starting read session
2025-10-26T18:06:33.849662Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] Starting session to cluster null (localhost:17330)
2025-10-26T18:06:33.850867Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] In Reconnect, ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.850906Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] New values: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.850943Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] Reconnecting session to cluster null in 0.000000s
2025-10-26T18:06:33.858951Z node 1 :PQ_READ_PROXY DEBUG: new grpc connection
2025-10-26T18:06:33.858976Z node 1 :PQ_READ_PROXY DEBUG: new session created cookie 3
2025-10-26T18:06:33.862275Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] Successfully connected. Initializing session
2025-10-26T18:06:33.869798Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { topic: "demo" } read_only_original: true consumer: "user" read_params { max_read_size: 104857600 } } }
2025-10-26T18:06:33.870001Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 read init: from# ipv6:[::1]:52362, request# { init_request { topics_read_settings { topic: "demo" } read_only_original: true consumer: "user" read_params { max_read_size: 104857600 } } }
2025-10-26T18:06:33.870287Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 auth for : user
2025-10-26T18:06:33.871553Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 Handle describe topics response
2025-10-26T18:06:33.871687Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 auth is DEAD
2025-10-26T18:06:33.871763Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 auth ok: topics# 1, initDone# 0
2025-10-26T18:06:33.873824Z :INFO: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] Server session id: shared/user_1_3_14350906982747515637_v1
2025-10-26T18:06:33.872658Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 register session: topic# rt3.dc1--demo
2025-10-26T18:06:33.874188Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-10-26T18:06:33.878453Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [1:7565593453017236904:4349], now have 1 active actors on pipe
2025-10-26T18:06:33.875237Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236891:4347] connected; active server actors: 1
2025-10-26T18:06:33.875922Z node 1 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--demo consumer "user" register session for pipe [1:7565593453017236891:4347] session shared/user_1_3_14350906982747515637_v1
2025-10-26T18:06:33.875955Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user register readable partition 0
2025-10-26T18:06:33.875994Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user family created family=1 (Status=Free, Partitions=[0])
2025-10-26T18:06:33.876027Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo consumer user register reading session ReadingSession "shared/user_1_3_14350906982747515637_v1" (Sender=[1:7565593453017236882:4347], Pipe=[1:7565593453017236891:4347], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:33.876045Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user rebalancing was scheduled
2025-10-26T18:06:33.876093Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing. Sessions=1, Families=1, UnradableFamilies=1 [1 (0), ], RequireBalancing=0 []
2025-10-26T18:06:33.876137Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing family=1 (Status=Free, Partitions=[0]) for ReadingSession "shared/user_1_3_14350906982747515637_v1" (Sender=[1:7565593453017236882:4347], Pipe=[1:7565593453017236891:4347], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:33.876201Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo consumer user family 1 status Active partitions [0] session "shared/user_1_3_14350906982747515637_v1" sender [1:7565593453017236882:4347] lock partition 0 for ReadingSession "shared/user_1_3_14350906982747515637_v1" (Sender=[1:7565593453017236882:4347], Pipe=[1:7565593453017236891:4347], Partitions=[], ActiveFamilyCount=1) generation 1 step 3
2025-10-26T18:06:33.876238Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user start rebalancing. familyCount=1, sessionCount=1, desiredFamilyCount=1, allowPlusOne=0
2025-10-26T18:06:33.876259Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user balancing duration: 0.000148s
2025-10-26T18:06:33.877297Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 assign: record# { Partition: 0 TabletId: 72075186224037892 Topic: "rt3.dc1--demo" Generation: 1 Step: 3 Session: "shared/user_1_3_14350906982747515637_v1" ClientId: "user" PipeClient { RawX1: 7565593453017236891 RawX2: 4503603922342139 } Path: "/Root/PQ/rt3.dc1--demo" }
2025-10-26T18:06:33.877362Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 INITING TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)
2025-10-26T18:06:33.878994Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 grpc read done: success# 1, data# { read { } }
2025-10-26T18:06:33.879164Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 got read request: guid# c0ef8313-a239c72b-4eb90652-b579b899
2025-10-26T18:06:33.879301Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:33.881163Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.881196Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.881226Z node 2 :PERSQUEUE DEBUG: Created session shared/user_1_3_14350906982747515637_v1 on pipe: [1:7565593453017236904:4349]
2025-10-26T18:06:33.881338Z node 2 :PERSQUEUE DEBUG: Topic 'rt3.dc1--demo' partition 0 user user session is set to 2 (startOffset 0) session shared/user_1_3_14350906982747515637_v1
2025-10-26T18:06:33.881463Z node 2 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:33.882063Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_1_3_14350906982747515637_v1:1 with generation 1
2025-10-26T18:06:33.887403Z node 2 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:33.887484Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:33.888590Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 2 EndOffset: 16 WriteTimestampMS: 1761501993278 CreateTimestampMS: 1761501993276 SizeLag: 314 WriteTimestampEstimateMS: 1761501993815 } Cookie: 18446744073709551615 }
2025-10-26T18:06:33.888646Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 INIT DONE TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 readOffset 2 committedOffset 2
2025-10-26T18:06:33.888754Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 sending to client partition status
TCreatePartitionStreamEvent: CreatePartitionStream { PartitionStreamId: 1 TopicPath: demo Cluster: dc1 PartitionId: 0 CommittedOffset: 2 EndOffset: 16 }
2025-10-26T18:06:33.890122Z :INFO: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] Confirm partition stream create. Partition stream id: 1. Cluster: "dc1". Topic: "demo". Partition: 0. Read offset: (empty maybe)
2025-10-26T18:06:33.890338Z :INFO: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] Closing read session. Close timeout: 0.000000s
2025-10-26T18:06:33.890384Z :INFO: [] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): null:demo:0:1:0:2
2025-10-26T18:06:33.890413Z :INFO: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] Counters: { Errors: 0 CurrentSessionLifetimeMs: 40 BytesRead: 0 MessagesRead: 0 BytesReadCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-10-26T18:06:33.890501Z :NOTICE: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Close with zero timeout " }
2025-10-26T18:06:33.890535Z :DEBUG: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] [null] Abort session to cluster
2025-10-26T18:06:33.890832Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 grpc read done: success# 1, data# { start_read { topic { path: "demo" } cluster: "dc1" assign_id: 1 } }
2025-10-26T18:06:33.890924Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 0, commitOffset# 0
2025-10-26T18:06:33.890959Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 Start reading TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) EndOffset 16 readOffset 2 committedOffset 2 clientCommitOffset 0 clientReadOffset 0
2025-10-26T18:06:33.890981Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1) ready for read with readOffset 2 endOffset 16
2025-10-26T18:06:33.891026Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), readOffset# 2, endOffset# 16, WTime# 1761501993278, sizeLag# 314
2025-10-26T18:06:33.891044Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1TEvPartitionReady. Aval parts: 1
2025-10-26T18:06:33.891072Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 performing read request: guid# c0ef8313-a239c72b-4eb90652-b579b899, from# TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1), count# 16, size# 376, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-26T18:06:33.891118Z node 1 :PQ_READ_PROXY DEBUG: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 READ FROM TopicId: Topic rt3.dc1--demo in dc dc1 in database: Root, partition 0(assignId:1)maxCount 16 maxSize 376 maxTimeLagMs 0 readTimestampMs 0 readOffset 2 EndOffset 16 ClientCommitOffset 2 committedOffset 2 Guid c0ef8313-a239c72b-4eb90652-b579b899
2025-10-26T18:06:33.890914Z :NOTICE: [] [] [394b7e16-48bd9884-a3c9136d-3bb06fb3] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Aborted " }
2025-10-26T18:06:33.891581Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 grpc closed
2025-10-26T18:06:33.891619Z node 1 :PQ_READ_PROXY INFO: session cookie 3 consumer shared/user session shared/user_1_3_14350906982747515637_v1 is DEAD
2025-10-26T18:06:33.891758Z node 1 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--demo consumer user Reading of the partition 0 was started by user.
2025-10-26T18:06:33.891890Z node 2 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--demo' requestId: <none>
2025-10-26T18:06:33.891923Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--demo' partition 0
2025-10-26T18:06:33.892035Z node 2 :PERSQUEUE DEBUG: read cookie 4 Topic 'rt3.dc1--demo' partition 0 user user offset 2 count 16 size 376 endOffset 16 max time lag 0ms effective offset 2
2025-10-26T18:06:33.892051Z node 2 :PERSQUEUE DEBUG: read cookie 4 added 0 blobs, size 0 count 0 last offset 2
2025-10-26T18:06:33.892105Z node 2 :PERSQUEUE DEBUG: Reading cookie 4. All data is from uncompacted head.
2025-10-26T18:06:33.892122Z node 2 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:33.892230Z node 2 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--demo' partition: 0 messageNo: 0  requestId: <none> cookie: 2
2025-10-26T18:06:33.892277Z node 2 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2025-10-26T18:06:33.894497Z node 1 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236891:4347] disconnected; active server actors: 1
2025-10-26T18:06:33.894525Z node 1 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--demo pipe [1:7565593453017236891:4347] client user disconnected session shared/user_1_3_14350906982747515637_v1
2025-10-26T18:06:33.895195Z node 2 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_1_3_14350906982747515637_v1
2025-10-26T18:06:33.895233Z node 2 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [1:7565593453017236904:4349] destroyed
2025-10-26T18:06:33.897214Z node 2 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_1_3_14350906982747515637_v1
