test_client.cpp: SetPath # /home/runner/.ya/build/build_root/4xc1/003f89/r3tmp/tmpH4vpQ2/pdisk_1.dat
2025-11-05T13:42:45.380700Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: : Created
2025-11-05T13:42:45.407780Z node 4 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:69;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=incorrect path status: LookupError;
2025-11-05T13:42:45.408424Z node 4 :IMPORT WARN: Table profiles were not loaded
TServer::EnableGrpc on GrpcPort 2632, node 4
2025-11-05T13:42:45.434336Z node 4 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/4xc1/003f89/r3tmp/yandexTqIjgW.tmp
2025-11-05T13:42:45.434347Z node 4 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/4xc1/003f89/r3tmp/yandexTqIjgW.tmp
2025-11-05T13:42:45.434445Z node 4 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/4xc1/003f89/r3tmp/yandexTqIjgW.tmp
2025-11-05T13:42:45.434496Z node 4 :NET_CLASSIFIER ERROR: got bad distributable configuration
2025-11-05T13:42:45.438990Z INFO: TTestServer started on Port 5669 GrpcPort 2632
TClient is connected to server localhost:5669
PQClient connected to localhost:2632
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:42:45.473981Z node 4 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976710657:0, at schemeshard:  72057594046644480
2025-11-05T13:42:45.474521Z node 4 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-11-05T13:42:45.474538Z node 4 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Disconnected -> Connecting
waiting...
2025-11-05T13:42:45.476020Z node 4 :FLAT_TX_SCHEMESHARD WARN: NotifyTxCompletion, unknown transaction, txId: 281474976710657, at schemeshard: 72057594046644480
2025-11-05T13:42:45.478400Z node 4 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Connecting -> Connected
waiting...
2025-11-05T13:42:45.493350Z node 4 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710659:0, at schemeshard:  72057594046644480
waiting...
waiting...
waiting...
2025-11-05T13:42:45.762146Z node 4 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710662:0, at schemeshard:  72057594046644480
2025-11-05T13:42:45.764873Z node 4 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [4:7569236324080173944: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:42:45.765418Z node 4 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=4&id=N2Q1MDVjYWMtOWNiZTM0MzktMTg2ZGU1MzMtNDAwYjM2ZDY=, ActorId: [4:7569236324080173941:2314], ActorState: ExecuteState, TraceId: 01k9a42vqwdahqzm02w8jxpgva, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-11-05T13:42:45.765593Z 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:42:45.781483Z node 4 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710663:0, at schemeshard:  72057594046644480
2025-11-05T13:42:45.798870Z node 4 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710664: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:7569236324080174218:2565] 
2025-11-05T13:42:46.355683Z node 4 :TX_CONVEYOR ERROR: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
=== CheckClustersList. Ok
2025-11-05T13:42:50.933745Z :WriteToTopic_Demo_36 INFO: TTopicSdkTestSetup started
2025-11-05T13:42:50.936267Z node 4 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:42:50.939375Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:42:50.939398Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037893][] pipe [4:7569236345555011018:2746] connected; active server actors: 1
2025-11-05T13:42:50.939496Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:42:50.939513Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:42:50.939560Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:42:50.939601Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:42:50.939622Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] doesn't have tx info
2025-11-05T13:42:50.939624Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] BALANCER INIT DONE for test-topic: (0, 72075186224037892) 
2025-11-05T13:42:50.939632Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:42:50.939635Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-11-05T13:42:50.939639Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:42:50.939645Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:42:50.939659Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037892] doesn't have tx writes info
2025-11-05T13:42:50.939694Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236345555011015:2744], now have 1 active actors on pipe
2025-11-05T13:42:50.939702Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236345555011046:2422], now have 1 active actors on pipe
2025-11-05T13:42:50.939703Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72075186224037892, NodeId 4, Generation 1
2025-11-05T13:42:50.939706Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72057594046644480, NodeId 4, Generation 2
2025-11-05T13:42:50.939827Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236324080173519 RawX2: 17179871332 } TxId: 281474976710671 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:42:50.939862Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] Propose TxId 281474976710671, WriteId (empty maybe)
2025-11-05T13:42:50.939871Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state UNKNOWN
2025-11-05T13:42:50.939873Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State UNKNOWN
2025-11-05T13:42:50.939876Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:42:50.939879Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from UNKNOWN to PREPARING
2025-11-05T13:42:50.939885Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710671
2025-11-05T13:42:50.939937Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] save tx TxId: 281474976710671 State: PREPARED MinStep: 1762350170980 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: 7569236324080173519 RawX2: 17179871332 } Partitions { }
2025-11-05T13:42:50.939960Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.940084Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.940094Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARING
2025-11-05T13:42:50.940095Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State PREPARING
2025-11-05T13:42:50.940097Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from PREPARING to PREPARED
2025-11-05T13:42:50.940233Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037892 TxId: 281474976710671
2025-11-05T13:42:50.940445Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236345555011057:2769], now have 1 active actors on pipe
2025-11-05T13:42:50.940466Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976710671 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350170987 MediatorID: 72057594046382081 TabletID: 72075186224037892
2025-11-05T13:42:50.940477Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARED
2025-11-05T13:42:50.940478Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State PREPARED
2025-11-05T13:42:50.940481Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from PREPARED to PLANNING
2025-11-05T13:42:50.940485Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] PlanStep 1762350170987, PlanTxId 281474976710671
2025-11-05T13:42:50.940490Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710671
2025-11-05T13:42:50.940543Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] save tx TxId: 281474976710671 State: PLANNED MinStep: 1762350170980 MaxStep: 18446744073709551615 Step: 1762350170987 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: 7569236324080173519 RawX2: 17179871332 } Partitions { }
2025-11-05T13:42:50.940570Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.940659Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.940671Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PLANNING
2025-11-05T13:42:50.940673Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State PLANNING
2025-11-05T13:42:50.940676Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from PLANNING to PLANNED
2025-11-05T13:42:50.940679Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxQueue.size 1
2025-11-05T13:42:50.940682Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] New ExecStep 1762350170987, ExecTxId 281474976710671
2025-11-05T13:42:50.940784Z node 4 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:42:50.940789Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from PLANNED to CALCULATING
2025-11-05T13:42:50.940803Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:42:50.940920Z node 4 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:42:50.940976Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] bootstrapping 0 [4:7569236345555011064:2426]
2025-11-05T13:42:50.941195Z node 4 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Initializing completed.
2025-11-05T13:42:50.941205Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] init complete for topic 'test-topic' partition 0 generation 1 [4:7569236345555011064:2426]
2025-11-05T13:42:50.941211Z 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:42:50.941278Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:42:50.941289Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.941314Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.941322Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:42:50.941324Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.941327Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.941327Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350170987, TxId 281474976710671, Partition 0
2025-11-05T13:42:50.941329Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:42:50.941331Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] Handle TEvProposePartitionConfigResult
2025-11-05T13:42:50.941334Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] Partition responses 1/1
2025-11-05T13:42:50.941337Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-11-05T13:42:50.941338Z 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:42:50.941340Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State CALCULATING
2025-11-05T13:42:50.941345Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671 State CALCULATING FrontTxId 281474976710671
2025-11-05T13:42:50.941348Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:42:50.941352Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from CALCULATING to CALCULATED
2025-11-05T13:42:50.941362Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710671
2025-11-05T13:42:50.941530Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] save tx TxId: 281474976710671 State: CALCULATED MinStep: 1762350170980 MaxStep: 18446744073709551615 Step: 1762350170987 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: 7569236324080173519 RawX2: 17179871332 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:42:50.941561Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.941833Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.941845Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATED
2025-11-05T13:42:50.941847Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State CALCULATED
2025-11-05T13:42:50.941850Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671 State CALCULATED FrontTxId 281474976710671
2025-11-05T13:42:50.941853Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from CALCULATED to WAIT_RS
2025-11-05T13:42:50.941863Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:42:50.941866Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveParticipantsDecision 1
2025-11-05T13:42:50.941874Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from WAIT_RS to EXECUTING
2025-11-05T13:42:50.941877Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 0, Expected 1
2025-11-05T13:42:50.941886Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350170987, TxId 281474976710671
2025-11-05T13:42:50.941895Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.941902Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.941934Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.941975Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:50.942488Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:42:50.942498Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.942499Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.942499Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1762350170987, TxId 281474976710671, Partition 0
2025-11-05T13:42:50.942503Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-11-05T13:42:50.942505Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State EXECUTING
2025-11-05T13:42:50.942507Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671 State EXECUTING FrontTxId 281474976710671
2025-11-05T13:42:50.942510Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:42:50.942514Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId: 281474976710671 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:42:50.942524Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] complete TxId 281474976710671
2025-11-05T13:42:50.942575Z 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:42:50.942598Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:42:50.942611Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] delete partitions for TxId 281474976710671
2025-11-05T13:42:50.942617Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from EXECUTING to EXECUTED
2025-11-05T13:42:50.942620Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710671
2025-11-05T13:42:50.942672Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] save tx TxId: 281474976710671 State: EXECUTED MinStep: 1762350170980 MaxStep: 18446744073709551615 Step: 1762350170987 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: 7569236324080173519 RawX2: 17179871332 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:42:50.942701Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.943002Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.943013Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTED
2025-11-05T13:42:50.943015Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State EXECUTED
2025-11-05T13:42:50.943018Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671 State EXECUTED FrontTxId 281474976710671
2025-11-05T13:42:50.943021Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:42:50.943023Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:42:50.943026Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] PredicateAcks: 0/0
2025-11-05T13:42:50.943028Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:42:50.943030Z node 4 :PQ_TX DEBUG: [TxId: 281474976710671] PredicateAcks: 0/0
2025-11-05T13:42:50.943032Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] add an TxId 281474976710671 to the list for deletion
2025-11-05T13:42:50.943034Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976710671 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:42:50.943037Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] delete key for TxId 281474976710671
2025-11-05T13:42:50.943043Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:42:50.943044Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.943074Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:42:50.943180Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.943189Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state DELETING
2025-11-05T13:42:50.943190Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976710671, State DELETING
2025-11-05T13:42:50.943193Z node 4 :PQ_TX INFO: [PQ: 72075186224037892] delete TxId 281474976710671
2025-11-05T13:42:50.943533Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:42:50.943730Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:42:50.943734Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:2632
2025-11-05T13:42:50.944668Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "test-topic" message_group_id: "src" }
2025-11-05T13:42:50.944739Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:42:50.944755Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2025-11-05T13:42:50.944856Z 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:42:50.944889Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "test-topic" message_group_id: "src" from ipv6:[::1]:49708
2025-11-05T13:42:50.944898Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:49708 proto=v1  topic=test-topic durationSec=0
2025-11-05T13:42:50.944901Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:42:50.945439Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  describe result for acl check
2025-11-05T13:42:50.945472Z 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:42:50.945478Z 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:42:50.945479Z 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:42:50.945492Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236345555011108:2434] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:42:50.945501Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 1 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:42:50.945609Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 4, Generation: 1
2025-11-05T13:42:50.945619Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [4:7569236345555011111:2434], now have 1 active actors on pipe
2025-11-05T13:42:50.945629Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:42:50.945637Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:42:50.945668Z node 4 :PERSQUEUE INFO: new Cookie src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0 generated for partition 0 topic 'test-topic' owner src
2025-11-05T13:42:50.945681Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.945689Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.945698Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.945713Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:42:50.945736Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.945789Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:42:50.945795Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:42:50.945813Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.945842Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 1 partition: 0 MaxSeqNo: 0 sessionId: src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0
2025-11-05T13:42:50.946021Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350170946 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:42:50.946039Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0" topic: "test-topic"
2025-11-05T13:42:50.946110Z :INFO: [/Root] MessageGroupId [src] SessionId [src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0] Write session: close. Timeout = 0 ms
2025-11-05T13:42:50.946115Z :INFO: [/Root] MessageGroupId [src] SessionId [src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0] Write session will now close
2025-11-05T13:42:50.946121Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0] Write session: aborting
2025-11-05T13:42:50.946209Z :INFO: [/Root] MessageGroupId [src] SessionId [src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:42:50.946213Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0] Write session: destroy
2025-11-05T13:42:50.946425Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0 grpc read done: success: 0 data: 
2025-11-05T13:42:50.946434Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0 grpc read failed
2025-11-05T13:42:50.946442Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0 grpc closed
2025-11-05T13:42:50.946444Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|3c08f7a3-c23a611c-9ea3b592-49c4b25_0 is DEAD
2025-11-05T13:42:50.946546Z :WriteToTopic_Demo_36 INFO: Topic created
2025-11-05T13:42:50.946638Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:42:50.946675Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server disconnected, pipe [4:7569236345555011111:2434] destroyed
2025-11-05T13:42:50.946686Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:42:50.946694Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.946695Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.948986Z node 4 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:42:50.949956Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:42:50.950022Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:42:50.952302Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:42:50.952309Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][] pipe [4:7569236345555011155:2812] connected; active server actors: 1
2025-11-05T13:42:50.952415Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:42:50.952456Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:42:50.952458Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:42:50.952480Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] doesn't have tx info
2025-11-05T13:42:50.952483Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:42:50.952485Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] no config, start with empty partitions and default config
2025-11-05T13:42:50.952487Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:42:50.952492Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:42:50.952502Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894] doesn't have tx writes info
2025-11-05T13:42:50.952560Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236345555011154:2811], now have 1 active actors on pipe
2025-11-05T13:42:50.952590Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:42:50.952612Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] BALANCER INIT DONE for topic_A: (0, 72075186224037894) 
2025-11-05T13:42:50.952652Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72075186224037894, NodeId 4, Generation 1
2025-11-05T13:42:50.952658Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72057594046644480, NodeId 4, Generation 2
2025-11-05T13:42:50.952662Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236324080173519 RawX2: 17179871332 } TxId: 281474976710672 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:42:50.952690Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Propose TxId 281474976710672, WriteId (empty maybe)
2025-11-05T13:42:50.952702Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state UNKNOWN
2025-11-05T13:42:50.952704Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State UNKNOWN
2025-11-05T13:42:50.952708Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:42:50.952714Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from UNKNOWN to PREPARING
2025-11-05T13:42:50.952720Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976710672
2025-11-05T13:42:50.952780Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] save tx TxId: 281474976710672 State: PREPARED MinStep: 1762350171000 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: 7569236324080173519 RawX2: 17179871332 } Partitions { }
2025-11-05T13:42:50.952810Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.952826Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236345555011187:2448], now have 1 active actors on pipe
2025-11-05T13:42:50.953060Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.953077Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARING
2025-11-05T13:42:50.953079Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State PREPARING
2025-11-05T13:42:50.953082Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from PREPARING to PREPARED
2025-11-05T13:42:50.953295Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037894 TxId: 281474976710672
2025-11-05T13:42:50.953480Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236345555011199:2838], now have 1 active actors on pipe
2025-11-05T13:42:50.953518Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976710672 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350171001 MediatorID: 72057594046382081 TabletID: 72075186224037894
2025-11-05T13:42:50.953525Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARED
2025-11-05T13:42:50.953526Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State PREPARED
2025-11-05T13:42:50.953529Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from PREPARED to PLANNING
2025-11-05T13:42:50.953534Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] PlanStep 1762350171001, PlanTxId 281474976710672
2025-11-05T13:42:50.953539Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976710672
2025-11-05T13:42:50.953611Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] save tx TxId: 281474976710672 State: PLANNED MinStep: 1762350171000 MaxStep: 18446744073709551615 Step: 1762350171001 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: 7569236324080173519 RawX2: 17179871332 } Partitions { }
2025-11-05T13:42:50.953634Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.953819Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.953838Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PLANNING
2025-11-05T13:42:50.953840Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State PLANNING
2025-11-05T13:42:50.953842Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from PLANNING to PLANNED
2025-11-05T13:42:50.953845Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxQueue.size 1
2025-11-05T13:42:50.953849Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] New ExecStep 1762350171001, ExecTxId 281474976710672
2025-11-05T13:42:50.953967Z node 4 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:42:50.953974Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from PLANNED to CALCULATING
2025-11-05T13:42:50.953985Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:42:50.954025Z node 4 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:42:50.954082Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] bootstrapping 0 [4:7569236345555011205:2452]
2025-11-05T13:42:50.954308Z node 4 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Initializing completed.
2025-11-05T13:42:50.954318Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] init complete for topic 'topic_A' partition 0 generation 1 [4:7569236345555011205:2452]
2025-11-05T13:42:50.954323Z 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:42:50.954388Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:42:50.954396Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.954416Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.954422Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:42:50.954424Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.954426Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.954428Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:42:50.954430Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350171001, TxId 281474976710672, Partition 0
2025-11-05T13:42:50.954434Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] Handle TEvProposePartitionConfigResult
2025-11-05T13:42:50.954435Z 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:42:50.954438Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] Partition responses 1/1
2025-11-05T13:42:50.954441Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATING
2025-11-05T13:42:50.954443Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State CALCULATING
2025-11-05T13:42:50.954445Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672 State CALCULATING FrontTxId 281474976710672
2025-11-05T13:42:50.954449Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:42:50.954453Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from CALCULATING to CALCULATED
2025-11-05T13:42:50.954457Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976710672
2025-11-05T13:42:50.954533Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] save tx TxId: 281474976710672 State: CALCULATED MinStep: 1762350171000 MaxStep: 18446744073709551615 Step: 1762350171001 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: 7569236324080173519 RawX2: 17179871332 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:42:50.954558Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.954780Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.954792Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATED
2025-11-05T13:42:50.954794Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State CALCULATED
2025-11-05T13:42:50.954795Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672 State CALCULATED FrontTxId 281474976710672
2025-11-05T13:42:50.954798Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from CALCULATED to WAIT_RS
2025-11-05T13:42:50.954809Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:42:50.954812Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveParticipantsDecision 1
2025-11-05T13:42:50.954820Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from WAIT_RS to EXECUTING
2025-11-05T13:42:50.954822Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 0, Expected 1
2025-11-05T13:42:50.954824Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350171001, TxId 281474976710672
2025-11-05T13:42:50.954827Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.954829Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.954852Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.954888Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:50.955304Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTxCommitDone Step 1762350171001, TxId 281474976710672, Partition 0
2025-11-05T13:42:50.955311Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTING
2025-11-05T13:42:50.955312Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State EXECUTING
2025-11-05T13:42:50.955314Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672 State EXECUTING FrontTxId 281474976710672
2025-11-05T13:42:50.955316Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:42:50.955316Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:42:50.955321Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId: 281474976710672 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:42:50.955321Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.955323Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.955327Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] complete TxId 281474976710672
2025-11-05T13:42:50.955376Z 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:42:50.955394Z node 4 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:42:50.955404Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] delete partitions for TxId 281474976710672
2025-11-05T13:42:50.955410Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from EXECUTING to EXECUTED
2025-11-05T13:42:50.955413Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976710672
2025-11-05T13:42:50.955459Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] save tx TxId: 281474976710672 State: EXECUTED MinStep: 1762350171000 MaxStep: 18446744073709551615 Step: 1762350171001 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: 7569236324080173519 RawX2: 17179871332 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:42:50.955484Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.955685Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.955697Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTED
2025-11-05T13:42:50.955699Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State EXECUTED
2025-11-05T13:42:50.955701Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672 State EXECUTED FrontTxId 281474976710672
2025-11-05T13:42:50.955704Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:42:50.955706Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:42:50.955709Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] PredicateAcks: 0/0
2025-11-05T13:42:50.955711Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:42:50.955712Z node 4 :PQ_TX DEBUG: [TxId: 281474976710672] PredicateAcks: 0/0
2025-11-05T13:42:50.955715Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] add an TxId 281474976710672 to the list for deletion
2025-11-05T13:42:50.955717Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710672 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:42:50.955722Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] delete key for TxId 281474976710672
2025-11-05T13:42:50.955730Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.955860Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:42:50.955879Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:42:50.955904Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:42:50.955912Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.955919Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state DELETING
2025-11-05T13:42:50.955920Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976710672, State DELETING
2025-11-05T13:42:50.955923Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] delete TxId 281474976710672
2025-11-05T13:42:50.955935Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:42:50.956341Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:42:50.956559Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:42:50.956564Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:2632
2025-11-05T13:42:50.957392Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:42:50.957472Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:42:50.957483Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2025-11-05T13:42:50.957609Z 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:42:50.957636Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "topic_A" message_group_id: "src" from ipv6:[::1]:49708
2025-11-05T13:42:50.957645Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:49708 proto=v1  topic=topic_A durationSec=0
2025-11-05T13:42:50.957649Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:42:50.958022Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2025-11-05T13:42:50.958059Z 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:42:50.958064Z 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:42:50.958066Z 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:42:50.958077Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236345555011240:2460] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:42:50.958082Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:42:50.958207Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:42:50.958208Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236345555011243:2460], now have 1 active actors on pipe
2025-11-05T13:42:50.958213Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.958216Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.958236Z node 4 :PERSQUEUE INFO: new Cookie src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0 generated for partition 0 topic 'topic_A' owner src
2025-11-05T13:42:50.958248Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.958254Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.958261Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.958273Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:42:50.958292Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.958332Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.958340Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.958360Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.958377Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0
2025-11-05T13:42:50.958538Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350170958 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:42:50.958560Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0" topic: "topic_A"
2025-11-05T13:42:50.958650Z :INFO: [/Root] MessageGroupId [src] SessionId [src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0] Write session: close. Timeout = 0 ms
2025-11-05T13:42:50.958658Z :INFO: [/Root] MessageGroupId [src] SessionId [src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0] Write session will now close
2025-11-05T13:42:50.958662Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0] Write session: aborting
2025-11-05T13:42:50.958767Z :INFO: [/Root] MessageGroupId [src] SessionId [src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:42:50.958771Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0] Write session: destroy
2025-11-05T13:42:50.958895Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0 grpc read done: success: 0 data: 
2025-11-05T13:42:50.958907Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0 grpc read failed
2025-11-05T13:42:50.958914Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0 grpc closed
2025-11-05T13:42:50.958916Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|703e4a0c-9aa4ca81-10f1a9d3-164d7cf2_0 is DEAD
2025-11-05T13:42:50.959146Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:42:50.959200Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236345555011243:2460] destroyed
2025-11-05T13:42:50.959212Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:42:50.959221Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.959227Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.962658Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Write session: try to update token
2025-11-05T13:42:50.962837Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:42:50.962847Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_A partition_id=0
2025-11-05T13:42:50.962885Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:42:50.963386Z node 4 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:42:50.963427Z node 4 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_A"
include_location: true
2025-11-05T13:42:50.963442Z node 4 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[4:7569236345555011253:2466]: Bootstrap
2025-11-05T13:42:50.963780Z node 4 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [4:7569236345555011253:2466]: Request location
2025-11-05T13:42:50.963844Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236345555011262:2467] connected; active server actors: 1
2025-11-05T13:42:50.963859Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] addPartitionToResponse tabletId 72075186224037894, partitionId 0, NodeId 4, Generation 1
2025-11-05T13:42:50.963880Z node 4 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [4:7569236345555011253:2466]: Got location
2025-11-05T13:42:50.963923Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236345555011262:2467] disconnected; active server actors: 1
2025-11-05T13:42:50.963932Z node 4 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [4:7569236345555011262:2467] disconnected no session
2025-11-05T13:42:50.964155Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 4
    generation: 1
  }
}
2025-11-05T13:42:50.964168Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=4 pl_generation=1
2025-11-05T13:42:50.964173Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 4 exists in the endpoint pool.
2025-11-05T13:42:50.964180Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=4 Generation=1
2025-11-05T13:42:50.964184Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 4
2025-11-05T13:42:50.964395Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:42:50.964423Z :DEBUG: [/Root]  TraceId []  SessionId []  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:42:50.964428Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:42:50.964546Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:42:50.964544Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:42:50.964555Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2025-11-05T13:42:50.964662Z 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" partition_with_generation { generation: 1 } }
2025-11-05T13:42:50.964693Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 3 path: "topic_A" producer_id: "test-message_group_id" partition_with_generation { generation: 1 } from ipv6:[::1]:49708
2025-11-05T13:42:50.964703Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="topic server" ip=ipv6:[::1]:49708 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:42:50.964707Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:42:50.964718Z node 4 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:42:50.964960Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2025-11-05T13:42:50.965015Z 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:42:50.965021Z 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:42:50.965023Z 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:42:50.965029Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236345555011267:2469] (SourceId=test-message_group_id, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:42:50.965034Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:42:50.965144Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:42:50.965159Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236345555011270:2469], now have 1 active actors on pipe
2025-11-05T13:42:50.965169Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.965178Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.965205Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 generated for partition 0 topic 'topic_A' owner test-message_group_id
2025-11-05T13:42:50.965218Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.965226Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.965235Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.965250Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:42:50.965271Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.965325Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.965335Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.965366Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.965399Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0
2025-11-05T13:42:50.965571Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:42:50.965594Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350170965 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:42:50.965607Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0"
2025-11-05T13:42:50.965610Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0
2025-11-05T13:42:50.965649Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=1, txId=01k9a430thc77bhw5h4g146hsr, WriteCount=1, AckCount=0
2025-11-05T13:42:50.970669Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:42:50.975360Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:42:50.975373Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:42:50.979184Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=2, txId=01k9a430thc77bhw5h4g146hsr, WriteCount=2, AckCount=0
2025-11-05T13:42:50.979204Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 2 to 2
2025-11-05T13:42:50.979223Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:42:50.979228Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 2
2025-11-05T13:42:50.986198Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:42:50.987246Z 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=NDZmYjk2ZGQtN2VlYmRkNjAtZTA1OTVjMjctZGQ4NjMxZTI= TxId: 01k9a430thc77bhw5h4g146hsr
2025-11-05T13:42:50.987368Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:42:50.987383Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236345555011274:2469], now have 1 active actors on pipe
2025-11-05T13:42:50.987616Z 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=NDZmYjk2ZGQtN2VlYmRkNjAtZTA1OTVjMjctZGQ4NjMxZTI= TxId: 01k9a430thc77bhw5h4g146hsr Status: SUCCESS
2025-11-05T13:42:50.987628Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) SessionId: ydb://session/3?node_id=4&id=NDZmYjk2ZGQtN2VlYmRkNjAtZTA1OTVjMjctZGQ4NjMxZTI= TxId: 01k9a430thc77bhw5h4g146hsr WriteId: {4, 281474976710673}
2025-11-05T13:42:50.987650Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.987663Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.987677Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] partition {0, {4, 281474976710673}, 100000} for WriteId {4, 281474976710673}
2025-11-05T13:42:50.987722Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvSubscribeLock for WriteId {4, 281474976710673}
2025-11-05T13:42:50.987751Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:50.987788Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976710673 LockNode: 4 Status: STATUS_SUBSCRIBED
2025-11-05T13:42:50.987798Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {4, 281474976710673}, TxId (empty maybe), Status STATUS_UNSPECIFIED
2025-11-05T13:42:50.987800Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] subscribed WriteId {4, 281474976710673}
2025-11-05T13:42:50.988060Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:50.988186Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:42:50.988277Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:42:50.988347Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateInit] bootstrapping {0, {4, 281474976710673}, 100000} [4:7569236345555011280:2471]
2025-11-05T13:42:50.988549Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:42:50.988710Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:42:50.988758Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:42:50.988800Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:42:50.988821Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:42:50.988827Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:42:50.988831Z node 4 :PERSQUEUE INFO: [topic_A:{0, {4, 281474976710673}, 100000}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:42:50.988833Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710673}, 100000}:Initializer] Initializing completed.
2025-11-05T13:42:50.988839Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateInit] init complete for topic 'topic_A' partition {0, {4, 281474976710673}, 100000} generation 1 [4:7569236345555011280:2471]
2025-11-05T13:42:50.988845Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateInit] SYNC INIT topic topic_A partitition {0, {4, 281474976710673}, 100000} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:42:50.988850Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:42:50.988853Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.988856Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.988898Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|dd6023ba-beaacfba-d3907f00-eaaa564c_0 generated for partition {0, {4, 281474976710673}, 100000} topic 'topic_A' owner test-message_group_id
2025-11-05T13:42:50.988909Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.988913Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.988925Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.988935Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:50.988957Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.988973Z 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=NDZmYjk2ZGQtN2VlYmRkNjAtZTA1OTVjMjctZGQ4NjMxZTI= TxId: 01k9a430thc77bhw5h4g146hsr
2025-11-05T13:42:50.989081Z 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=NDZmYjk2ZGQtN2VlYmRkNjAtZTA1OTVjMjctZGQ4NjMxZTI= TxId: 01k9a430thc77bhw5h4g146hsr Status: SUCCESS
2025-11-05T13:42:50.989103Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.989112Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.989128Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:50.989182Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.989190Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.989214Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976710673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:42:50.989242Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:42:50.989260Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:42:50.989303Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.989310Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.989327Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976710673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:42:50.989403Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:42:50.989416Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 0 messageNo: 1 size: 511944
2025-11-05T13:42:50.989468Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-11-05T13:42:50.989493Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 1 messageNo: 1 size: 511944
2025-11-05T13:42:50.989577Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 2 messageNo: 1 size: 511944
2025-11-05T13:42:50.989888Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 3 messageNo: 1 size: 511944
2025-11-05T13:42:50.990154Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 4 messageNo: 1 size: 511944
2025-11-05T13:42:50.990241Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 5 messageNo: 1 size: 511944
2025-11-05T13:42:50.990328Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 6 messageNo: 1 size: 511944
2025-11-05T13:42:50.990747Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 7 messageNo: 1 size: 511944
2025-11-05T13:42:50.991161Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 8 messageNo: 1 size: 511944
2025-11-05T13:42:50.991253Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 9 messageNo: 1 size: 511944
2025-11-05T13:42:50.991339Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 10 messageNo: 1 size: 511944
2025-11-05T13:42:50.991423Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 11 messageNo: 1 size: 511944
2025-11-05T13:42:50.991507Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 12 messageNo: 1 size: 511944
2025-11-05T13:42:50.991595Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client PART message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 13 messageNo: 1 size: 344802
2025-11-05T13:42:50.991605Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 1 partNo : 13 messageNo: 1 size 344802 offset: -1
2025-11-05T13:42:50.991632Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:50.991638Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:50.991653Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976710673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:42:50.991674Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:50.991694Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.991726Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 0
2025-11-05T13:42:50.991742Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 1
2025-11-05T13:42:50.991751Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 2
2025-11-05T13:42:50.991756Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 3
2025-11-05T13:42:50.991766Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 4
2025-11-05T13:42:50.991770Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 5
2025-11-05T13:42:50.991779Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 6
2025-11-05T13:42:50.991783Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 7
2025-11-05T13:42:50.991792Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 8
2025-11-05T13:42:50.991797Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 9
2025-11-05T13:42:50.991806Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 10
2025-11-05T13:42:50.991811Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 11
2025-11-05T13:42:50.991820Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 12
2025-11-05T13:42:50.991825Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 1 partNo 13
2025-11-05T13:42:50.994025Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob complete sourceId '\0test-message_group_id' seqNo 1 partNo 13 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 7001250 count 1 nextOffset 1 batches 14
2025-11-05T13:42:50.994056Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:50.994219Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {4, 281474976710673}, 100000} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100000_00000000000000000000_00000_0000000001_00013 size 7001240 WTime 1762350170994
2025-11-05T13:42:51.001001Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.001024Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 0 partNo 0 count 1 size 7001240
2025-11-05T13:42:51.001028Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 2  requestId: <none> cookie: 2
2025-11-05T13:42:51.001052Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:42:51.001117Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.001130Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.001165Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976710673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:42:51.001181Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 2 partNo : 0 messageNo: 3 size 16457 offset: -1
2025-11-05T13:42:51.001226Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Can't process txs
2025-11-05T13:42:51.001484Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 0 count 1 size 7001240 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.001530Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 7000382 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:42:51.001533Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 13 size 7001240
2025-11-05T13:42:51.001548Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001562Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:42:51.001574Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001580Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 1, Offset: 0 is stored on disk
2025-11-05T13:42:51.001590Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001602Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 2, Offset: 0 is stored on disk
2025-11-05T13:42:51.001612Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001618Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 3, Offset: 0 is stored on disk
2025-11-05T13:42:51.001621Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001626Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 4, Offset: 0 is stored on disk
2025-11-05T13:42:51.001630Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001635Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 5, Offset: 0 is stored on disk
2025-11-05T13:42:51.001639Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001645Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 6, Offset: 0 is stored on disk
2025-11-05T13:42:51.001650Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001655Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 7, Offset: 0 is stored on disk
2025-11-05T13:42:51.001658Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001664Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 8, Offset: 0 is stored on disk
2025-11-05T13:42:51.001667Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001672Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 9, Offset: 0 is stored on disk
2025-11-05T13:42:51.001675Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001681Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 10, Offset: 0 is stored on disk
2025-11-05T13:42:51.001685Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001691Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 11, Offset: 0 is stored on disk
2025-11-05T13:42:51.001694Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001700Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 12, Offset: 0 is stored on disk
2025-11-05T13:42:51.001708Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.001720Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 1, partNo: 13, Offset: 0 is stored on disk
2025-11-05T13:42:51.001721Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-11-05T13:42:51.001736Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:42:51.001744Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.001751Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.001777Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob processing sourceId '\0test-message_group_id' seqNo 2 partNo 0
2025-11-05T13:42:51.001805Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710673}, 100000} part blob complete sourceId '\0test-message_group_id' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 16546 count 1 nextOffset 2 batches 1
2025-11-05T13:42:51.001817Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.001874Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {4, 281474976710673}, 100000} compactOffset 1,1 HeadOffset 1 endOffset 1 curOffset 2 D0000100000_00000000000000000001_00000_0000000001_00000| size 16536 WTime 1762350171001
2025-11-05T13:42:51.001916Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.001927Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 1 partNo 0 count 1 size 16536
2025-11-05T13:42:51.002052Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:42:51.002090Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 1 written_in_tx { } } write_statistics { persisting_time { nanos: 9000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:42:51.002099Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=01k9a430thc77bhw5h4g146hsr, WriteCount=2, AckCount=1
2025-11-05T13:42:51.002104Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:42:51.002181Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 1 count 1 size 16536 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.002229Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100000 offset 1 partno 0 count 1 parts 0 size 16536
2025-11-05T13:42:51.002385Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 16479 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:42:51.002405Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.002413Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710673}, 100000}, SeqNo: 2, partNo: 0, Offset: 1 is stored on disk
2025-11-05T13:42:51.002433Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.002435Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.002446Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 3  requestId: <none> cookie: 2
2025-11-05T13:42:51.003111Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:42:51.003289Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:42:51.003319Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 2 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:42:51.003327Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] OnAck: seqNo=2, txId=01k9a430thc77bhw5h4g146hsr, WriteCount=2, AckCount=2
2025-11-05T13:42:51.003569Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 2
2025-11-05T13:42:51.004239Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236349849978594:2873], now have 1 active actors on pipe
2025-11-05T13:42:51.004285Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236349849978591 RawX2: 4503616807242144 } TxId: 281474976710674 Data { Operations { PartitionId: 0 Path: "/Root/topic_A" SupportivePartition: 100000 } Op: Commit SendingShards: 72075186224037894 ReceivingShards: 72075186224037894 Immediate: true WriteId { NodeId: 4 KeyId: 281474976710673 } }
2025-11-05T13:42:51.004299Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] PartitionId {0, {4, 281474976710673}, 100000} for WriteId {4, 281474976710673}
2025-11-05T13:42:51.004309Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710674 has WriteId {4, 281474976710673}
2025-11-05T13:42:51.004313Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] immediate transaction
2025-11-05T13:42:51.004331Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Send TEvGetWriteInfoRequest for TxId (empty maybe)
2025-11-05T13:42:51.004339Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.004342Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] The Tx (empty maybe) is waiting for TEvGetWriteInfoResponse
2025-11-05T13:42:51.004346Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still preprocessing - waiting for something
2025-11-05T13:42:51.004349Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Handle TEvPQ::TEvGetWriteInfoRequest
2025-11-05T13:42:51.004367Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Send TEvPQ::TEvGetWriteInfoResponse
2025-11-05T13:42:51.004383Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvGetWriteInfoResponse
2025-11-05T13:42:51.004390Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Received TEvGetWriteInfoResponse for TxId (empty maybe)
2025-11-05T13:42:51.004393Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.004403Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.004412Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::CommitWriteOperations TxId: (empty maybe)
2025-11-05T13:42:51.004420Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] t.WriteInfo->BodyKeys.size=1, t.WriteInfo->BlobsFromHead.size=1
2025-11-05T13:42:51.004429Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Head=Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0, NewHead=Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:42:51.004435Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] add key D0000100000_00000000000000000000_00000_0000000001_00013
2025-11-05T13:42:51.004447Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] PartitionedBlob.GetFormedBlobs().size=1
2025-11-05T13:42:51.004459Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] writing blob: topic 'topic_A' partition 0 old key D0000100000_00000000000000000000_00000_0000000001_00013 new key d0000000000_00000000000000000000_00000_0000000001_00013 size 7001240 WTime 1762350171004
2025-11-05T13:42:51.004470Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob processing sourceId '\0test-message_group_id' seqNo 2 partNo 0
2025-11-05T13:42:51.004486Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob complete sourceId '\0test-message_group_id' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 16546 count 1 nextOffset 2 batches 1
2025-11-05T13:42:51.004498Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] schedule TEvPersQueue::TEvProposeTransactionResult(COMPLETE), reason=
2025-11-05T13:42:51.004511Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.004556Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Add new write blob: topic 'topic_A' partition 0 compactOffset 1,1 HeadOffset 0 endOffset 0 curOffset 2 d0000000000_00000000000000000001_00000_0000000001_00000| size 16536 WTime 1762350171004
2025-11-05T13:42:51.004594Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.004610Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 0 offset 1 partNo 0 count 1 size 16536
2025-11-05T13:42:51.004615Z node 4 :PERSQUEUE DEBUG: CacheProxy. Rename blob from D0000100000_00000000000000000000_00000_0000000001_00013 to d0000000000_00000000000000000000_00000_0000000001_00013
2025-11-05T13:42:51.004904Z node 4 :PERSQUEUE DEBUG: Renaming head blob in L1. Old partition 100000 old offset 0 old count 1 new partition 0 new offset 0 new count 1 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.004913Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 0 offset 1 count 1 size 16536 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.004941Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 7016861
2025-11-05T13:42:51.004949Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Renamed. old Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 13, new Tablet '72075186224037894' partition 0 offset 0 partno 0 count 1 parts 13
2025-11-05T13:42:51.004967Z 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:42:51.004970Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 0 offset 1 partno 0 count 1 parts 0 size 16536
2025-11-05T13:42:51.004976Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-11-05T13:42:51.004979Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.004981Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.004993Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTransactionCompleted WriteId {4, 281474976710673}
2025-11-05T13:42:51.005001Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvPQ::TEvDeletePartition to partition {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.005016Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Handle TEvPQ::TEvDeletePartition
2025-11-05T13:42:51.005083Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] read cookie 0 Topic 'topic_A' partition 0 user test-consumer offset 0 count 1 size 1024000 endOffset 2 max time lag 0ms effective offset 0
2025-11-05T13:42:51.005097Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] read cookie 0 added 1 blobs, size 7001240 count 1 last offset 1, current partition end offset: 2
2025-11-05T13:42:51.005107Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Reading cookie 0. Send blob request.
2025-11-05T13:42:51.005115Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.005118Z node 4 :PERSQUEUE DEBUG: CacheProxy. Delete blobs from D0000100000(+) to D0000100001(-)
2025-11-05T13:42:51.005125Z node 4 :PERSQUEUE DEBUG: Got data from cache. Partition 0 offset 0 count 1 source 1 size 7001240 accessed 0 times before, last time 2025-11-05T13:42:51.000000Z
2025-11-05T13:42:51.005138Z node 4 :PERSQUEUE DEBUG: Reading cookie 0. All 1 blobs are from cache.
2025-11-05T13:42:51.005166Z node 4 :PERSQUEUE DEBUG: FormAnswer for 1 blobs
2025-11-05T13:42:51.005192Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976710673 LockNode: 4 Status: STATUS_NOT_FOUND
2025-11-05T13:42:51.005203Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {4, 281474976710673}, TxId 281474976710674, Status STATUS_SUBSCRIBED
2025-11-05T13:42:51.005205Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] there is already a transaction TxId 281474976710674 for WriteId {4, 281474976710673}
2025-11-05T13:42:51.005242Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Touched. Tablet '72075186224037894' partition 0 offset 0 partno 0 count 1 parts 13
2025-11-05T13:42:51.005329Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512009 from pos 0 cbcount 1
2025-11-05T13:42:51.005363Z node 4 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100000 offset 1 count 1 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.005394Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037894' partition 100000 offset 1 partno 0 count 1 parts 0
2025-11-05T13:42:51.005403Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.005406Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.005493Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.005508Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvDeletePartitionDone {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.005526Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] DeletePartition {0, {4, 281474976710673}, 100000}
2025-11-05T13:42:51.005532Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvUnsubscribeLock for WriteId {4, 281474976710673}
2025-11-05T13:42:51.005539Z node 4 :PQ_TX WARN: [PQ: 72075186224037894] Unknown transaction 281474976710674
2025-11-05T13:42:51.005551Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:51.005655Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.005695Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:51.005798Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.006290Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.006774Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.006916Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.007133Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.007281Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.007605Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.007746Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.007796Z node 4 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:42:51.007882Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.008022Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 0 size 512005 from pos 0 cbcount 1
2025-11-05T13:42:51.008117Z node 4 :PERSQUEUE DEBUG: FormAnswer processing batch offset 0 totakecount 1 count 1 size 344863 from pos 0 cbcount 1
2025-11-05T13:42:51.008157Z node 4 :PERSQUEUE DEBUG: Topic 'topic_A' partition 0 user test-consumer readTimeStamp done, result 1762350170991 queuesize 0 startOffset 0
2025-11-05T13:42:51.008363Z node 4 :TX_PROXY ERROR: Actor# [4:7569236349849978613:2880] txid# 281474976710675, issues: { message: "Check failed: path: \'/Root/topic_A\', error: path exist, request accepts it (id: [OwnerId: 72057594046644480, LocalPathId: 10], type: EPathTypePersQueueGroup, state: EPathStateNoChanges), source_location: ydb/core/tx/schemeshard/schemeshard__operation_create_pq.cpp:345" severity: 1 }
2025-11-05T13:42:51.008704Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:42:51.008902Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:42:51.008906Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:2632
2025-11-05T13:42:51.009760Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:42:51.009819Z node 4 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:42:51.009831Z node 4 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2025-11-05T13:42:51.009958Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:42:51.009978Z node 4 :PQ_WRITE_PROXY INFO: session request cookie: 4 topic: "topic_A" message_group_id: "src" from ipv6:[::1]:49708
2025-11-05T13:42:51.009988Z node 4 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:49708 proto=v1  topic=topic_A durationSec=0
2025-11-05T13:42:51.009992Z node 4 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:42:51.010201Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2025-11-05T13:42:51.010237Z 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:42:51.010242Z 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:42:51.010244Z 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:42:51.010256Z node 4 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [4:7569236349849978624:2482] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:42:51.010260Z node 4 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:42:51.010366Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:42:51.010372Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236349849978627:2482], now have 1 active actors on pipe
2025-11-05T13:42:51.010378Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.010382Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.010411Z node 4 :PERSQUEUE INFO: new Cookie src|abb21af4-90ce02a4-3f4fe842-62445cbd_0 generated for partition 0 topic 'topic_A' owner src
2025-11-05T13:42:51.010423Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.010426Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.010434Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.010444Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:42:51.010466Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:51.010513Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.010521Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.010538Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:51.010562Z node 4 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 0 MaxSeqNo: 0 sessionId: src|abb21af4-90ce02a4-3f4fe842-62445cbd_0
2025-11-05T13:42:51.010730Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350171010 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:42:51.010753Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|abb21af4-90ce02a4-3f4fe842-62445cbd_0" topic: "topic_A"
2025-11-05T13:42:51.010830Z :INFO: [/Root] MessageGroupId [src] SessionId [src|abb21af4-90ce02a4-3f4fe842-62445cbd_0] Write session: close. Timeout = 0 ms
2025-11-05T13:42:51.010837Z :INFO: [/Root] MessageGroupId [src] SessionId [src|abb21af4-90ce02a4-3f4fe842-62445cbd_0] Write session will now close
2025-11-05T13:42:51.010841Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|abb21af4-90ce02a4-3f4fe842-62445cbd_0] Write session: aborting
2025-11-05T13:42:51.010937Z :INFO: [/Root] MessageGroupId [src] SessionId [src|abb21af4-90ce02a4-3f4fe842-62445cbd_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:42:51.010941Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|abb21af4-90ce02a4-3f4fe842-62445cbd_0] Write session: destroy
2025-11-05T13:42:51.011058Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: src|abb21af4-90ce02a4-3f4fe842-62445cbd_0 grpc read done: success: 0 data: 
2025-11-05T13:42:51.011065Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: src|abb21af4-90ce02a4-3f4fe842-62445cbd_0 grpc read failed
2025-11-05T13:42:51.011070Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: src|abb21af4-90ce02a4-3f4fe842-62445cbd_0 grpc closed
2025-11-05T13:42:51.011072Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: src|abb21af4-90ce02a4-3f4fe842-62445cbd_0 is DEAD
2025-11-05T13:42:51.011273Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:42:51.011318Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236349849978627:2482] destroyed
2025-11-05T13:42:51.011329Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:42:51.011332Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.011333Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.013216Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=3, txId=01k9a430w48t1ydta6sr9h1yef, WriteCount=1, AckCount=0
2025-11-05T13:42:51.013228Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 3 to 3
2025-11-05T13:42:51.013247Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:42:51.013251Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 3
2025-11-05T13:42:51.013462Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:42:51.013582Z 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=MTEzZjAxYTYtNTY3MDNhMDAtMzc1NzE3Ny05MzM3MDNi TxId: 01k9a430w48t1ydta6sr9h1yef
2025-11-05T13:42:51.013665Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 4, Generation: 1
2025-11-05T13:42:51.013674Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [4:7569236349849978636:2469], now have 1 active actors on pipe
2025-11-05T13:42:51.013860Z 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=MTEzZjAxYTYtNTY3MDNhMDAtMzc1NzE3Ny05MzM3MDNi TxId: 01k9a430w48t1ydta6sr9h1yef Status: SUCCESS
2025-11-05T13:42:51.013870Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) SessionId: ydb://session/3?node_id=4&id=MTEzZjAxYTYtNTY3MDNhMDAtMzc1NzE3Ny05MzM3MDNi TxId: 01k9a430w48t1ydta6sr9h1yef WriteId: {4, 281474976710676}
2025-11-05T13:42:51.013892Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.013901Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.013906Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] partition {0, {4, 281474976710676}, 100001} for WriteId {4, 281474976710676}
2025-11-05T13:42:51.013939Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvSubscribeLock for WriteId {4, 281474976710676}
2025-11-05T13:42:51.013965Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:51.013989Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976710676 LockNode: 4 Status: STATUS_SUBSCRIBED
2025-11-05T13:42:51.013997Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {4, 281474976710676}, TxId (empty maybe), Status STATUS_UNSPECIFIED
2025-11-05T13:42:51.014000Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] subscribed WriteId {4, 281474976710676}
2025-11-05T13:42:51.014206Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:51.014306Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:42:51.014385Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:42:51.014438Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateInit] bootstrapping {0, {4, 281474976710676}, 100001} [4:7569236349849978642:2487]
2025-11-05T13:42:51.014624Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:42:51.014724Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:42:51.014756Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:42:51.014788Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:42:51.014807Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:42:51.014810Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:42:51.014813Z node 4 :PERSQUEUE INFO: [topic_A:{0, {4, 281474976710676}, 100001}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:42:51.014815Z node 4 :PERSQUEUE DEBUG: [topic_A:{0, {4, 281474976710676}, 100001}:Initializer] Initializing completed.
2025-11-05T13:42:51.014821Z node 4 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateInit] init complete for topic 'topic_A' partition {0, {4, 281474976710676}, 100001} generation 1 [4:7569236349849978642:2487]
2025-11-05T13:42:51.014827Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateInit] SYNC INIT topic topic_A partitition {0, {4, 281474976710676}, 100001} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:42:51.014831Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:42:51.014833Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.014836Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.014871Z node 4 :PERSQUEUE INFO: new Cookie test-message_group_id|3c432a-f9ac91b2-5de53a7f-316ecc8_0 generated for partition {0, {4, 281474976710676}, 100001} topic 'topic_A' owner test-message_group_id
2025-11-05T13:42:51.014876Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.014879Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.014886Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.014893Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {4, 281474976710676}, 100001}
2025-11-05T13:42:51.014904Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:51.014914Z 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=MTEzZjAxYTYtNTY3MDNhMDAtMzc1NzE3Ny05MzM3MDNi TxId: 01k9a430w48t1ydta6sr9h1yef
2025-11-05T13:42:51.014994Z 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=MTEzZjAxYTYtNTY3MDNhMDAtMzc1NzE3Ny05MzM3MDNi TxId: 01k9a430w48t1ydta6sr9h1yef Status: SUCCESS
2025-11-05T13:42:51.015028Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.015038Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.015061Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:42:51.015097Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.015103Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.015121Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976710676 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:42:51.015139Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 3
2025-11-05T13:42:51.015154Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:42:51.015181Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:42:51.015186Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:42:51.015194Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 4 KeyId: 281474976710676 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:42:51.015206Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id' SeqNo: 3 partNo : 0 messageNo: 1 size 16457 offset: -1
2025-11-05T13:42:51.015229Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.015239Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.015258Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710676}, 100001} part blob processing sourceId '\0test-message_group_id' seqNo 3 partNo 0
2025-11-05T13:42:51.015291Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Topic 'topic_A' partition {0, {4, 281474976710676}, 100001} part blob complete sourceId '\0test-message_group_id' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 16546 count 1 nextOffset 1 batches 1
2025-11-05T13:42:51.015301Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.015351Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {4, 281474976710676}, 100001} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100001_00000000000000000000_00000_0000000001_00000| size 16536 WTime 1762350171015
2025-11-05T13:42:51.015387Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.015398Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100001 offset 0 partNo 0 count 1 size 16536
2025-11-05T13:42:51.015601Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100001 offset 0 count 1 size 16536 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.015631Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100001 offset 0 partno 0 count 1 parts 0 size 16536
2025-11-05T13:42:51.015662Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 16479 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:42:51.015677Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {4, 281474976710676}, 100001}
2025-11-05T13:42:51.015691Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id', Topic: 'topic_A', Partition: {0, {4, 281474976710676}, 100001}, SeqNo: 3, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:42:51.015696Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 3
2025-11-05T13:42:51.015706Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:42:51.015711Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.015713Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.015900Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:42:51.015932Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 3 written_in_tx { } } write_statistics { persisting_time { } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:42:51.015939Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] OnAck: seqNo=3, txId=01k9a430w48t1ydta6sr9h1yef, WriteCount=1, AckCount=1
2025-11-05T13:42:51.016113Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 3
2025-11-05T13:42:51.016542Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236349849978655 RawX2: 4503616807242165 } TxId: 281474976710677 Data { Operations { PartitionId: 0 Path: "/Root/topic_A" SupportivePartition: 100001 } Op: Commit SendingShards: 72075186224037894 ReceivingShards: 72075186224037894 Immediate: true WriteId { NodeId: 4 KeyId: 281474976710676 } }
2025-11-05T13:42:51.016555Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] PartitionId {0, {4, 281474976710676}, 100001} for WriteId {4, 281474976710676}
2025-11-05T13:42:51.016560Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976710677 has WriteId {4, 281474976710676}
2025-11-05T13:42:51.016562Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] immediate transaction
2025-11-05T13:42:51.016574Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Send TEvGetWriteInfoRequest for TxId (empty maybe)
2025-11-05T13:42:51.016582Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.016584Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] The Tx (empty maybe) is waiting for TEvGetWriteInfoResponse
2025-11-05T13:42:51.016586Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still preprocessing - waiting for something
2025-11-05T13:42:51.016586Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Handle TEvPQ::TEvGetWriteInfoRequest
2025-11-05T13:42:51.016599Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Send TEvPQ::TEvGetWriteInfoResponse
2025-11-05T13:42:51.016608Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvGetWriteInfoResponse
2025-11-05T13:42:51.016610Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Received TEvGetWriteInfoResponse for TxId (empty maybe)
2025-11-05T13:42:51.016612Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.016618Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.016626Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::CommitWriteOperations TxId: (empty maybe)
2025-11-05T13:42:51.016632Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] t.WriteInfo->BodyKeys.size=0, t.WriteInfo->BlobsFromHead.size=1
2025-11-05T13:42:51.016640Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Head=Offset 1 PartNo 0 PackedSize 16536 count 1 nextOffset 2 batches 1, NewHead=Offset 2 PartNo 0 PackedSize 0 count 0 nextOffset 2 batches 0
2025-11-05T13:42:51.016652Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob processing sourceId '\0test-message_group_id' seqNo 3 partNo 0
2025-11-05T13:42:51.016671Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob complete sourceId '\0test-message_group_id' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 2 PartNo 0 PackedSize 16546 count 1 nextOffset 3 batches 1
2025-11-05T13:42:51.016682Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] schedule TEvPersQueue::TEvProposeTransactionResult(COMPLETE), reason=
2025-11-05T13:42:51.016691Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.016730Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Add new write blob: topic 'topic_A' partition 0 compactOffset 2,1 HeadOffset 1 endOffset 2 curOffset 3 d0000000000_00000000000000000002_00000_0000000001_00000| size 16536 WTime 1762350171016
2025-11-05T13:42:51.016765Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.016775Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 0 offset 2 partNo 0 count 1 size 16536
2025-11-05T13:42:51.016991Z node 4 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 0 offset 2 count 1 size 16536 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.017019Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 0 offset 2 partno 0 count 1 parts 0 size 16536
2025-11-05T13:42:51.017215Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 16479
2025-11-05T13:42:51.017238Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.017245Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.017253Z node 4 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTransactionCompleted WriteId {4, 281474976710676}
2025-11-05T13:42:51.017261Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvPQ::TEvDeletePartition to partition {0, {4, 281474976710676}, 100001}
2025-11-05T13:42:51.017266Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Handle TEvPQ::TEvDeletePartition
2025-11-05T13:42:51.017281Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:42:51.017288Z node 4 :PERSQUEUE DEBUG: CacheProxy. Delete blobs from D0000100001(+) to D0000100002(-)
2025-11-05T13:42:51.017398Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976710676 LockNode: 4 Status: STATUS_NOT_FOUND
2025-11-05T13:42:51.017408Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {4, 281474976710676}, TxId 281474976710677, Status STATUS_SUBSCRIBED
2025-11-05T13:42:51.017411Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] there is already a transaction TxId 281474976710677 for WriteId {4, 281474976710676}
2025-11-05T13:42:51.017447Z node 4 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100001 offset 0 count 1 actorID [4:7569236345555011180:2451]
2025-11-05T13:42:51.017478Z node 4 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037894' partition 100001 offset 0 partno 0 count 1 parts 0
2025-11-05T13:42:51.017483Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.017487Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {4, 281474976710676}, 100001}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.017503Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvDeletePartitionDone {0, {4, 281474976710676}, 100001}
2025-11-05T13:42:51.017506Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] DeletePartition {0, {4, 281474976710676}, 100001}
2025-11-05T13:42:51.017523Z node 4 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvUnsubscribeLock for WriteId {4, 281474976710676}
2025-11-05T13:42:51.017526Z node 4 :PQ_TX WARN: [PQ: 72075186224037894] Unknown transaction 281474976710677
2025-11-05T13:42:51.017536Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:42:51.017636Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:42:51.018013Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 0.000000s
2025-11-05T13:42:51.018017Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:42:51.018022Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:42:51.018369Z node 4 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 grpc read done: success: 0 data: 
2025-11-05T13:42:51.018377Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 grpc read failed
2025-11-05T13:42:51.018384Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 grpc closed
2025-11-05T13:42:51.018386Z node 4 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0 is DEAD
2025-11-05T13:42:51.018559Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:42:51.018576Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:42:51.018588Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:42:51.018592Z node 4 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:42:51.018625Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236345555011274:2469] destroyed
2025-11-05T13:42:51.018633Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236349849978636:2469] destroyed
2025-11-05T13:42:51.018635Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [4:7569236345555011270:2469] destroyed
2025-11-05T13:42:51.018641Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:42:51.018648Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.018650Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.018767Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 1, Msg: CANCELLED, Details: , InternalError: 0
2025-11-05T13:42:51.018780Z :TRACE: [/Root] TRACE_EVENT Error  status=CLIENT_CANCELLED
2025-11-05T13:42:51.018783Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session is aborting and will not restart
2025-11-05T13:42:51.018803Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id|f5425ad7-beb99b71-d21ffda7-48cd5cd5_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:42:51.041290Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.041302Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.054640Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.054658Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.141666Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.141688Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:42:51.154946Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:42:51.154961Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
