2025-11-05T13:43:08.686334Z node 4 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[4:7569236423471942574:2141];send_to=[0:7307199536658146131:7762515];
2025-11-05T13:43:08.687879Z node 4 :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:08.689669Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: : Created
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/4xc1/003f3f/r3tmp/tmpp3vbgj/pdisk_1.dat
2025-11-05T13:43:08.701913Z node 4 :IMPORT WARN: Table profiles were not loaded
2025-11-05T13:43:08.702165Z node 4 :CONFIGS_DISPATCHER ERROR: Notification cookie mismatch for subscription [4:7569236423471942467:2081] 1762350188685189 != 1762350188685192
TServer::EnableGrpc on GrpcPort 14608, node 4
2025-11-05T13:43:08.708866Z node 4 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/4xc1/003f3f/r3tmp/yandexR7GrjF.tmp
2025-11-05T13:43:08.708880Z node 4 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/4xc1/003f3f/r3tmp/yandexR7GrjF.tmp
2025-11-05T13:43:08.708938Z node 4 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/4xc1/003f3f/r3tmp/yandexR7GrjF.tmp
2025-11-05T13:43:08.708986Z node 4 :NET_CLASSIFIER ERROR: got bad distributable configuration
2025-11-05T13:43:08.713505Z INFO: TTestServer started on Port 8617 GrpcPort 14608
TClient is connected to server localhost:8617
PQClient connected to localhost:14608
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:08.789737Z node 4 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-11-05T13:43:08.789767Z node 4 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-11-05T13:43:08.790077Z node 4 :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:08.790773Z node 4 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Connecting -> Connected
waiting...
2025-11-05T13:43:08.800800Z node 4 :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:08.950737Z node 4 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [4:7569236423471943230: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:08.950965Z node 4 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=4&id=OGYwYzRhMmEtYmRhYWNlYzAtMTk4MDE4YWUtNTgxMDI0NzY=, ActorId: [4:7569236423471943227:2314], ActorState: ExecuteState, TraceId: 01k9a43jck69cz7962jxy1wz3q, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-11-05T13:43:08.951077Z node 4 :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:08.952887Z node 4 :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:08.959698Z node 4 :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:08.976895Z node 4 :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 [4:7569236427766910803:2561] 
2025-11-05T13:43:09.688149Z node 4 :TX_CONVEYOR ERROR: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-11-05T13:43:13.685850Z node 4 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[4:7569236423471942574:2141];send_to=[0:7307199536658146131:7762515];
2025-11-05T13:43:13.685892Z node 4 :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:14.096025Z :WriteToTopic_Demo_14 INFO: TTopicSdkTestSetup started
2025-11-05T13:43:14.098288Z node 4 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:14.100897Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037893][] pipe [4:7569236449241747591:2731] connected; active server actors: 1
2025-11-05T13:43:14.100898Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:14.101006Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:14.101031Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:14.101046Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:14.101070Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] doesn't have tx info
2025-11-05T13:43:14.101076Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:14.101077Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-11-05T13:43:14.101080Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:14.101084Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:14.101088Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037892] doesn't have tx writes info
2025-11-05T13:43:14.101096Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:14.101101Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236449241747590:2730], now have 1 active actors on pipe
2025-11-05T13:43:14.101105Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] BALANCER INIT DONE for test-topic: (0, 72075186224037892) 
2025-11-05T13:43:14.101197Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72075186224037892, NodeId 4, Generation 1
2025-11-05T13:43:14.101203Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72057594046644480, NodeId 4, Generation 2
2025-11-05T13:43:14.101245Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236423471942825 RawX2: 17179871338 } 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:14.101271Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] Propose TxId 281474976715671, WriteId (empty maybe)
2025-11-05T13:43:14.101278Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state UNKNOWN
2025-11-05T13:43:14.101280Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State UNKNOWN
2025-11-05T13:43:14.101283Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:14.101285Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from UNKNOWN to PREPARING
2025-11-05T13:43:14.101290Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:14.101326Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: PREPARED MinStep: 1762350194143 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: 7569236423471942825 RawX2: 17179871338 } Partitions { }
2025-11-05T13:43:14.101344Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.101352Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236449241747623:2422], now have 1 active actors on pipe
2025-11-05T13:43:14.101492Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.101503Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARING
2025-11-05T13:43:14.101505Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PREPARING
2025-11-05T13:43:14.101507Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PREPARING to PREPARED
2025-11-05T13:43:14.101658Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037892 TxId: 281474976715671
2025-11-05T13:43:14.101802Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236449241747635:2758], now have 1 active actors on pipe
2025-11-05T13:43:14.101814Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715671 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350194150 MediatorID: 72057594046382081 TabletID: 72075186224037892
2025-11-05T13:43:14.101822Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARED
2025-11-05T13:43:14.101823Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PREPARED
2025-11-05T13:43:14.101824Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PREPARED to PLANNING
2025-11-05T13:43:14.101828Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] PlanStep 1762350194150, PlanTxId 281474976715671
2025-11-05T13:43:14.101830Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:14.101864Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: PLANNED MinStep: 1762350194143 MaxStep: 18446744073709551615 Step: 1762350194150 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: 7569236423471942825 RawX2: 17179871338 } Partitions { }
2025-11-05T13:43:14.101876Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.101950Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.101955Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PLANNING
2025-11-05T13:43:14.101956Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PLANNING
2025-11-05T13:43:14.101958Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PLANNING to PLANNED
2025-11-05T13:43:14.101959Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxQueue.size 1
2025-11-05T13:43:14.101961Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] New ExecStep 1762350194150, ExecTxId 281474976715671
2025-11-05T13:43:14.102051Z node 4 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:14.102062Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PLANNED to CALCULATING
2025-11-05T13:43:14.102064Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:14.102093Z node 4 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:14.102133Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] bootstrapping 0 [4:7569236449241747641:2426]
2025-11-05T13:43:14.102289Z node 4 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Initializing completed.
2025-11-05T13:43:14.102294Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] init complete for topic 'test-topic' partition 0 generation 1 [4:7569236449241747641:2426]
2025-11-05T13:43:14.102300Z node 4 :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:14.102355Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:14.102361Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.102376Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.102380Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350194150, TxId 281474976715671, Partition 0
2025-11-05T13:43:14.102380Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:14.102381Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:14.102382Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.102383Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] Partition responses 1/1
2025-11-05T13:43:14.102383Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.102385Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-11-05T13:43:14.102384Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:14.102385Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State CALCULATING
2025-11-05T13:43:14.102387Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State CALCULATING FrontTxId 281474976715671
2025-11-05T13:43:14.102389Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:43:14.102390Z node 4 :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:14.102390Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from CALCULATING to CALCULATED
2025-11-05T13:43:14.102392Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:14.102430Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: CALCULATED MinStep: 1762350194143 MaxStep: 18446744073709551615 Step: 1762350194150 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: 7569236423471942825 RawX2: 17179871338 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:14.102552Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.102664Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.102668Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATED
2025-11-05T13:43:14.102669Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State CALCULATED
2025-11-05T13:43:14.102671Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State CALCULATED FrontTxId 281474976715671
2025-11-05T13:43:14.102672Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:14.102678Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:14.102680Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveParticipantsDecision 1
2025-11-05T13:43:14.102685Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:14.102686Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 0, Expected 1
2025-11-05T13:43:14.102688Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350194150, TxId 281474976715671
2025-11-05T13:43:14.102691Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.102692Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.102707Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.102735Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:14.103134Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1762350194150, TxId 281474976715671, Partition 0
2025-11-05T13:43:14.103135Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:14.103141Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.103143Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.103145Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-11-05T13:43:14.103147Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State EXECUTING
2025-11-05T13:43:14.103149Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State EXECUTING FrontTxId 281474976715671
2025-11-05T13:43:14.103152Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:43:14.103157Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId: 281474976715671 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:14.103165Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] complete TxId 281474976715671
2025-11-05T13:43:14.103216Z node 4 :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:14.103234Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:14.103247Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] delete partitions for TxId 281474976715671
2025-11-05T13:43:14.103253Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from EXECUTING to EXECUTED
2025-11-05T13:43:14.103257Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:14.103319Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: EXECUTED MinStep: 1762350194143 MaxStep: 18446744073709551615 Step: 1762350194150 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: 7569236423471942825 RawX2: 17179871338 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:14.103349Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.103767Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:14.103850Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:14.103889Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.103894Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTED
2025-11-05T13:43:14.103896Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State EXECUTED
2025-11-05T13:43:14.103897Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State EXECUTED FrontTxId 281474976715671
2025-11-05T13:43:14.103899Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:14.103900Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:14.103902Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] PredicateAcks: 0/0
2025-11-05T13:43:14.103903Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:14.103904Z node 4 :PQ_TX DEBUG: [TxId: 281474976715671] PredicateAcks: 0/0
2025-11-05T13:43:14.103906Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] add an TxId 281474976715671 to the list for deletion
2025-11-05T13:43:14.103907Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:14.103909Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] delete key for TxId 281474976715671
2025-11-05T13:43:14.103915Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.104004Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.104009Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state DELETING
2025-11-05T13:43:14.104010Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State DELETING
2025-11-05T13:43:14.104012Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] delete TxId 281474976715671
2025-11-05T13:43:14.104278Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:14.104526Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:14.104534Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:14608
2025-11-05T13:43:14.105369Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "test-topic" message_group_id: "src" }
2025-11-05T13:43:14.105447Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:14.105467Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2025-11-05T13:43:14.105557Z node 4 :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:14.105575Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "test-topic" message_group_id: "src" from ipv6:[::1]:50584
2025-11-05T13:43:14.105582Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:50584 proto=v1  topic=test-topic durationSec=0
2025-11-05T13:43:14.105584Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:14.106000Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  describe result for acl check
2025-11-05T13:43:14.106028Z node 4 :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:14.106034Z node 4 :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:14.106036Z node 4 :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:14.106046Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236449241747685:2434] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:14.106050Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 1 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:14.106135Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 4, Generation: 1
2025-11-05T13:43:14.106143Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236449241747688:2434], now have 1 active actors on pipe
2025-11-05T13:43:14.106149Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:43:14.106152Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:43:14.106173Z node 4 :PERSQUEUE INFO: new Cookie src|4788b435-b70ffb7-812dd561-904ece9c_0 generated for partition 0 topic 'test-topic' owner src
2025-11-05T13:43:14.106186Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.106193Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.106202Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.106214Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:14.106235Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.106261Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:43:14.106268Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:43:14.106288Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.106304Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 1 partition: 0 MaxSeqNo: 0 sessionId: src|4788b435-b70ffb7-812dd561-904ece9c_0
2025-11-05T13:43:14.106459Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350194106 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:14.106474Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|4788b435-b70ffb7-812dd561-904ece9c_0" topic: "test-topic"
2025-11-05T13:43:14.106583Z :INFO: [/Root] MessageGroupId [src] SessionId [src|4788b435-b70ffb7-812dd561-904ece9c_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:14.106593Z :INFO: [/Root] MessageGroupId [src] SessionId [src|4788b435-b70ffb7-812dd561-904ece9c_0] Write session will now close
2025-11-05T13:43:14.106601Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|4788b435-b70ffb7-812dd561-904ece9c_0] Write session: aborting
2025-11-05T13:43:14.106721Z :INFO: [/Root] MessageGroupId [src] SessionId [src|4788b435-b70ffb7-812dd561-904ece9c_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:14.106726Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|4788b435-b70ffb7-812dd561-904ece9c_0] Write session: destroy
2025-11-05T13:43:14.106842Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: src|4788b435-b70ffb7-812dd561-904ece9c_0 grpc read done: success: 0 data: 
2025-11-05T13:43:14.106852Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|4788b435-b70ffb7-812dd561-904ece9c_0 grpc read failed
2025-11-05T13:43:14.106857Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|4788b435-b70ffb7-812dd561-904ece9c_0 grpc closed
2025-11-05T13:43:14.106860Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|4788b435-b70ffb7-812dd561-904ece9c_0 is DEAD
2025-11-05T13:43:14.107041Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.107086Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server disconnected, pipe [4:7569236449241747688:2434] destroyed
2025-11-05T13:43:14.107099Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.107104Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.107106Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.107182Z :WriteToTopic_Demo_14 INFO: Topic created
2025-11-05T13:43:14.109967Z node 4 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:14.110783Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:14.110829Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:14.112558Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][] pipe [4:7569236449241747730:2798] connected; active server actors: 1
2025-11-05T13:43:14.112628Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:14.112644Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:14.112644Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:14.112726Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:14.112739Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] BALANCER INIT DONE for topic_A: (0, 72075186224037894) 
2025-11-05T13:43:14.112752Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:14.112765Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72057594046644480, NodeId 4, Generation 2
2025-11-05T13:43:14.112786Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] doesn't have tx info
2025-11-05T13:43:14.112794Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:14.112796Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] no config, start with empty partitions and default config
2025-11-05T13:43:14.112800Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:14.112806Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:14.112816Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894] doesn't have tx writes info
2025-11-05T13:43:14.112827Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747763:2448], now have 1 active actors on pipe
2025-11-05T13:43:14.112829Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72075186224037894, NodeId 4, Generation 1
2025-11-05T13:43:14.112834Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747728:2797], now have 1 active actors on pipe
2025-11-05T13:43:14.112920Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236423471942825 RawX2: 17179871338 } 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:14.112947Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Propose TxId 281474976715672, WriteId (empty maybe)
2025-11-05T13:43:14.112956Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state UNKNOWN
2025-11-05T13:43:14.112958Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State UNKNOWN
2025-11-05T13:43:14.112961Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:14.112964Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from UNKNOWN to PREPARING
2025-11-05T13:43:14.112969Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:14.113000Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: PREPARED MinStep: 1762350194157 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: 7569236423471942825 RawX2: 17179871338 } Partitions { }
2025-11-05T13:43:14.113017Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.113173Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.113184Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARING
2025-11-05T13:43:14.113185Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PREPARING
2025-11-05T13:43:14.113187Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PREPARING to PREPARED
2025-11-05T13:43:14.113327Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037894 TxId: 281474976715672
2025-11-05T13:43:14.114495Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747776:2826], now have 1 active actors on pipe
2025-11-05T13:43:14.114514Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715672 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350194164 MediatorID: 72057594046382081 TabletID: 72075186224037894
2025-11-05T13:43:14.114518Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARED
2025-11-05T13:43:14.114523Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PREPARED
2025-11-05T13:43:14.114525Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PREPARED to PLANNING
2025-11-05T13:43:14.114527Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] PlanStep 1762350194164, PlanTxId 281474976715672
2025-11-05T13:43:14.114530Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:14.114576Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: PLANNED MinStep: 1762350194157 MaxStep: 18446744073709551615 Step: 1762350194164 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: 7569236423471942825 RawX2: 17179871338 } Partitions { }
2025-11-05T13:43:14.114593Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.114725Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.114733Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PLANNING
2025-11-05T13:43:14.114734Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PLANNING
2025-11-05T13:43:14.114735Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PLANNING to PLANNED
2025-11-05T13:43:14.114738Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxQueue.size 1
2025-11-05T13:43:14.114739Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] New ExecStep 1762350194164, ExecTxId 281474976715672
2025-11-05T13:43:14.114818Z node 4 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:14.114829Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PLANNED to CALCULATING
2025-11-05T13:43:14.114834Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:14.114868Z node 4 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:14.114922Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] bootstrapping 0 [4:7569236449241747782:2452]
2025-11-05T13:43:14.115119Z node 4 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Initializing completed.
2025-11-05T13:43:14.115126Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] init complete for topic 'topic_A' partition 0 generation 1 [4:7569236449241747782:2452]
2025-11-05T13:43:14.115130Z node 4 :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:14.115188Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:14.115195Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.115212Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115217Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:14.115218Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115219Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350194164, TxId 281474976715672, Partition 0
2025-11-05T13:43:14.115219Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115220Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:14.115221Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:14.115223Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] Partition responses 1/1
2025-11-05T13:43:14.115224Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATING
2025-11-05T13:43:14.115225Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State CALCULATING
2025-11-05T13:43:14.115226Z node 4 :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:14.115227Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State CALCULATING FrontTxId 281474976715672
2025-11-05T13:43:14.115229Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:43:14.115230Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from CALCULATING to CALCULATED
2025-11-05T13:43:14.115232Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:14.115272Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: CALCULATED MinStep: 1762350194157 MaxStep: 18446744073709551615 Step: 1762350194164 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: 7569236423471942825 RawX2: 17179871338 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:14.115286Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.115409Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.115415Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATED
2025-11-05T13:43:14.115416Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State CALCULATED
2025-11-05T13:43:14.115418Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State CALCULATED FrontTxId 281474976715672
2025-11-05T13:43:14.115419Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:14.115427Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:14.115429Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveParticipantsDecision 1
2025-11-05T13:43:14.115435Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:14.115438Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350194164, TxId 281474976715672
2025-11-05T13:43:14.115441Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115442Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 0, Expected 1
2025-11-05T13:43:14.115443Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115462Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115492Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:14.115923Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTxCommitDone Step 1762350194164, TxId 281474976715672, Partition 0
2025-11-05T13:43:14.115924Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:14.115929Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.115930Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.115931Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTING
2025-11-05T13:43:14.115932Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State EXECUTING
2025-11-05T13:43:14.115935Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State EXECUTING FrontTxId 281474976715672
2025-11-05T13:43:14.115937Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:43:14.115942Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId: 281474976715672 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:14.115948Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] complete TxId 281474976715672
2025-11-05T13:43:14.115996Z node 4 :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:14.116012Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:14.116019Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] delete partitions for TxId 281474976715672
2025-11-05T13:43:14.116025Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from EXECUTING to EXECUTED
2025-11-05T13:43:14.116028Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:14.116071Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: EXECUTED MinStep: 1762350194157 MaxStep: 18446744073709551615 Step: 1762350194164 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: 7569236423471942825 RawX2: 17179871338 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:14.116097Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.116278Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:14.116291Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:14.116298Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:14.116311Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:14.116319Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.116321Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTED
2025-11-05T13:43:14.116322Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State EXECUTED
2025-11-05T13:43:14.116324Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State EXECUTED FrontTxId 281474976715672
2025-11-05T13:43:14.116326Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:14.116332Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:14.116334Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] PredicateAcks: 0/0
2025-11-05T13:43:14.116336Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:14.116337Z node 4 :PQ_TX DEBUG: [TxId: 281474976715672] PredicateAcks: 0/0
2025-11-05T13:43:14.116339Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] add an TxId 281474976715672 to the list for deletion
2025-11-05T13:43:14.116341Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:14.116343Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] delete key for TxId 281474976715672
2025-11-05T13:43:14.116353Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.116443Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.116451Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state DELETING
2025-11-05T13:43:14.116452Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State DELETING
2025-11-05T13:43:14.116454Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] delete TxId 281474976715672
2025-11-05T13:43:14.116711Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:14.116945Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:14.116951Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:14608
2025-11-05T13:43:14.117910Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:43:14.117993Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:14.118003Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2025-11-05T13:43:14.118090Z node 4 :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:14.118109Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "topic_A" message_group_id: "src" from ipv6:[::1]:50584
2025-11-05T13:43:14.118118Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:50584 proto=v1  topic=topic_A durationSec=0
2025-11-05T13:43:14.118120Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:14.118423Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2025-11-05T13:43:14.118454Z node 4 :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:14.118461Z node 4 :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:14.118842Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350194118 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:14.118462Z node 4 :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:14.118474Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236449241747817:2460] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:14.118478Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:14.151002Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|2d848b60-ae89048b-58108899-2f9cf000_0" topic: "topic_A"
2025-11-05T13:43:14.118565Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.118571Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747820:2460], now have 1 active actors on pipe
2025-11-05T13:43:14.118576Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.118579Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.118601Z node 4 :PERSQUEUE INFO: new Cookie src|2d848b60-ae89048b-58108899-2f9cf000_0 generated for partition 0 topic 'topic_A' owner src
2025-11-05T13:43:14.118609Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.118613Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.118620Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.118629Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:14.118646Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.118668Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.118673Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.118693Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.118707Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: src|2d848b60-ae89048b-58108899-2f9cf000_0
2025-11-05T13:43:14.151219Z :INFO: [/Root] MessageGroupId [src] SessionId [src|2d848b60-ae89048b-58108899-2f9cf000_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:14.151225Z :INFO: [/Root] MessageGroupId [src] SessionId [src|2d848b60-ae89048b-58108899-2f9cf000_0] Write session will now close
2025-11-05T13:43:14.151231Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|2d848b60-ae89048b-58108899-2f9cf000_0] Write session: aborting
2025-11-05T13:43:14.151400Z :INFO: [/Root] MessageGroupId [src] SessionId [src|2d848b60-ae89048b-58108899-2f9cf000_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:14.151406Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|2d848b60-ae89048b-58108899-2f9cf000_0] Write session: destroy
2025-11-05T13:43:14.151583Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: src|2d848b60-ae89048b-58108899-2f9cf000_0 grpc read done: success: 0 data: 
2025-11-05T13:43:14.151595Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|2d848b60-ae89048b-58108899-2f9cf000_0 grpc read failed
2025-11-05T13:43:14.151605Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|2d848b60-ae89048b-58108899-2f9cf000_0 grpc closed
2025-11-05T13:43:14.151608Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|2d848b60-ae89048b-58108899-2f9cf000_0 is DEAD
2025-11-05T13:43:14.151871Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.151937Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747820:2460] destroyed
2025-11-05T13:43:14.151958Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.151976Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.151984Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.154133Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: try to update token
2025-11-05T13:43:14.154299Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Start write session. Will connect to nodeId: 0
2025-11-05T13:43:14.154493Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: write to message_group: test-message_group_id
2025-11-05T13:43:14.154523Z :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:14.154527Z :TRACE: [/Root] TRACE_EVENT InitRequest 
2025-11-05T13:43:14.154622Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:14.154628Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:14.154638Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2025-11-05T13:43:14.154756Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 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:14.154786Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 3 path: "topic_A" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" from ipv6:[::1]:50584
2025-11-05T13:43:14.154794Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="topic server" ip=ipv6:[::1]:50584 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:14.154797Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:14.155050Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2025-11-05T13:43:14.155086Z node 4 :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:14.155090Z node 4 :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:14.155092Z node 4 :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:14.155101Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236449241747832:2467] (SourceId=test-message_group_id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:14.155105Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:14.155227Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747835:2467], now have 1 active actors on pipe
2025-11-05T13:43:14.155236Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.155237Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.155241Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.155260Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:14.155268Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.155273Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.155282Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.155293Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:14.155321Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.155354Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.155362Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.155383Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.155396Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0
2025-11-05T13:43:14.155536Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:14.155548Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350194155 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:14.155559Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session established. Init response: session_id: "test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0"
2025-11-05T13:43:14.155562Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0
2025-11-05T13:43:14.155565Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  MessageGroupId [test-message_group_id] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:14.155613Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:43:14.155621Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_A partition_id=0
2025-11-05T13:43:14.155643Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:43:14.155945Z node 4 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:43:14.155966Z node 4 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_A"
include_location: true
2025-11-05T13:43:14.155972Z node 4 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[4:7569236449241747838:2469]: Bootstrap
2025-11-05T13:43:14.156219Z node 4 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [4:7569236449241747838:2469]: Request location
2025-11-05T13:43:14.156268Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236449241747847:2470] connected; active server actors: 1
2025-11-05T13:43:14.156281Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] addPartitionToResponse tabletId 72075186224037894, partitionId 0, NodeId 4, Generation 1
2025-11-05T13:43:14.156289Z node 4 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [4:7569236449241747838:2469]: Got location
2025-11-05T13:43:14.156316Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236449241747847:2470] disconnected; active server actors: 1
2025-11-05T13:43:14.156323Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236449241747847:2470] disconnected no session
2025-11-05T13:43:14.156482Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 4
    generation: 1
  }
}
2025-11-05T13:43:14.156488Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=4 pl_generation=1
2025-11-05T13:43:14.156491Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 4 exists in the endpoint pool.
2025-11-05T13:43:14.156494Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=4 Generation=1
2025-11-05T13:43:14.156496Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 4
2025-11-05T13:43:14.156654Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 1, Msg: CANCELLED, Details: , InternalError: 0
2025-11-05T13:43:14.156675Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0 grpc read done: success: 0 data: 
2025-11-05T13:43:14.156683Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0 grpc read failed
2025-11-05T13:43:14.156687Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0 grpc closed
2025-11-05T13:43:14.156690Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0 is DEAD
2025-11-05T13:43:14.156785Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:43:14.156778Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.156808Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_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:14.156813Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:43:14.156818Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747835:2467] destroyed
2025-11-05T13:43:14.156831Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.156837Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.156839Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.156891Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:14.156894Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:14.156900Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2025-11-05T13:43:14.156960Z node 4 :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" partition_with_generation { generation: 1 } }
2025-11-05T13:43:14.156977Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 4 path: "topic_A" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } from ipv6:[::1]:50584
2025-11-05T13:43:14.156983Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="topic server" ip=ipv6:[::1]:50584 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:14.156985Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:14.156992Z node 4 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:43:14.157144Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2025-11-05T13:43:14.157174Z node 4 :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:14.157177Z node 4 :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:14.157179Z node 4 :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:14.157182Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236449241747852:2472] (SourceId=test-message_group_id, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:14.157184Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:43:14.157268Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.157278Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747855:2472], now have 1 active actors on pipe
2025-11-05T13:43:14.157283Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.157286Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.157300Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:14.157309Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.157312Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.157318Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.157328Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:14.157344Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.157367Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.157372Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.157383Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.157397Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0
2025-11-05T13:43:14.157580Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:14.157596Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|568f922d-e7fd44b4-15cf028-80769d0d_0]  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0"
2025-11-05T13:43:14.157602Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0
2025-11-05T13:43:14.157606Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:14.157659Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=1, txId=01k9a43qf9dv7g3sb05a7fmh2e, WriteCount=1, AckCount=0
2025-11-05T13:43:14.157669Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:43:14.157686Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:14.157690Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:43:14.157811Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:14.157903Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP for a WriteId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e
2025-11-05T13:43:14.157968Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.157979Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747858:2472], now have 1 active actors on pipe
2025-11-05T13:43:14.158179Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of the request to KQP for the WriteId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e Status: SUCCESS
2025-11-05T13:43:14.158187Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e WriteId: {4, 281474976715673}
2025-11-05T13:43:14.158210Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.158217Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.158222Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] partition {0, {4, 281474976715673}, 100000} for WriteId {4, 281474976715673}
2025-11-05T13:43:14.158254Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvSubscribeLock for WriteId {4, 281474976715673}
2025-11-05T13:43:14.158277Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.158297Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715673 LockNode: 4 Status: STATUS_SUBSCRIBED
2025-11-05T13:43:14.158304Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {4, 281474976715673}, TxId (empty maybe), Status STATUS_UNSPECIFIED
2025-11-05T13:43:14.158307Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] subscribed WriteId {4, 281474976715673}
2025-11-05T13:43:14.158521Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.158652Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:14.158713Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:14.158761Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateInit] bootstrapping {0, {4, 281474976715673}, 100000} [4:7569236449241747864:2474]
2025-11-05T13:43:14.158901Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:43:14.159030Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:43:14.159059Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:43:14.159088Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:43:14.159104Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:43:14.159109Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:43:14.159111Z node 4 :PERSQUEUE INFO: [topic_A:{0, {4, 281474976715673}, 100000}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:43:14.159113Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100000}:Initializer] Initializing completed.
2025-11-05T13:43:14.159116Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateInit] init complete for topic 'topic_A' partition {0, {4, 281474976715673}, 100000} generation 1 [4:7569236449241747864:2474]
2025-11-05T13:43:14.159120Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateInit] SYNC INIT topic topic_A partitition {0, {4, 281474976715673}, 100000} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:14.159124Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:43:14.159127Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.159129Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.159154Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|ea033f87-79ede3f5-2398cee8-c1fad034_0 generated for partition {0, {4, 281474976715673}, 100000} topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:14.159161Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.159163Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.159166Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.159170Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {4, 281474976715673}, 100000}
2025-11-05T13:43:14.159179Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.159189Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e
2025-11-05T13:43:14.159260Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e Status: SUCCESS
2025-11-05T13:43:14.159293Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.159303Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.159324Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.159357Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.159362Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.159380Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976715673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:14.159397Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:43:14.159410Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:14.159443Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.159448Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.159455Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976715673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:14.159463Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 0 messageNo: 1 size 81 offset: -1
2025-11-05T13:43:14.159488Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.159497Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.159514Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976715673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 0
2025-11-05T13:43:14.159566Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976715673}, 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:14.159584Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.159627Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {4, 281474976715673}, 100000} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100000_00000000000000000000_00000_0000000001_00000| size 158 WTime 1762350194159
2025-11-05T13:43:14.159657Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:14.159669Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 0 partNo 0 count 1 size 158
2025-11-05T13:43:14.159819Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 0 count 1 size 158 actorID [4:7569236449241747758:2451]
2025-11-05T13:43:14.159844Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 0 size 158
2025-11-05T13:43:14.159943Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 103 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:14.159956Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976715673}, 100000}
2025-11-05T13:43:14.159970Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976715673}, 100000}, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:43:14.159971Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-11-05T13:43:14.159976Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:14.159985Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.159987Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.160111Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:14.160134Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 1 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:14.160139Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=01k9a43qf9dv7g3sb05a7fmh2e, WriteCount=1, AckCount=1
2025-11-05T13:43:14.160141Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:43:14.160309Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747876:2860], now have 1 active actors on pipe
2025-11-05T13:43:14.160400Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747879:2862], now have 1 active actors on pipe
2025-11-05T13:43:14.160419Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715673 LockNode: 4 Status: STATUS_NOT_FOUND
2025-11-05T13:43:14.160422Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {4, 281474976715673}, TxId (empty maybe), Status STATUS_SUBSCRIBED
2025-11-05T13:43:14.160425Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] delete partitions for WriteId {4, 281474976715673} (longTxService lost tx)
2025-11-05T13:43:14.160428Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvPQ::TEvDeletePartition to partition {0, {4, 281474976715673}, 100000}
2025-11-05T13:43:14.160436Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747880:2863], now have 1 active actors on pipe
2025-11-05T13:43:14.160450Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Handle TEvPQ::TEvDeletePartition
2025-11-05T13:43:14.160462Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:14.160466Z node 4 :PERSQUEUE DEBUG: CacheProxy. Delete blobs from D0000100000(+) to D0000100001(-)
2025-11-05T13:43:14.160638Z node 4 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100000 offset 0 count 1 actorID [4:7569236449241747758:2451]
2025-11-05T13:43:14.160662Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 0
2025-11-05T13:43:14.160670Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.160672Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.160685Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvDeletePartitionDone {0, {4, 281474976715673}, 100000}
2025-11-05T13:43:14.160694Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] DeletePartition {0, {4, 281474976715673}, 100000}
2025-11-05T13:43:14.160699Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvUnsubscribeLock for WriteId {4, 281474976715673}
2025-11-05T13:43:14.160709Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.160803Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.202470Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.202487Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.215266Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.215288Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.260707Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747889:2869], now have 1 active actors on pipe
2025-11-05T13:43:14.260911Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 18446744073709.551615s
2025-11-05T13:43:14.260926Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:43:14.260935Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:43:14.261133Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:14.261141Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:43:14.261338Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: try to update token
2025-11-05T13:43:14.261329Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0 grpc read done: success: 0 data: 
2025-11-05T13:43:14.261334Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0 grpc read failed
2025-11-05T13:43:14.261343Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0 grpc closed
2025-11-05T13:43:14.261346Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id|dc840e68-868af2a3-293174f1-7354e7da_0 is DEAD
2025-11-05T13:43:14.261538Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Start write session. Will connect to nodeId: 0
2025-11-05T13:43:14.261665Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.261679Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.261713Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747855:2472] destroyed
2025-11-05T13:43:14.261720Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747858:2472] destroyed
2025-11-05T13:43:14.261736Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.261748Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.261751Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.261796Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: write to message_group: test-message_group_id
2025-11-05T13:43:14.261824Z :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:14.261828Z :TRACE: [/Root] TRACE_EVENT InitRequest 
2025-11-05T13:43:14.261915Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:14.262085Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:14.262099Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 5
2025-11-05T13:43:14.262187Z node 4 :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" message_group_id: "test-message_group_id" }
2025-11-05T13:43:14.262204Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 5 path: "topic_A" producer_id: "test-message_group_id" message_group_id: "test-message_group_id" from ipv6:[::1]:50584
2025-11-05T13:43:14.262209Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=5 sessionId= userAgent="topic server" ip=ipv6:[::1]:50584 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:14.262211Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:14.262390Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId:  describe result for acl check
2025-11-05T13:43:14.262420Z node 4 :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:14.262423Z node 4 :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:14.262424Z node 4 :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:14.262432Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236449241747895:2477] (SourceId=test-message_group_id, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:14.262435Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 5 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:14.262504Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.262509Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747898:2477], now have 1 active actors on pipe
2025-11-05T13:43:14.262514Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.262519Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.262533Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:14.262537Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.262540Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.262547Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.262556Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:14.262573Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.262604Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.262611Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.262622Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.262641Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 5 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0
2025-11-05T13:43:14.262803Z :DEBUG: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:14.262814Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350194262 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:14.262837Z :INFO: [/Root]  TraceId []  SessionId []  MessageGroupId [test-message_group_id] Write session established. Init response: session_id: "test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0"
2025-11-05T13:43:14.262842Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0
2025-11-05T13:43:14.262845Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  MessageGroupId [test-message_group_id] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:14.262894Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:43:14.262900Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_A partition_id=0
2025-11-05T13:43:14.262930Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:43:14.263254Z node 4 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:43:14.263269Z node 4 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_A"
include_location: true
2025-11-05T13:43:14.263276Z node 4 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[4:7569236449241747901:2479]: Bootstrap
2025-11-05T13:43:14.263375Z node 4 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [4:7569236449241747901:2479]: Request location
2025-11-05T13:43:14.263404Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236449241747903:2480] connected; active server actors: 1
2025-11-05T13:43:14.263415Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] addPartitionToResponse tabletId 72075186224037894, partitionId 0, NodeId 4, Generation 1
2025-11-05T13:43:14.263426Z node 4 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [4:7569236449241747901:2479]: Got location
2025-11-05T13:43:14.263447Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236449241747903:2480] disconnected; active server actors: 1
2025-11-05T13:43:14.263451Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236449241747903:2480] disconnected no session
2025-11-05T13:43:14.263644Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 4
    generation: 1
  }
}
2025-11-05T13:43:14.263651Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=4 pl_generation=1
2025-11-05T13:43:14.263656Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 4 exists in the endpoint pool.
2025-11-05T13:43:14.263661Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=4 Generation=1
2025-11-05T13:43:14.263664Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 4
2025-11-05T13:43:14.263817Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 1, Msg: CANCELLED, Details: , InternalError: 0
2025-11-05T13:43:14.263840Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0 grpc read done: success: 0 data: 
2025-11-05T13:43:14.263846Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0 grpc read failed
2025-11-05T13:43:14.263849Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0 grpc closed
2025-11-05T13:43:14.263851Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0 is DEAD
2025-11-05T13:43:14.263895Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:43:14.263913Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_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:14.263916Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:43:14.263982Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:14.263972Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.264000Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747898:2477] destroyed
2025-11-05T13:43:14.264012Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.264020Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.264022Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.264047Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:14.264052Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 6
2025-11-05T13:43:14.264156Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 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:14.264193Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 6 path: "topic_A" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } from ipv6:[::1]:50584
2025-11-05T13:43:14.264200Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=6 sessionId= userAgent="topic server" ip=ipv6:[::1]:50584 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:14.264203Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:14.264214Z node 4 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:43:14.264384Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId:  describe result for acl check
2025-11-05T13:43:14.264412Z node 4 :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:14.264414Z node 4 :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:14.264414Z node 4 :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:14.264417Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236449241747908:2482] (SourceId=test-message_group_id, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:14.264419Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 6 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:43:14.264504Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747911:2482], now have 1 active actors on pipe
2025-11-05T13:43:14.264506Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.264511Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.264515Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.264532Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:14.264545Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.264553Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.264561Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.264574Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:14.264601Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.264631Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.264641Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.264658Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.264672Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 6 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0
2025-11-05T13:43:14.264883Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:14.264900Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|70b96d81-ede434a6-acc1a701-ec11d538_0]  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0"
2025-11-05T13:43:14.264905Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0
2025-11-05T13:43:14.264908Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: set DirectWriteToPartitionId 0
2025-11-05T13:43:14.264973Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=1, txId=01k9a43qf9dv7g3sb05a7fmh2e, WriteCount=1, AckCount=0
2025-11-05T13:43:14.264986Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:43:14.265003Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:14.265007Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:43:14.265196Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId: test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:14.265273Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP for a WriteId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e
2025-11-05T13:43:14.265340Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:43:14.265351Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747914:2482], now have 1 active actors on pipe
2025-11-05T13:43:14.265438Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of the request to KQP for the WriteId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e Status: SUCCESS
2025-11-05T13:43:14.265448Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e WriteId: {4, 281474976715673}
2025-11-05T13:43:14.265479Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.265486Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.265492Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] partition {0, {4, 281474976715673}, 100001} for WriteId {4, 281474976715673}
2025-11-05T13:43:14.265530Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:14.265775Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:14.265862Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:14.265924Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:14.265985Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateInit] bootstrapping {0, {4, 281474976715673}, 100001} [4:7569236449241747919:2484]
2025-11-05T13:43:14.266152Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:43:14.266279Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:43:14.266305Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:43:14.266335Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:43:14.266362Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:43:14.266369Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:43:14.266372Z node 4 :PERSQUEUE INFO: [topic_A:{0, {4, 281474976715673}, 100001}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:43:14.266381Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976715673}, 100001}:Initializer] Initializing completed.
2025-11-05T13:43:14.266390Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateInit] init complete for topic 'topic_A' partition {0, {4, 281474976715673}, 100001} generation 1 [4:7569236449241747919:2484]
2025-11-05T13:43:14.266401Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateInit] SYNC INIT topic topic_A partitition {0, {4, 281474976715673}, 100001} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:14.266409Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:43:14.266415Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.266417Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.266453Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|860d73b8-9934cd65-b142cf20-7fc1daf5_0 generated for partition {0, {4, 281474976715673}, 100001} topic 'topic_A' owner test-message_group_id
2025-11-05T13:43:14.266462Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.266465Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.266471Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.266476Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {4, 281474976715673}, 100001}
2025-11-05T13:43:14.266488Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.266500Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e
2025-11-05T13:43:14.266577Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg= TxId: 01k9a43qf9dv7g3sb05a7fmh2e Status: SUCCESS
2025-11-05T13:43:14.266607Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.266615Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.266632Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:14.266683Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.266687Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.266702Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976715673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:14.266722Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:43:14.266735Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:14.266798Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:14.266803Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:14.266809Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976715673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:14.266815Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 0 messageNo: 1 size 81 offset: -1
2025-11-05T13:43:14.266830Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.266837Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.266847Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976715673}, 100001} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 0
2025-11-05T13:43:14.266868Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976715673}, 100001} 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:14.266878Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.266913Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {4, 281474976715673}, 100001} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100001_00000000000000000000_00000_0000000001_00000| size 158 WTime 1762350194266
2025-11-05T13:43:14.266938Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:14.266948Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100001 offset 0 partNo 0 count 1 size 158
2025-11-05T13:43:14.267137Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100001 offset 0 count 1 size 158 actorID [4:7569236449241747758:2451]
2025-11-05T13:43:14.267173Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100001 offset 0 partno 0 count 1 parts 0 size 158
2025-11-05T13:43:14.267448Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 103 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:14.267460Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976715673}, 100001}
2025-11-05T13:43:14.267471Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976715673}, 100001}, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:43:14.267481Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-11-05T13:43:14.267488Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.267489Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.267498Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:14.267654Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:14.267684Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_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:14.267692Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=01k9a43qf9dv7g3sb05a7fmh2e, WriteCount=1, AckCount=1
2025-11-05T13:43:14.267869Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:43:14.268353Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236449241747935:2882], now have 1 active actors on pipe
2025-11-05T13:43:14.268390Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236449241747932 RawX2: 4503616807242144 } TxId: 281474976715674 Data { Operations { PartitionId: 0 Path: "/Root/topic_A" SupportivePartition: 4294967295 } Op: Commit SendingShards: 72075186224037894 ReceivingShards: 72075186224037894 Immediate: true WriteId { NodeId: 4 KeyId: 281474976715673 } }
2025-11-05T13:43:14.268401Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] PartitionId {0, {4, 281474976715673}, 4294967295} for WriteId {4, 281474976715673}
2025-11-05T13:43:14.268405Z node 4 :PQ_TX WARN: [PQ: 72075186224037894] TxId 281474976715674 invalid WriteId { NodeId: 4 KeyId: 281474976715673 }
2025-11-05T13:43:14.268409Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId: 281474976715674 send TEvPersQueue::TEvProposeTransactionResult(ABORTED)
2025-11-05T13:43:14.268459Z node 4 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=4&id=ZjM0MjcxYzUtMjVjMTMwZjAtZGIwZTI5ZGYtM2U0NTY0Mzg=, ActorId: [4:7569236449241747825:2464], ActorState: ExecuteState, TraceId: 01k9a43qjw8649ym681mxdtknn, Create QueryResponse for error on request, msg: 
2025-11-05T13:43:14.269237Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 0.000000s
2025-11-05T13:43:14.269241Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:43:14.269245Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:43:14.269350Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:14.269355Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:43:14.269595Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId: test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0 grpc read done: success: 0 data: 
2025-11-05T13:43:14.269605Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0 grpc read failed
2025-11-05T13:43:14.269610Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0 grpc closed
2025-11-05T13:43:14.269612Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: test-message_group_id|2119299f-f9c2f5dc-37381c80-4e0815db_0 is DEAD
2025-11-05T13:43:14.269787Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.269799Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:14.269836Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747911:2482] destroyed
2025-11-05T13:43:14.269845Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236449241747914:2482] destroyed
2025-11-05T13:43:14.269848Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.269852Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:14.269855Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.269857Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:14.269859Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976715673}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:14.269863Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
