2025-11-05T13:43:28.850724Z node 9 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[9:7569236509082682825:2154];send_to=[0:7307199536658146131:7762515];
2025-11-05T13:43:28.851452Z node 9 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:69;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-11-05T13:43:28.852741Z node 9 :PQ_READ_PROXY DEBUG: Direct read cache: : Created
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/4xc1/003f38/r3tmp/tmpQNwK0Q/pdisk_1.dat
2025-11-05T13:43:28.866452Z node 9 :IMPORT WARN: Table profiles were not loaded
TServer::EnableGrpc on GrpcPort 5994, node 9
2025-11-05T13:43:28.879455Z node 9 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/4xc1/003f38/r3tmp/yandexAxFy7Z.tmp
2025-11-05T13:43:28.879467Z node 9 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/4xc1/003f38/r3tmp/yandexAxFy7Z.tmp
2025-11-05T13:43:28.884416Z INFO: TTestServer started on Port 26887 GrpcPort 5994
2025-11-05T13:43:28.889123Z node 9 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/4xc1/003f38/r3tmp/yandexAxFy7Z.tmp
2025-11-05T13:43:28.889216Z node 9 :NET_CLASSIFIER ERROR: got bad distributable configuration
TClient is connected to server localhost:26887
PQClient connected to localhost:5994
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
    ChildrenExist: false
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      Pl...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-11-05T13:43:28.954566Z node 9 :HIVE WARN: HIVE#72057594037968897 Node(9, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-11-05T13:43:28.954613Z node 9 :HIVE WARN: HIVE#72057594037968897 Node(9, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-11-05T13:43:28.954979Z node 9 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976715657:0, at schemeshard:  72057594046644480
waiting...
2025-11-05T13:43:28.955550Z node 9 :HIVE WARN: HIVE#72057594037968897 Node(9, (0,0,0,0)) VolatileState: Connecting -> Connected
waiting...
2025-11-05T13:43:28.977951Z node 9 :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-11-05T13:43:29.138720Z node 9 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [9:7569236513377650754:2316], 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-11-05T13:43:29.140010Z node 9 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=9&id=ODNiYWIwNTAtMTAxMzhkZi0xMWQzYTk0NC0xZjE1MTk1Mw==, ActorId: [9:7569236513377650751:2314], ActorState: ExecuteState, TraceId: 01k9a4463dcmzczkghxf49eqay, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-11-05T13:43:29.140131Z node 9 :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-11-05T13:43:29.141064Z node 9 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715662:0, at schemeshard:  72057594046644480
2025-11-05T13:43:29.148361Z node 9 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715663:0, at schemeshard:  72057594046644480
2025-11-05T13:43:29.208269Z node 9 :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);
=== CheckClustersList. Subcribe to ClusterTracker from [9:7569236513377651041:2561] 
2025-11-05T13:43:29.852913Z node 9 :TX_CONVEYOR ERROR: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-11-05T13:43:33.853373Z node 9 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[9:7569236509082682825:2154];send_to=[0:7307199536658146131:7762515];
2025-11-05T13:43:33.853446Z node 9 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:69;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
=== CheckClustersList. Ok
2025-11-05T13:43:34.318369Z :Sinks_Oltp_WriteToTopicAndTable_6_Query INFO: TTopicSdkTestSetup started
2025-11-05T13:43:34.321393Z node 9 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:34.324775Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037893][] pipe [9:7569236534852487828:2734] connected; active server actors: 1
2025-11-05T13:43:34.324790Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:34.324881Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.324904Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:34.324979Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:34.325024Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.325049Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] doesn't have tx info
2025-11-05T13:43:34.325050Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] BALANCER INIT DONE for test-topic: (0, 72075186224037892) 
2025-11-05T13:43:34.325053Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:34.325056Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-11-05T13:43:34.325059Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:34.325066Z node 9 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:34.325074Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037892] doesn't have tx writes info
2025-11-05T13:43:34.325168Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [9:7569236534852487827:2733], now have 1 active actors on pipe
2025-11-05T13:43:34.325224Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72075186224037892, NodeId 9, Generation 1
2025-11-05T13:43:34.325232Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72057594046644480, NodeId 9, Generation 2
2025-11-05T13:43:34.325280Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } TxId: 281474976715671 Config { TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 } } }
2025-11-05T13:43:34.325310Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] Propose TxId 281474976715671, WriteId (empty maybe)
2025-11-05T13:43:34.325322Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state UNKNOWN
2025-11-05T13:43:34.325324Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State UNKNOWN
2025-11-05T13:43:34.325328Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:34.325331Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from UNKNOWN to PREPARING
2025-11-05T13:43:34.325338Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:34.325391Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: PREPARED MinStep: 1762350214366 MaxStep: 18446744073709551615 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { }
2025-11-05T13:43:34.325446Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.325458Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [9:7569236534852487866:2424], now have 1 active actors on pipe
2025-11-05T13:43:34.325636Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.325651Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARING
2025-11-05T13:43:34.325658Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PREPARING
2025-11-05T13:43:34.325660Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PREPARING to PREPARED
2025-11-05T13:43:34.325906Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037892 TxId: 281474976715671
2025-11-05T13:43:34.326220Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [9:7569236534852487878:2763], now have 1 active actors on pipe
2025-11-05T13:43:34.326247Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715671 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350214373 MediatorID: 72057594046382081 TabletID: 72075186224037892
2025-11-05T13:43:34.326256Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARED
2025-11-05T13:43:34.326258Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PREPARED
2025-11-05T13:43:34.326261Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PREPARED to PLANNING
2025-11-05T13:43:34.326265Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] PlanStep 1762350214373, PlanTxId 281474976715671
2025-11-05T13:43:34.326270Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:34.326334Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: PLANNED MinStep: 1762350214366 MaxStep: 18446744073709551615 Step: 1762350214373 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { }
2025-11-05T13:43:34.326357Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.326501Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.326513Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PLANNING
2025-11-05T13:43:34.326514Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PLANNING
2025-11-05T13:43:34.326517Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PLANNING to PLANNED
2025-11-05T13:43:34.326519Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxQueue.size 1
2025-11-05T13:43:34.326523Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] New ExecStep 1762350214373, ExecTxId 281474976715671
2025-11-05T13:43:34.326624Z node 9 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:34.326632Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PLANNED to CALCULATING
2025-11-05T13:43:34.326643Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:34.326682Z node 9 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:34.326733Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] bootstrapping 0 [9:7569236534852487884:2428]
2025-11-05T13:43:34.326989Z node 9 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Initializing completed.
2025-11-05T13:43:34.327000Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] init complete for topic 'test-topic' partition 0 generation 1 [9:7569236534852487884:2428]
2025-11-05T13:43:34.327006Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] SYNC INIT topic test-topic partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:34.327081Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:34.327093Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.327117Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327123Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:34.327125Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350214373, TxId 281474976715671, Partition 0
2025-11-05T13:43:34.327126Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327127Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327128Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:34.327129Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:34.327132Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] Partition responses 1/1
2025-11-05T13:43:34.327134Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-11-05T13:43:34.327135Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State CALCULATING
2025-11-05T13:43:34.327137Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Topic 'test-topic' partition 0 user test-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:34.327139Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State CALCULATING FrontTxId 281474976715671
2025-11-05T13:43:34.327142Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:43:34.327145Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from CALCULATING to CALCULATED
2025-11-05T13:43:34.327148Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:34.327224Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: CALCULATED MinStep: 1762350214366 MaxStep: 18446744073709551615 Step: 1762350214373 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:34.327247Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.327514Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.327526Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATED
2025-11-05T13:43:34.327528Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State CALCULATED
2025-11-05T13:43:34.327531Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State CALCULATED FrontTxId 281474976715671
2025-11-05T13:43:34.327533Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:34.327543Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:34.327546Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveParticipantsDecision 1
2025-11-05T13:43:34.327561Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:34.327564Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 0, Expected 1
2025-11-05T13:43:34.327567Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350214373, TxId 281474976715671
2025-11-05T13:43:34.327571Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327573Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327600Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327646Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.327801Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1762350214373, TxId 281474976715671, Partition 0
2025-11-05T13:43:34.327807Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-11-05T13:43:34.327809Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State EXECUTING
2025-11-05T13:43:34.327810Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:34.327811Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State EXECUTING FrontTxId 281474976715671
2025-11-05T13:43:34.327813Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:43:34.327815Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.327817Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.327818Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId: 281474976715671 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:34.327824Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] complete TxId 281474976715671
2025-11-05T13:43:34.327874Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 }
2025-11-05T13:43:34.327891Z node 9 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:34.327902Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] delete partitions for TxId 281474976715671
2025-11-05T13:43:34.327908Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from EXECUTING to EXECUTED
2025-11-05T13:43:34.327923Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:34.327975Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: EXECUTED MinStep: 1762350214366 MaxStep: 18446744073709551615 Step: 1762350214373 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:34.328005Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.328250Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.328322Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.328420Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.328425Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTED
2025-11-05T13:43:34.328426Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State EXECUTED
2025-11-05T13:43:34.328427Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State EXECUTED FrontTxId 281474976715671
2025-11-05T13:43:34.328429Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:34.328432Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:34.328434Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] PredicateAcks: 0/0
2025-11-05T13:43:34.328435Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:34.328436Z node 9 :PQ_TX DEBUG: [TxId: 281474976715671] PredicateAcks: 0/0
2025-11-05T13:43:34.328437Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] add an TxId 281474976715671 to the list for deletion
2025-11-05T13:43:34.328439Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:34.328441Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] delete key for TxId 281474976715671
2025-11-05T13:43:34.328446Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.328525Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.328529Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state DELETING
2025-11-05T13:43:34.328530Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State DELETING
2025-11-05T13:43:34.328531Z node 9 :PQ_TX INFO: [PQ: 72075186224037892] delete TxId 281474976715671
2025-11-05T13:43:34.328968Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:34.329209Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:34.329215Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:5994
2025-11-05T13:43:34.330129Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "test-topic" message_group_id: "src" }
2025-11-05T13:43:34.330238Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.330247Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2025-11-05T13:43:34.330338Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "test-topic" message_group_id: "src" }
2025-11-05T13:43:34.330359Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "test-topic" message_group_id: "src" from ipv6:[::1]:36768
2025-11-05T13:43:34.330366Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36768 proto=v1  topic=test-topic durationSec=0
2025-11-05T13:43:34.330370Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.330882Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  describe result for acl check
2025-11-05T13:43:34.330912Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.330918Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.330919Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.330930Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852487928:2436] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.330937Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 1 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:34.331052Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 9, Generation: 1
2025-11-05T13:43:34.331066Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [9:7569236534852487931:2436], now have 1 active actors on pipe
2025-11-05T13:43:34.331080Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:43:34.331084Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:43:34.331117Z node 9 :PERSQUEUE INFO: new Cookie src|10b150cd-d0144401-887e5476-13290fbd_0 generated for partition 0 topic 'test-topic' owner src
2025-11-05T13:43:34.331129Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.331137Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.331151Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.331164Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.331186Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.331229Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:43:34.331238Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:43:34.331259Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.331278Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 1 partition: 0 MaxSeqNo: 0 sessionId: src|10b150cd-d0144401-887e5476-13290fbd_0
2025-11-05T13:43:34.331426Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350214331 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:34.331448Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|10b150cd-d0144401-887e5476-13290fbd_0" topic: "test-topic"
2025-11-05T13:43:34.331530Z :INFO: [/Root] MessageGroupId [src] SessionId [src|10b150cd-d0144401-887e5476-13290fbd_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:34.331538Z :INFO: [/Root] MessageGroupId [src] SessionId [src|10b150cd-d0144401-887e5476-13290fbd_0] Write session will now close
2025-11-05T13:43:34.331544Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|10b150cd-d0144401-887e5476-13290fbd_0] Write session: aborting
2025-11-05T13:43:34.331657Z :INFO: [/Root] MessageGroupId [src] SessionId [src|10b150cd-d0144401-887e5476-13290fbd_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.331661Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|10b150cd-d0144401-887e5476-13290fbd_0] Write session: destroy
2025-11-05T13:43:34.331768Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: src|10b150cd-d0144401-887e5476-13290fbd_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.331778Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|10b150cd-d0144401-887e5476-13290fbd_0 grpc read failed
2025-11-05T13:43:34.331785Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|10b150cd-d0144401-887e5476-13290fbd_0 grpc closed
2025-11-05T13:43:34.331787Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|10b150cd-d0144401-887e5476-13290fbd_0 is DEAD
2025-11-05T13:43:34.332015Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.332064Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server disconnected, pipe [9:7569236534852487931:2436] destroyed
2025-11-05T13:43:34.332078Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.332089Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.332091Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.332128Z :Sinks_Oltp_WriteToTopicAndTable_6_Query INFO: Topic created
2025-11-05T13:43:34.335881Z node 9 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:34.337025Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.337084Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.339148Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:34.339173Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][] pipe [9:7569236534852487973:2803] connected; active server actors: 1
2025-11-05T13:43:34.339295Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:34.339303Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:34.339364Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:34.339391Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:34.339412Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] BALANCER INIT DONE for topic_A: (0, 72075186224037894) 
2025-11-05T13:43:34.339421Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] doesn't have tx info
2025-11-05T13:43:34.339424Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:34.339429Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] no config, start with empty partitions and default config
2025-11-05T13:43:34.339433Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:34.339439Z node 9 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:34.339445Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037894] doesn't have tx writes info
2025-11-05T13:43:34.339456Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72057594046644480, NodeId 9, Generation 2
2025-11-05T13:43:34.339462Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852488007:2450], now have 1 active actors on pipe
2025-11-05T13:43:34.339466Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852487970:2801], now have 1 active actors on pipe
2025-11-05T13:43:34.339474Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72075186224037894, NodeId 9, Generation 1
2025-11-05T13:43:34.339593Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } TxId: 281474976715672 Config { TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 } } }
2025-11-05T13:43:34.339618Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] Propose TxId 281474976715672, WriteId (empty maybe)
2025-11-05T13:43:34.339626Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state UNKNOWN
2025-11-05T13:43:34.339628Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State UNKNOWN
2025-11-05T13:43:34.339633Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:34.339637Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from UNKNOWN to PREPARING
2025-11-05T13:43:34.339646Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:34.339690Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: PREPARED MinStep: 1762350214380 MaxStep: 18446744073709551615 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { }
2025-11-05T13:43:34.339710Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.339839Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.339849Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARING
2025-11-05T13:43:34.339851Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PREPARING
2025-11-05T13:43:34.339853Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PREPARING to PREPARED
2025-11-05T13:43:34.340001Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037894 TxId: 281474976715672
2025-11-05T13:43:34.340159Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852488019:2831], now have 1 active actors on pipe
2025-11-05T13:43:34.340178Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715672 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350214387 MediatorID: 72057594046382081 TabletID: 72075186224037894
2025-11-05T13:43:34.340186Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARED
2025-11-05T13:43:34.340187Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PREPARED
2025-11-05T13:43:34.340190Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PREPARED to PLANNING
2025-11-05T13:43:34.340194Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] PlanStep 1762350214387, PlanTxId 281474976715672
2025-11-05T13:43:34.340198Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:34.340252Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: PLANNED MinStep: 1762350214380 MaxStep: 18446744073709551615 Step: 1762350214387 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { }
2025-11-05T13:43:34.340270Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.340436Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.340450Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PLANNING
2025-11-05T13:43:34.340452Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PLANNING
2025-11-05T13:43:34.340454Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PLANNING to PLANNED
2025-11-05T13:43:34.340457Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxQueue.size 1
2025-11-05T13:43:34.340460Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] New ExecStep 1762350214387, ExecTxId 281474976715672
2025-11-05T13:43:34.340565Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PLANNED to CALCULATING
2025-11-05T13:43:34.340567Z node 9 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:34.340580Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:34.340617Z node 9 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:34.340669Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] bootstrapping 0 [9:7569236534852488025:2454]
2025-11-05T13:43:34.340884Z node 9 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Initializing completed.
2025-11-05T13:43:34.340895Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] init complete for topic 'topic_A' partition 0 generation 1 [9:7569236534852488025:2454]
2025-11-05T13:43:34.340900Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateInit] SYNC INIT topic topic_A partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:34.340956Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:34.340965Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.340984Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.340990Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:34.340993Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.340994Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.340997Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:34.341000Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350214387, TxId 281474976715672, Partition 0
2025-11-05T13:43:34.341004Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:34.341004Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:34.341008Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] Partition responses 1/1
2025-11-05T13:43:34.341011Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATING
2025-11-05T13:43:34.341013Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State CALCULATING
2025-11-05T13:43:34.341016Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State CALCULATING FrontTxId 281474976715672
2025-11-05T13:43:34.341019Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:43:34.341022Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from CALCULATING to CALCULATED
2025-11-05T13:43:34.341026Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:34.341107Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: CALCULATED MinStep: 1762350214380 MaxStep: 18446744073709551615 Step: 1762350214387 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:34.341137Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.341332Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.341338Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATED
2025-11-05T13:43:34.341339Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State CALCULATED
2025-11-05T13:43:34.341340Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State CALCULATED FrontTxId 281474976715672
2025-11-05T13:43:34.341342Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:34.341349Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:34.341351Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveParticipantsDecision 1
2025-11-05T13:43:34.341356Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:34.341358Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 0, Expected 1
2025-11-05T13:43:34.341364Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350214387, TxId 281474976715672
2025-11-05T13:43:34.341375Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.341377Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.341406Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.341478Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.341612Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:34.341618Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.341619Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.341626Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTxCommitDone Step 1762350214387, TxId 281474976715672, Partition 0
2025-11-05T13:43:34.341630Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTING
2025-11-05T13:43:34.341632Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State EXECUTING
2025-11-05T13:43:34.341634Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State EXECUTING FrontTxId 281474976715672
2025-11-05T13:43:34.341636Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:43:34.341642Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId: 281474976715672 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:34.341658Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] complete TxId 281474976715672
2025-11-05T13:43:34.341715Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 }
2025-11-05T13:43:34.341737Z node 9 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:34.341751Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] delete partitions for TxId 281474976715672
2025-11-05T13:43:34.341760Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from EXECUTING to EXECUTED
2025-11-05T13:43:34.341765Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:34.341824Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: EXECUTED MinStep: 1762350214380 MaxStep: 18446744073709551615 Step: 1762350214387 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:34.341858Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.342114Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:34.342132Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.342134Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTED
2025-11-05T13:43:34.342134Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State EXECUTED
2025-11-05T13:43:34.342136Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State EXECUTED FrontTxId 281474976715672
2025-11-05T13:43:34.342137Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:34.342138Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:34.342140Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] PredicateAcks: 0/0
2025-11-05T13:43:34.342142Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:34.342143Z node 9 :PQ_TX DEBUG: [TxId: 281474976715672] PredicateAcks: 0/0
2025-11-05T13:43:34.342144Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] add an TxId 281474976715672 to the list for deletion
2025-11-05T13:43:34.342145Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:34.342147Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] delete key for TxId 281474976715672
2025-11-05T13:43:34.342148Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.342153Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.342166Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.342192Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:34.342279Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.342287Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state DELETING
2025-11-05T13:43:34.342289Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State DELETING
2025-11-05T13:43:34.342292Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] delete TxId 281474976715672
2025-11-05T13:43:34.342560Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:34.342746Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:34.342751Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:5994
2025-11-05T13:43:34.343572Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:43:34.343602Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.343610Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2025-11-05T13:43:34.343740Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:43:34.343761Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "topic_A" message_group_id: "src" from ipv6:[::1]:36768
2025-11-05T13:43:34.343770Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36768 proto=v1  topic=topic_A durationSec=0
2025-11-05T13:43:34.343773Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.344080Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2025-11-05T13:43:34.344123Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.344130Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.344574Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350214344 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:34.344131Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.369953Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|b6699ead-e8904e0-227769b9-55ac8c8b_0" topic: "topic_A"
2025-11-05T13:43:34.344142Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852488061:2462] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.344147Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:34.344248Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 9, Generation: 1
2025-11-05T13:43:34.344254Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852488064:2462], now have 1 active actors on pipe
2025-11-05T13:43:34.344259Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.344262Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.344284Z node 9 :PERSQUEUE INFO: new Cookie src|b6699ead-e8904e0-227769b9-55ac8c8b_0 generated for partition 0 topic 'topic_A' owner src
2025-11-05T13:43:34.344292Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.344296Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.344303Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.344312Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.344340Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.344370Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.344372Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.344388Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.344406Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: src|b6699ead-e8904e0-227769b9-55ac8c8b_0
2025-11-05T13:43:34.370124Z :INFO: [/Root] MessageGroupId [src] SessionId [src|b6699ead-e8904e0-227769b9-55ac8c8b_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:34.370133Z :INFO: [/Root] MessageGroupId [src] SessionId [src|b6699ead-e8904e0-227769b9-55ac8c8b_0] Write session will now close
2025-11-05T13:43:34.370137Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|b6699ead-e8904e0-227769b9-55ac8c8b_0] Write session: aborting
2025-11-05T13:43:34.370266Z :INFO: [/Root] MessageGroupId [src] SessionId [src|b6699ead-e8904e0-227769b9-55ac8c8b_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.370274Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|b6699ead-e8904e0-227769b9-55ac8c8b_0] Write session: destroy
2025-11-05T13:43:34.370433Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: src|b6699ead-e8904e0-227769b9-55ac8c8b_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.370446Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|b6699ead-e8904e0-227769b9-55ac8c8b_0 grpc read failed
2025-11-05T13:43:34.370454Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|b6699ead-e8904e0-227769b9-55ac8c8b_0 grpc closed
2025-11-05T13:43:34.370457Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|b6699ead-e8904e0-227769b9-55ac8c8b_0 is DEAD
2025-11-05T13:43:34.370687Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.370773Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [9:7569236534852488064:2462] destroyed
2025-11-05T13:43:34.370786Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.370792Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.370796Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.373339Z node 9 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:34.374493Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.374508Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:34.374514Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.374515Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:34.376278Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037897][] pipe [9:7569236534852488097:2870] connected; active server actors: 1
2025-11-05T13:43:34.376340Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:34.376418Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037897
2025-11-05T13:43:34.376438Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] BALANCER INIT DONE for topic_B: (0, 72075186224037896) 
2025-11-05T13:43:34.376461Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:34.376511Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Registered with mediator time cast
2025-11-05T13:43:34.376518Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] TEvClientConnected TabletId 72057594046644480, NodeId 9, Generation 2
2025-11-05T13:43:34.376618Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:34.376651Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] doesn't have tx info
2025-11-05T13:43:34.376658Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:34.376660Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] no config, start with empty partitions and default config
2025-11-05T13:43:34.376663Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:34.376668Z node 9 :PERSQUEUE NOTICE: [PQ: 72075186224037896] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:34.376678Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037896] doesn't have tx writes info
2025-11-05T13:43:34.376719Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] TEvClientConnected TabletId 72075186224037896, NodeId 9, Generation 1
2025-11-05T13:43:34.376728Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488096:2869], now have 1 active actors on pipe
2025-11-05T13:43:34.376731Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488132:2470], now have 1 active actors on pipe
2025-11-05T13:43:34.376822Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } TxId: 281474976715673 Config { TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_B" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_B" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 } } }
2025-11-05T13:43:34.376848Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] Propose TxId 281474976715673, WriteId (empty maybe)
2025-11-05T13:43:34.376856Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state UNKNOWN
2025-11-05T13:43:34.376858Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State UNKNOWN
2025-11-05T13:43:34.376861Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:34.376864Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from UNKNOWN to PREPARING
2025-11-05T13:43:34.376870Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] write key for TxId 281474976715673
2025-11-05T13:43:34.376919Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] save tx TxId: 281474976715673 State: PREPARED MinStep: 1762350214394 MaxStep: 18446744073709551615 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_B" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_B" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { }
2025-11-05T13:43:34.376938Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.377050Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.377060Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state PREPARING
2025-11-05T13:43:34.377061Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State PREPARING
2025-11-05T13:43:34.377064Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from PREPARING to PREPARED
2025-11-05T13:43:34.377240Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037896 TxId: 281474976715673
2025-11-05T13:43:34.377389Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488148:2899], now have 1 active actors on pipe
2025-11-05T13:43:34.377407Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715673 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350214422 MediatorID: 72057594046382081 TabletID: 72075186224037896
2025-11-05T13:43:34.377420Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state PREPARED
2025-11-05T13:43:34.377422Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State PREPARED
2025-11-05T13:43:34.377435Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from PREPARED to PLANNING
2025-11-05T13:43:34.377439Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] PlanStep 1762350214422, PlanTxId 281474976715673
2025-11-05T13:43:34.377442Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] write key for TxId 281474976715673
2025-11-05T13:43:34.377488Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] save tx TxId: 281474976715673 State: PLANNED MinStep: 1762350214394 MaxStep: 18446744073709551615 Step: 1762350214422 Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_B" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_B" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { }
2025-11-05T13:43:34.377503Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.377611Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.377622Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state PLANNING
2025-11-05T13:43:34.377624Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State PLANNING
2025-11-05T13:43:34.377626Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from PLANNING to PLANNED
2025-11-05T13:43:34.377628Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxQueue.size 1
2025-11-05T13:43:34.377631Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] New ExecStep 1762350214422, ExecTxId 281474976715673
2025-11-05T13:43:34.377758Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from PLANNED to CALCULATING
2025-11-05T13:43:34.377762Z node 9 :PERSQUEUE DEBUG: [topic_B:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:34.377778Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:34.377827Z node 9 :PERSQUEUE DEBUG: [topic_B:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:34.377894Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037896, Partition: 0, State: StateInit] bootstrapping 0 [9:7569236534852488154:2474]
2025-11-05T13:43:34.378177Z node 9 :PERSQUEUE DEBUG: [topic_B:0:Initializer] Initializing completed.
2025-11-05T13:43:34.378193Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037896, Partition: 0, State: StateInit] init complete for topic 'topic_B' partition 0 generation 1 [9:7569236534852488154:2474]
2025-11-05T13:43:34.378199Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateInit] SYNC INIT topic topic_B partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:34.378280Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:34.378293Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.378318Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.378326Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:34.378328Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.378328Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350214422, TxId 281474976715673, Partition 0
2025-11-05T13:43:34.378330Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.378331Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:34.378332Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:34.378335Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] Partition responses 1/1
2025-11-05T13:43:34.378337Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state CALCULATING
2025-11-05T13:43:34.378340Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Topic 'topic_B' partition 0 user test-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:34.378340Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State CALCULATING
2025-11-05T13:43:34.378343Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673 State CALCULATING FrontTxId 281474976715673
2025-11-05T13:43:34.378346Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Received 1, Expected 1
2025-11-05T13:43:34.378349Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from CALCULATING to CALCULATED
2025-11-05T13:43:34.378352Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] write key for TxId 281474976715673
2025-11-05T13:43:34.378417Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] save tx TxId: 281474976715673 State: CALCULATED MinStep: 1762350214394 MaxStep: 18446744073709551615 Step: 1762350214422 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_B" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_B" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:34.378437Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.378599Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.378605Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state CALCULATED
2025-11-05T13:43:34.378606Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State CALCULATED
2025-11-05T13:43:34.378608Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673 State CALCULATED FrontTxId 281474976715673
2025-11-05T13:43:34.378610Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:34.378617Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:34.378620Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] HaveParticipantsDecision 1
2025-11-05T13:43:34.378624Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:34.378628Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Received 0, Expected 1
2025-11-05T13:43:34.378634Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350214422, TxId 281474976715673
2025-11-05T13:43:34.378645Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.378646Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.378686Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.378752Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.379580Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:34.379584Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] Handle TEvPQ::TEvTxCommitDone Step 1762350214422, TxId 281474976715673, Partition 0
2025-11-05T13:43:34.379588Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state EXECUTING
2025-11-05T13:43:34.379590Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State EXECUTING
2025-11-05T13:43:34.379592Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673 State EXECUTING FrontTxId 281474976715673
2025-11-05T13:43:34.379594Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.379595Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Received 1, Expected 1
2025-11-05T13:43:34.379596Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.379600Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId: 281474976715673 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:34.379610Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] complete TxId 281474976715673
2025-11-05T13:43:34.379664Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_B" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_B" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 }
2025-11-05T13:43:34.379685Z node 9 :PERSQUEUE NOTICE: [PQ: 72075186224037896] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:34.379696Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] delete partitions for TxId 281474976715673
2025-11-05T13:43:34.379707Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from EXECUTING to EXECUTED
2025-11-05T13:43:34.379711Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] write key for TxId 281474976715673
2025-11-05T13:43:34.379764Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] save tx TxId: 281474976715673 State: EXECUTED MinStep: 1762350214394 MaxStep: 18446744073709551615 Step: 1762350214422 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 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: "topic_B" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_B" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 } } BootstrapConfig { } SourceActor { RawX1: 7569236509082683048 RawX2: 38654707814 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:34.379795Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.380096Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037897
2025-11-05T13:43:34.380126Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.380135Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Registered with mediator time cast
2025-11-05T13:43:34.380137Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.380140Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state EXECUTED
2025-11-05T13:43:34.380142Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State EXECUTED
2025-11-05T13:43:34.380144Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673 State EXECUTED FrontTxId 281474976715673
2025-11-05T13:43:34.380146Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.380146Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:34.380149Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:34.380150Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:34.380155Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:34.380163Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] PredicateAcks: 0/0
2025-11-05T13:43:34.380169Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:34.380171Z node 9 :PQ_TX DEBUG: [TxId: 281474976715673] PredicateAcks: 0/0
2025-11-05T13:43:34.380173Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] add an TxId 281474976715673 to the list for deletion
2025-11-05T13:43:34.380174Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] TxId 281474976715673 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:34.380177Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] delete key for TxId 281474976715673
2025-11-05T13:43:34.380184Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.380284Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.380290Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Try execute txs with state DELETING
2025-11-05T13:43:34.380291Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxId 281474976715673, State DELETING
2025-11-05T13:43:34.380293Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] delete TxId 281474976715673
2025-11-05T13:43:34.380651Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:34.380879Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:34.380884Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:5994
2025-11-05T13:43:34.381876Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "topic_B" message_group_id: "src" }
2025-11-05T13:43:34.381955Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.381967Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2025-11-05T13:43:34.382063Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic_B" message_group_id: "src" }
2025-11-05T13:43:34.382083Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 3 topic: "topic_B" message_group_id: "src" from ipv6:[::1]:36768
2025-11-05T13:43:34.382089Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36768 proto=v1  topic=topic_B durationSec=0
2025-11-05T13:43:34.382093Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.382447Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2025-11-05T13:43:34.382481Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.382486Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.382487Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.382509Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852488189:2482] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.382517Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:34.382647Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037896, NodeId 9, Generation: 1
2025-11-05T13:43:34.382650Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488192:2482], now have 1 active actors on pipe
2025-11-05T13:43:34.382656Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.382660Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.382680Z node 9 :PERSQUEUE INFO: new Cookie src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0 generated for partition 0 topic 'topic_B' owner src
2025-11-05T13:43:34.382687Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.382691Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.382701Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.382714Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.382736Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.382773Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.382780Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.382800Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.382822Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 0 MaxSeqNo: 0 sessionId: src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0
2025-11-05T13:43:34.383009Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350214383 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:34.383031Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0" topic: "topic_B"
2025-11-05T13:43:34.383118Z :INFO: [/Root] MessageGroupId [src] SessionId [src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:34.383126Z :INFO: [/Root] MessageGroupId [src] SessionId [src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0] Write session will now close
2025-11-05T13:43:34.383130Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0] Write session: aborting
2025-11-05T13:43:34.383252Z :INFO: [/Root] MessageGroupId [src] SessionId [src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.383256Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0] Write session: destroy
2025-11-05T13:43:34.383377Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.383387Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0 grpc read failed
2025-11-05T13:43:34.383395Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0 grpc closed
2025-11-05T13:43:34.383397Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: src|a2bc07ce-73c62de-6cfc12a8-ca0d888f_0 is DEAD
2025-11-05T13:43:34.383574Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.383620Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server disconnected, pipe [9:7569236534852488192:2482] destroyed
2025-11-05T13:43:34.383631Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.383639Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.383640Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.386286Z node 9 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715674:0, at schemeshard:  72057594046644480
2025-11-05T13:43:34.386831Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037897
2025-11-05T13:43:34.386845Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.386855Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:34.386893Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:34.386900Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Registered with mediator time cast
2025-11-05T13:43:34.386901Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.427169Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.427186Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.440142Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:34.440169Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037897
2025-11-05T13:43:34.440186Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Registered with mediator time cast
2025-11-05T13:43:34.440190Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:34.440194Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:34.440287Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:34.440950Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.440960Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.478361Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.478379Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.491225Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: try to update token
2025-11-05T13:43:34.491381Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Start write session. Will connect to nodeId: 0
2025-11-05T13:43:34.491659Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: write to message_group: test-message_group_id
2025-11-05T13:43:34.491702Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: send init request: init_request { path: "topic_A" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" }
2025-11-05T13:43:34.491706Z :TRACE: [/Root] TRACE_EVENT InitRequest 
2025-11-05T13:43:34.491838Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:34.491942Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.491960Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2025-11-05T13:43:34.492140Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { path: "topic_A" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" }
2025-11-05T13:43:34.492167Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 4 path: "topic_A" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" from ipv6:[::1]:36768
2025-11-05T13:43:34.492177Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="topic server" ip=ipv6:[::1]:36768 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:34.492181Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.492525Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2025-11-05T13:43:34.492594Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.492601Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.492603Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.492617Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852488356:2514] (SourceId=test-message_group_id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.492622Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:34.492813Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 9, Generation: 1
2025-11-05T13:43:34.492829Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852488359:2514], now have 1 active actors on pipe
2025-11-05T13:43:34.492839Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.492846Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.492892Z node 9 :PERSQUEUE INFO: new Cookie test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:34.492908Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.492918Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.492931Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.492945Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.492981Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.493033Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.493046Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.493075Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.493097Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0
2025-11-05T13:43:34.493403Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.493449Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350214493 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:34.493474Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session established. Init response: session_id: "test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0"
2025-11-05T13:43:34.493479Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0
2025-11-05T13:43:34.493483Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  MessageGroupId [test-message_group_id] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:34.493586Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:43:34.493597Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_A partition_id=0
2025-11-05T13:43:34.493627Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:43:34.494149Z node 9 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:43:34.494180Z node 9 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_A"
include_location: true
2025-11-05T13:43:34.494191Z node 9 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[9:7569236534852488362:2516]: Bootstrap
2025-11-05T13:43:34.494566Z node 9 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [9:7569236534852488362:2516]: Request location
2025-11-05T13:43:34.494664Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [9:7569236534852488371:2517] connected; active server actors: 1
2025-11-05T13:43:34.494681Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] addPartitionToResponse tabletId 72075186224037894, partitionId 0, NodeId 9, Generation 1
2025-11-05T13:43:34.494691Z node 9 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [9:7569236534852488362:2516]: Got location
2025-11-05T13:43:34.494722Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [9:7569236534852488371:2517] disconnected; active server actors: 1
2025-11-05T13:43:34.494730Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [9:7569236534852488371:2517] disconnected no session
2025-11-05T13:43:34.495076Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 9
    generation: 1
  }
}
2025-11-05T13:43:34.495091Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=9 pl_generation=1
2025-11-05T13:43:34.495098Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 9 exists in the endpoint pool.
2025-11-05T13:43:34.495105Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=9 Generation=1
2025-11-05T13:43:34.495110Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 9
2025-11-05T13:43:34.495364Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 1, Msg: CANCELLED, Details: , InternalError: 0
2025-11-05T13:43:34.495435Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.495447Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0 grpc read failed
2025-11-05T13:43:34.495456Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0 grpc closed
2025-11-05T13:43:34.495459Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0 is DEAD
2025-11-05T13:43:34.495511Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:43:34.495538Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Write session: send init request: init_request { path: "topic_A" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } }
2025-11-05T13:43:34.495543Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:43:34.495642Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:34.495643Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.495654Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 5
2025-11-05T13:43:34.495712Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.495751Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [9:7569236534852488359:2514] destroyed
2025-11-05T13:43:34.495760Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId:  grpc read done: success: 1 data: init_request { path: "topic_A" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } }
2025-11-05T13:43:34.495762Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.495768Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.495771Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.495779Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 5 path: "topic_A" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } from ipv6:[::1]:36768
2025-11-05T13:43:34.495783Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=5 sessionId= userAgent="topic server" ip=ipv6:[::1]:36768 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:34.495787Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.495793Z node 9 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:43:34.496005Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId:  describe result for acl check
2025-11-05T13:43:34.496054Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.496061Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.496062Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.496069Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852488376:2519] (SourceId=test-message_group_id, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.496074Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 5 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:43:34.496166Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 9, Generation: 1
2025-11-05T13:43:34.496182Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852488379:2519], now have 1 active actors on pipe
2025-11-05T13:43:34.496191Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.496196Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.496230Z node 9 :PERSQUEUE INFO: new Cookie test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:34.496245Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.496250Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.496263Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.496278Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.496305Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.496345Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.496353Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.496366Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.496386Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 5 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0
2025-11-05T13:43:34.496644Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.496669Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|54d7e6fa-4a2b3d60-14e082ab-4e3a7934_0]  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0"
2025-11-05T13:43:34.496677Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0
2025-11-05T13:43:34.496682Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:34.496743Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=1, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=1, AckCount=0
2025-11-05T13:43:34.496758Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:43:34.496776Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:34.496780Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:43:34.496937Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: try to update token
2025-11-05T13:43:34.496975Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:34.497145Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Start write session. Will connect to nodeId: 0
2025-11-05T13:43:34.497060Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP for a WriteId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e
2025-11-05T13:43:34.497200Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 9, Generation: 1
2025-11-05T13:43:34.497208Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [9:7569236534852488382:2519], now have 1 active actors on pipe
2025-11-05T13:43:34.497314Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: write to message_group: test-message_group_id
2025-11-05T13:43:34.497335Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: send init request: init_request { path: "topic_B" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" }
2025-11-05T13:43:34.497338Z :TRACE: [/Root] TRACE_EVENT InitRequest 
2025-11-05T13:43:34.497454Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:34.497487Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of the request to KQP for the WriteId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e Status: SUCCESS
2025-11-05T13:43:34.497497Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e WriteId: {9, 281474976715679}
2025-11-05T13:43:34.497546Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.497558Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.497565Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] partition {0, {9, 281474976715679}, 100000} for WriteId {9, 281474976715679}
2025-11-05T13:43:34.497611Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvSubscribeLock for WriteId {9, 281474976715679}
2025-11-05T13:43:34.497640Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.497864Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715679 LockNode: 9 Status: STATUS_SUBSCRIBED
2025-11-05T13:43:34.497874Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {9, 281474976715679}, TxId (empty maybe), Status STATUS_UNSPECIFIED
2025-11-05T13:43:34.497877Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] subscribed WriteId {9, 281474976715679}
2025-11-05T13:43:34.497881Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.497884Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 6
2025-11-05T13:43:34.497951Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.498079Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:34.498143Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:34.498222Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateInit] bootstrapping {0, {9, 281474976715679}, 100000} [9:7569236534852488390:2523]
2025-11-05T13:43:34.498477Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:43:34.498587Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:43:34.498610Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:43:34.498646Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:43:34.498659Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:43:34.498662Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:43:34.498665Z node 9 :PERSQUEUE INFO: [topic_A:{0, {9, 281474976715679}, 100000}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:43:34.498667Z node 9 :PERSQUEUE DEBUG: [topic_A:{0, {9, 281474976715679}, 100000}:Initializer] Initializing completed.
2025-11-05T13:43:34.498672Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateInit] init complete for topic 'topic_A' partition {0, {9, 281474976715679}, 100000} generation 1 [9:7569236534852488390:2523]
2025-11-05T13:43:34.498678Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateInit] SYNC INIT topic topic_A partitition {0, {9, 281474976715679}, 100000} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:34.498685Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:43:34.498688Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.498692Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.498771Z node 9 :PERSQUEUE INFO: new Cookie test-message_group_id|2a420d76-b7643e6d-63bc7cb3-8e97870_0 generated for partition {0, {9, 281474976715679}, 100000} topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:34.498777Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.498781Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.498787Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.498795Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.498806Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.498818Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e
2025-11-05T13:43:34.498928Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e Status: SUCCESS
2025-11-05T13:43:34.498946Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.498948Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.498964Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.498998Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.499000Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.499019Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.499029Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:43:34.499044Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.499067Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:34.499069Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:34.499077Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.499086Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 0 messageNo: 1 size 216 offset: -1
2025-11-05T13:43:34.499102Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.499108Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.499125Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {9, 281474976715679}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 0
2025-11-05T13:43:34.499162Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {9, 281474976715679}, 100000} part blob complete sourceId '\0test-message_group_id' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 305 count 1 nextOffset 1 batches 1
2025-11-05T13:43:34.499169Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.499212Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {9, 281474976715679}, 100000} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100000_00000000000000000000_00000_0000000001_00000| size 293 WTime 1762350214498
2025-11-05T13:43:34.499240Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.499248Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 0 partNo 0 count 1 size 293
2025-11-05T13:43:34.499724Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId:  grpc read done: success: 1 data: init_request { path: "topic_B" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" }
2025-11-05T13:43:34.499757Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 6 path: "topic_B" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" from ipv6:[::1]:36768
2025-11-05T13:43:34.499765Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=6 sessionId= userAgent="topic server" ip=ipv6:[::1]:36768 proto=topic  topic=topic_B durationSec=0
2025-11-05T13:43:34.499769Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.500145Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.500188Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 1 written_in_tx { } } write_statistics { persisting_time { nanos: 1000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:43:34.500199Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=1, AckCount=1
2025-11-05T13:43:34.500204Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:43:34.499786Z node 9 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 0 count 1 size 293 actorID [9:7569236534852488001:2453]
2025-11-05T13:43:34.499839Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 238 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:34.500811Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.499843Z node 9 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 0 size 293
2025-11-05T13:43:34.500838Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350214500 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:34.499851Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.500852Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session established. Init response: session_id: "test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0"
2025-11-05T13:43:34.499861Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {9, 281474976715679}, 100000}, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:43:34.500856Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0
2025-11-05T13:43:34.500859Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  MessageGroupId [test-message_group_id] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:34.499881Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.499883Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.499911Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-11-05T13:43:34.499958Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.500244Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId:  describe result for acl check
2025-11-05T13:43:34.500287Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.500288Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.500290Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.500300Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852488401:2522] (SourceId=test-message_group_id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.500305Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 6 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:34.500425Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037896, NodeId 9, Generation: 1
2025-11-05T13:43:34.500435Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488404:2522], now have 1 active actors on pipe
2025-11-05T13:43:34.500444Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.500448Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.500468Z node 9 :PERSQUEUE INFO: new Cookie test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0 generated for partition 0 topic 'topic_B' owner test-message_group_id
2025-11-05T13:43:34.500474Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.500478Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.500483Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.500938Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:43:34.500490Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.500499Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.500524Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.500526Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.500535Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.500547Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 6 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0
2025-11-05T13:43:34.500965Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_B partition_id=0
2025-11-05T13:43:34.500998Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:43:34.501513Z node 9 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:43:34.501553Z node 9 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_B"
include_location: true
2025-11-05T13:43:34.501571Z node 9 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[9:7569236534852488407:2526]: Bootstrap
2025-11-05T13:43:34.501984Z node 9 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [9:7569236534852488407:2526]: Request location
2025-11-05T13:43:34.502035Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037897][topic_B] pipe [9:7569236534852488416:2527] connected; active server actors: 1
2025-11-05T13:43:34.502049Z node 9 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037897][topic_B] addPartitionToResponse tabletId 72075186224037896, partitionId 0, NodeId 9, Generation 1
2025-11-05T13:43:34.502054Z node 9 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [9:7569236534852488407:2526]: Got location
2025-11-05T13:43:34.502094Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037897][topic_B] pipe [9:7569236534852488416:2527] disconnected; active server actors: 1
2025-11-05T13:43:34.502096Z node 9 :PERSQUEUE_READ_BALANCER INFO: [72075186224037897][topic_B] pipe [9:7569236534852488416:2527] disconnected no session
2025-11-05T13:43:34.502666Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 9
    generation: 1
  }
}
2025-11-05T13:43:34.502675Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=9 pl_generation=1
2025-11-05T13:43:34.502682Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 9 exists in the endpoint pool.
2025-11-05T13:43:34.502687Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=9 Generation=1
2025-11-05T13:43:34.502690Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 9
2025-11-05T13:43:34.502953Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 1, Msg: CANCELLED, Details: , InternalError: 0
2025-11-05T13:43:34.503055Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:43:34.503086Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Write session: send init request: init_request { path: "topic_B" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } }
2025-11-05T13:43:34.503090Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:43:34.503203Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:34.503156Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId: test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.503164Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0 grpc read failed
2025-11-05T13:43:34.503171Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0 grpc closed
2025-11-05T13:43:34.503174Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0 is DEAD
2025-11-05T13:43:34.503342Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.503411Z node 9 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:34.503414Z node 9 :PQ_WRITE_PROXY DEBUG: new session created cookie 7
2025-11-05T13:43:34.503714Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server disconnected, pipe [9:7569236534852488404:2522] destroyed
2025-11-05T13:43:34.503742Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId:  grpc read done: success: 1 data: init_request { path: "topic_B" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } }
2025-11-05T13:43:34.503760Z node 9 :PQ_WRITE_PROXY INFO: session request cookie: 7 path: "topic_B" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } from ipv6:[::1]:36768
2025-11-05T13:43:34.503763Z node 9 :PQ_WRITE_PROXY INFO: write session:  cookie=7 sessionId= userAgent="topic server" ip=ipv6:[::1]:36768 proto=topic  topic=topic_B durationSec=0
2025-11-05T13:43:34.503767Z node 9 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:34.503773Z node 9 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:43:34.503783Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.503788Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.503790Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.504044Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId:  describe result for acl check
2025-11-05T13:43:34.504079Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:34.504080Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:34.504081Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:34.504087Z node 9 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [9:7569236534852488421:2529] (SourceId=test-message_group_id, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:34.504091Z node 9 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 7 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:43:34.504257Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037896, NodeId 9, Generation: 1
2025-11-05T13:43:34.504275Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488424:2529], now have 1 active actors on pipe
2025-11-05T13:43:34.504328Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.504343Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.504370Z node 9 :PERSQUEUE INFO: new Cookie test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 generated for partition 0 topic 'topic_B' owner test-message_group_id
2025-11-05T13:43:34.504401Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.504406Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.504418Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.504431Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:34.504465Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.504553Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.504562Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.504582Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.504610Z node 9 :PQ_WRITE_PROXY INFO: session inited cookie: 7 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0
2025-11-05T13:43:34.504859Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.504885Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5767950-fb21275a-2d793edd-6ab78527_0]  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0"
2025-11-05T13:43:34.504891Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0
2025-11-05T13:43:34.504895Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:34.504959Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=1, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=1, AckCount=0
2025-11-05T13:43:34.504972Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:43:34.504992Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:34.504996Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:43:34.505075Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=2, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=2, AckCount=0
2025-11-05T13:43:34.505079Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 2 to 2
2025-11-05T13:43:34.505086Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:34.505088Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 2
2025-11-05T13:43:34.505110Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=3, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=3, AckCount=0
2025-11-05T13:43:34.505113Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 3 to 3
2025-11-05T13:43:34.505115Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:34.505117Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 3
2025-11-05T13:43:34.505535Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:34.505617Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Start of a request to KQP for a WriteId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e
2025-11-05T13:43:34.505796Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037896, NodeId 9, Generation: 1
2025-11-05T13:43:34.505812Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server connected, pipe [9:7569236534852488427:2529], now have 1 active actors on pipe
2025-11-05T13:43:34.505869Z node 9 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ==, ActorId: [9:7569236534852488265:2494], ActorState: ExecuteState, TraceId: 01k9a44bb7bqrt868a7w4rdz6v, Reply query error, msg: Pending previous query completion proxyRequestId: 24
2025-11-05T13:43:34.505959Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) End of the request to KQP for the WriteId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e Status: SUCCESS
2025-11-05T13:43:34.505962Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e WriteId: {9, 281474976715679}
2025-11-05T13:43:34.505976Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.505981Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.505988Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] partition {0, {9, 281474976715679}, 100000} for WriteId {9, 281474976715679}
2025-11-05T13:43:34.506027Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] send TEvSubscribeLock for WriteId {9, 281474976715679}
2025-11-05T13:43:34.506047Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.506084Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715679 LockNode: 9 Status: STATUS_SUBSCRIBED
2025-11-05T13:43:34.506089Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxWriteInfo: WriteId {9, 281474976715679}, TxId (empty maybe), Status STATUS_UNSPECIFIED
2025-11-05T13:43:34.506092Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] subscribed WriteId {9, 281474976715679}
2025-11-05T13:43:34.506335Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:34.506339Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.506421Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:34.506446Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:34.506513Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:34.506578Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateInit] bootstrapping {0, {9, 281474976715679}, 100000} [9:7569236534852488436:2532]
2025-11-05T13:43:34.506929Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:43:34.507046Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:43:34.507079Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:43:34.507115Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:43:34.507136Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:43:34.507143Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:43:34.507146Z node 9 :PERSQUEUE INFO: [topic_B:{0, {9, 281474976715679}, 100000}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:43:34.507148Z node 9 :PERSQUEUE DEBUG: [topic_B:{0, {9, 281474976715679}, 100000}:Initializer] Initializing completed.
2025-11-05T13:43:34.507153Z node 9 :PERSQUEUE INFO: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateInit] init complete for topic 'topic_B' partition {0, {9, 281474976715679}, 100000} generation 1 [9:7569236534852488436:2532]
2025-11-05T13:43:34.507158Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateInit] SYNC INIT topic topic_B partitition {0, {9, 281474976715679}, 100000} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:34.507163Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:43:34.507165Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.507168Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.507236Z node 9 :PERSQUEUE INFO: new Cookie test-message_group_id|d00edee9-d4364669-eac713eb-464dde44_0 generated for partition {0, {9, 281474976715679}, 100000} topic 'topic_B' owner test-message_group_id
2025-11-05T13:43:34.507246Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.507250Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.507257Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.507263Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.507282Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.507293Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Start of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e
2025-11-05T13:43:34.507394Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) End of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=9&id=N2ExYTIyNDctMzVlMzcxMWQtODM5M2VhYy03ZTQ0N2U0OQ== TxId: 01k9a44b9abc1mgbymn03gdc5e Status: SUCCESS
2025-11-05T13:43:34.507535Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507547Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507571Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:34.507641Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507650Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507672Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.507687Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507693Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507698Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.507707Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507713Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507717Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.507727Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:43:34.507736Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 1  requestId: <none> cookie: 2
2025-11-05T13:43:34.507743Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 2  requestId: <none> cookie: 3
2025-11-05T13:43:34.507742Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.507749Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.507763Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.507789Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507792Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507810Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Write in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.507821Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message topic: topic_B partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 0 messageNo: 3 size 81 offset: -1
2025-11-05T13:43:34.507831Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507837Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507843Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Write in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.507851Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message topic: topic_B partition: 0 SourceId: '\0test-message_group_id' SeqNo: 2 partNo : 0 messageNo: 4 size 81 offset: -1
2025-11-05T13:43:34.507855Z node 9 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_B' requestId: <none>
2025-11-05T13:43:34.507861Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message batch for topic 'topic_B' partition 0
2025-11-05T13:43:34.507866Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Write in transaction. Partition: 0, WriteId: { NodeId: 9 KeyId: 281474976715679 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:34.507876Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] got client message topic: topic_B partition: 0 SourceId: '\0test-message_group_id' SeqNo: 3 partNo : 0 messageNo: 5 size 81 offset: -1
2025-11-05T13:43:34.507894Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.507903Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.507923Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_B' partition {0, {9, 281474976715679}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 0
2025-11-05T13:43:34.507951Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_B' partition {0, {9, 281474976715679}, 100000} part blob complete sourceId '\0test-message_group_id' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 170 count 1 nextOffset 1 batches 1
2025-11-05T13:43:34.507961Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.508001Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Add new write blob: topic 'topic_B' partition {0, {9, 281474976715679}, 100000} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100000_00000000000000000000_00000_0000000001_00000| size 158 WTime 1762350214507
2025-11-05T13:43:34.508034Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Can't process txs
2025-11-05T13:43:34.508042Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Can't process txs
2025-11-05T13:43:34.508043Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.508055Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 0 partNo 0 count 1 size 158
2025-11-05T13:43:34.508240Z node 9 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 0 count 1 size 158 actorID [9:7569236534852488130:2473]
2025-11-05T13:43:34.508269Z node 9 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037896' partition 100000 offset 0 partno 0 count 1 parts 0 size 158
2025-11-05T13:43:34.508638Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 103 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:34.508656Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.508670Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_B', Partition: {0, {9, 281474976715679}, 100000}, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:43:34.508686Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 3  requestId: <none> cookie: 1
2025-11-05T13:43:34.508690Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.508695Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.508706Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.508707Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_B' partition {0, {9, 281474976715679}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 2 partNo 0
2025-11-05T13:43:34.508724Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_B' partition {0, {9, 281474976715679}, 100000} part blob complete sourceId '\0test-message_group_id' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 170 count 1 nextOffset 2 batches 1
2025-11-05T13:43:34.508735Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_B' partition {0, {9, 281474976715679}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 3 partNo 0
2025-11-05T13:43:34.508740Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Topic 'topic_B' partition {0, {9, 281474976715679}, 100000} part blob complete sourceId '\0test-message_group_id' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 308 count 2 nextOffset 3 batches 1
2025-11-05T13:43:34.508743Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.508773Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Add new write blob: topic 'topic_B' partition {0, {9, 281474976715679}, 100000} compactOffset 1,2 HeadOffset 0 endOffset 1 curOffset 3 D0000100000_00000000000000000001_00000_0000000002_00000| size 287 WTime 1762350214508
2025-11-05T13:43:34.508799Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.508809Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 1 partNo 0 count 2 size 287
2025-11-05T13:43:34.508963Z node 9 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 1 count 2 size 287 actorID [9:7569236534852488130:2473]
2025-11-05T13:43:34.508986Z node 9 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037896' partition 100000 offset 1 partno 0 count 2 parts 0 size 287
2025-11-05T13:43:34.509009Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.509049Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 1 written_in_tx { } } write_statistics { persisting_time { nanos: 1000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:43:34.509058Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=3, AckCount=1
2025-11-05T13:43:34.509062Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:43:34.509059Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 206 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:34.509070Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.509083Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_B', Partition: {0, {9, 281474976715679}, 100000}, SeqNo: 2, partNo: 0, Offset: 1 is stored on disk
2025-11-05T13:43:34.509090Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.509094Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_B', Partition: {0, {9, 281474976715679}, 100000}, SeqNo: 3, partNo: 0, Offset: 2 is stored on disk
2025-11-05T13:43:34.509102Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 4  requestId: <none> cookie: 2
2025-11-05T13:43:34.509109Z node 9 :PERSQUEUE DEBUG: Answer ok topic: 'topic_B' partition: 0 messageNo: 5  requestId: <none> cookie: 3
2025-11-05T13:43:34.509110Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.509112Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.509124Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.509134Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:34.509391Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.509408Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 2 written_in_tx { } } write_statistics { persisting_time { } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:43:34.509441Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] OnAck: seqNo=2, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=3, AckCount=2
2025-11-05T13:43:34.509444Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 2
2025-11-05T13:43:34.509597Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:34.509634Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 3 written_in_tx { } } write_statistics { persisting_time { } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:43:34.509644Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] OnAck: seqNo=3, txId=01k9a44b9abc1mgbymn03gdc5e, WriteCount=3, AckCount=3
2025-11-05T13:43:34.509647Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 3
2025-11-05T13:43:34.527789Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.527811Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.541351Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.541375Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.578716Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.578742Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.598697Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.598716Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.607413Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.607432Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.627882Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.627904Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
[[bad]]assertion failed at ydb/public/sdk/cpp/src/client/topic/ut/topic_to_table_ut.cpp:2283, void NYdb::NTopic::NTests::NTestSuiteTxUsage::TFixture::DeleteFromTable(const TString &, const TVector<TTableRecord> &, NTable::TTransaction *): (result.IsSuccess()) <main>: Error: Pending previous query completion
[[rst]]
[[alt1]]NUnitTest::NPrivate::RaiseError(char const*, TBasicString<char, std::__y1::char_traits<char>> const&, bool)+137 (0x13963469)
NYdb::NTopic::NTests::NTestSuiteTxUsage::TFixture::DeleteFromTable(TBasicString<char, std::__y1::char_traits<char>> const&, TVector<NYdb::NTopic::NTests::NTestSuiteTxUsage::TFixture::TTableRecord, std::__y1::allocator<NYdb::NTopic::NTests::NTestSuiteTxUsage::TFixture::TTableRecord>> const&, NYdb::V3::NTable::TTransaction*)+1345 (0x136AB2D1)
NYdb::NTopic::NTests::NTestSuiteTxUsage::TFixtureSinks::TestSinksOltpWriteToTopicAndTable6()+1453 (0x136BF9BD)
NYdb::NTopic::NTests::NTestSuiteTxUsage::TCurrentTest::Execute()::'lambda'()::operator()() const+71 (0x136D04D7)
NUnitTest::TTestBase::Run(std::__y1::function<void ()>, TBasicString<char, std::__y1::char_traits<char>> const&, char const*, bool)+126 (0x1396532E)
NYdb::NTopic::NTests::NTestSuiteTxUsage::TCurrentTest::Execute()+395 (0x136CFE9B)
NUnitTest::TTestFactory::Execute()+803 (0x13965AA3)
NUnitTest::RunMain(int, char**)+3021 (0x13976F3D)
??+0 (0x7FAA04353D90)
__libc_start_main+128 (0x7FAA04353E40)
_start+41 (0x12766029)
[[rst]]
2025-11-05T13:43:34.631282Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 0.000000s
2025-11-05T13:43:34.631289Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:43:34.631296Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:43:34.631418Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.631424Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:43:34.631634Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 0.000000s
2025-11-05T13:43:34.631637Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:43:34.631640Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:43:34.631708Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.631711Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:43:34.631719Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.631734Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 grpc read failed
2025-11-05T13:43:34.631742Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 grpc closed
2025-11-05T13:43:34.631745Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId: test-message_group_id|aa23c1b6-27fdbd89-205bf2f7-95925508_0 is DEAD
2025-11-05T13:43:34.631934Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.631951Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037896 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.632045Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server disconnected, pipe [9:7569236534852488427:2529] destroyed
2025-11-05T13:43:34.632062Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] server disconnected, pipe [9:7569236534852488424:2529] destroyed
2025-11-05T13:43:34.632077Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.632089Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.632095Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.632108Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.632114Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.632115Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.632333Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715679 LockNode: 9 Status: STATUS_NOT_FOUND
2025-11-05T13:43:34.632346Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {9, 281474976715679}, TxId (empty maybe), Status STATUS_SUBSCRIBED
2025-11-05T13:43:34.632348Z node 9 :PQ_TX INFO: [PQ: 72075186224037894] delete partitions for WriteId {9, 281474976715679} (longTxService lost tx)
2025-11-05T13:43:34.632352Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvPQ::TEvDeletePartition to partition {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.632357Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715679 LockNode: 9 Status: STATUS_NOT_FOUND
2025-11-05T13:43:34.632359Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] TxWriteInfo: WriteId {9, 281474976715679}, TxId (empty maybe), Status STATUS_SUBSCRIBED
2025-11-05T13:43:34.632360Z node 9 :PQ_TX INFO: [PQ: 72075186224037896] delete partitions for WriteId {9, 281474976715679} (longTxService lost tx)
2025-11-05T13:43:34.632362Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] send TEvPQ::TEvDeletePartition to partition {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.632370Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Handle TEvPQ::TEvDeletePartition
2025-11-05T13:43:34.632384Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Handle TEvPQ::TEvDeletePartition
2025-11-05T13:43:34.632394Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.632398Z node 9 :PERSQUEUE DEBUG: CacheProxy. Delete blobs from D0000100000(+) to D0000100001(-)
2025-11-05T13:43:34.632409Z node 9 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:34.632414Z node 9 :PERSQUEUE DEBUG: CacheProxy. Delete blobs from D0000100000(+) to D0000100001(-)
2025-11-05T13:43:34.632729Z node 9 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100000 offset 0 count 1 actorID [9:7569236534852488001:2453]
2025-11-05T13:43:34.632760Z node 9 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100000 offset 0 count 1 actorID [9:7569236534852488130:2473]
2025-11-05T13:43:34.632767Z node 9 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100000 offset 1 count 2 actorID [9:7569236534852488130:2473]
2025-11-05T13:43:34.632778Z node 9 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.632781Z node 9 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 0
2025-11-05T13:43:34.632784Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0 grpc read failed
2025-11-05T13:43:34.632790Z node 9 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037896' partition 100000 offset 0 partno 0 count 1 parts 0
2025-11-05T13:43:34.632792Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0 grpc closed
2025-11-05T13:43:34.632795Z node 9 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: test-message_group_id|b9190417-e78bdc7f-109e4eec-8b450a59_0 is DEAD
2025-11-05T13:43:34.632803Z node 9 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037896' partition 100000 offset 1 partno 0 count 2 parts 0
2025-11-05T13:43:34.633119Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.633135Z node 9 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.633198Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.633204Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.633332Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.633338Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896, Partition: {0, {9, 281474976715679}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.633482Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvDeletePartitionDone {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.633493Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] DeletePartition {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.633500Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvUnsubscribeLock for WriteId {9, 281474976715679}
2025-11-05T13:43:34.633522Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.633610Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] Handle TEvPQ::TEvDeletePartitionDone {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.633622Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] DeletePartition {0, {9, 281474976715679}, 100000}
2025-11-05T13:43:34.633626Z node 9 :PQ_TX DEBUG: [PQ: 72075186224037896] send TEvUnsubscribeLock for WriteId {9, 281474976715679}
2025-11-05T13:43:34.633636Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:34.633697Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [9:7569236534852488379:2519] destroyed
2025-11-05T13:43:34.633704Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [9:7569236534852488382:2519] destroyed
2025-11-05T13:43:34.633708Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.633714Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.633731Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.633809Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037896] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.633835Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:34.641723Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.641744Z node 9 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
