2025-11-05T13:43:26.318022Z node 7 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[7:7569236501468631091:2138];send_to=[0:7307199536658146131:7762515];
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/4xc1/003f58/r3tmp/tmpeP7phv/pdisk_1.dat
2025-11-05T13:43:26.319426Z node 7 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:69;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-11-05T13:43:26.319582Z node 7 :PQ_READ_PROXY DEBUG: Direct read cache: : Created
2025-11-05T13:43:26.332507Z node 7 :IMPORT WARN: Table profiles were not loaded
2025-11-05T13:43:26.332722Z node 7 :CONFIGS_DISPATCHER ERROR: Notification cookie mismatch for subscription [7:7569236501468630992:2081] 1762350206316772 != 1762350206316775
TServer::EnableGrpc on GrpcPort 7604, node 7
2025-11-05T13:43:26.340035Z node 7 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/4xc1/003f58/r3tmp/yandexThthKh.tmp
2025-11-05T13:43:26.340046Z node 7 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/4xc1/003f58/r3tmp/yandexThthKh.tmp
2025-11-05T13:43:26.343524Z INFO: TTestServer started on Port 15993 GrpcPort 7604
2025-11-05T13:43:26.344997Z node 7 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/4xc1/003f58/r3tmp/yandexThthKh.tmp
2025-11-05T13:43:26.345082Z node 7 :NET_CLASSIFIER ERROR: got bad distributable configuration
TClient is connected to server localhost:15993
PQClient connected to localhost:7604
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
    ChildrenExist: false
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      Pl...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-11-05T13:43:26.422506Z node 7 :HIVE WARN: HIVE#72057594037968897 Node(7, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-11-05T13:43:26.422540Z node 7 :HIVE WARN: HIVE#72057594037968897 Node(7, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-11-05T13:43:26.422883Z node 7 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976715657:0, at schemeshard:  72057594046644480
waiting...
2025-11-05T13:43:26.423521Z node 7 :HIVE WARN: HIVE#72057594037968897 Node(7, (0,0,0,0)) VolatileState: Connecting -> Connected
waiting...
2025-11-05T13:43:26.442485Z node 7 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715659:0, at schemeshard:  72057594046644480
waiting...
waiting...
waiting...
2025-11-05T13:43:26.641490Z node 7 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [7:7569236501468631759:2316], status: SCHEME_ERROR, issues: <main>: Error: Type annotation, code: 1030
    <main>:3:16: Error: At function: KiReadTable!
        <main>:3:16: Error: Cannot find table 'db.[/Root/PQ/Config/V2/Cluster]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions., code: 2003
2025-11-05T13:43:26.642532Z node 7 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=7&id=Nzc1NGUyNC01ZGQ0M2ZiNS1hZGViODc1ZC1iYWQxMmJmOA==, ActorId: [7:7569236501468631756:2314], ActorState: ExecuteState, TraceId: 01k9a443nd48rng3gpye4pesaf, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-11-05T13:43:26.642648Z node 7 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 3 column: 16 } message: "At function: KiReadTable!" end_position { row: 3 column: 16 } severity: 1 issues { position { row: 3 column: 16 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Cluster]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 3 column: 16 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2025-11-05T13:43:26.643376Z node 7 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715662:0, at schemeshard:  72057594046644480
2025-11-05T13:43:26.650329Z node 7 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715663:0, at schemeshard:  72057594046644480
2025-11-05T13:43:26.665388Z node 7 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715664:0, at schemeshard:  72057594046644480
=== Init DC: UPSERT INTO `/Root/PQ/Config/V2/Cluster` (name, balancer, local, enabled, weight) VALUES ("dc1", "localhost", true, true, 1000), ("dc2", "dc2.logbroker.yandex.net", false, true, 1000);
=== CheckClustersList. Subcribe to ClusterTracker from [7:7569236501468632034:2562] 
2025-11-05T13:43:27.318835Z node 7 :TX_CONVEYOR ERROR: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-11-05T13:43:31.317641Z node 7 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[7:7569236501468631091:2138];send_to=[0:7307199536658146131:7762515];
2025-11-05T13:43:31.317681Z node 7 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:69;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
=== CheckClustersList. Ok
2025-11-05T13:43:31.828417Z :WriteToTopic_Demo_28 INFO: TTopicSdkTestSetup started
2025-11-05T13:43:31.847018Z node 7 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:31.854725Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:31.854843Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037893][] pipe [7:7569236522943468821:2735] connected; active server actors: 1
2025-11-05T13:43:31.854908Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:31.855164Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:31.855205Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:31.855237Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] doesn't have tx info
2025-11-05T13:43:31.855241Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:31.855243Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-11-05T13:43:31.855247Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:31.855253Z node 7 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:31.855262Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037892] doesn't have tx writes info
2025-11-05T13:43:31.855286Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:31.855301Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] BALANCER INIT DONE for test-topic: (0, 72075186224037892) 
2025-11-05T13:43:31.855687Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [7:7569236522943468820:2734], now have 1 active actors on pipe
2025-11-05T13:43:31.855802Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236501468631340 RawX2: 30064773219 } TxId: 281474976715671 Config { TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 TotalPartitions: 1 ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } SourceIdMaxCounts: 6000000 } PartitionIds: 0 TopicName: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 } } }
2025-11-05T13:43:31.855833Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] Propose TxId 281474976715671, WriteId (empty maybe)
2025-11-05T13:43:31.855837Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state UNKNOWN
2025-11-05T13:43:31.855839Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State UNKNOWN
2025-11-05T13:43:31.855842Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:31.855846Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from UNKNOWN to PREPARING
2025-11-05T13:43:31.855852Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:31.855903Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: PREPARED MinStep: 1762350211874 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: 7569236501468631340 RawX2: 30064773219 } Partitions { }
2025-11-05T13:43:31.855920Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.856070Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [7:7569236522943468859:2423], now have 1 active actors on pipe
2025-11-05T13:43:31.856125Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72075186224037892, NodeId 7, Generation 1
2025-11-05T13:43:31.856128Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] TEvClientConnected TabletId 72057594046644480, NodeId 7, Generation 2
2025-11-05T13:43:31.856280Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.856287Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARING
2025-11-05T13:43:31.856289Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PREPARING
2025-11-05T13:43:31.856291Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PREPARING to PREPARED
2025-11-05T13:43:31.856811Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037892 TxId: 281474976715671
2025-11-05T13:43:31.856822Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [7:7569236522943468870:2763], now have 1 active actors on pipe
2025-11-05T13:43:31.856838Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715671 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350211902 MediatorID: 72057594046382081 TabletID: 72075186224037892
2025-11-05T13:43:31.856843Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARED
2025-11-05T13:43:31.856846Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PREPARED
2025-11-05T13:43:31.856849Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PREPARED to PLANNING
2025-11-05T13:43:31.856854Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] PlanStep 1762350211902, PlanTxId 281474976715671
2025-11-05T13:43:31.856858Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:31.856927Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: PLANNED MinStep: 1762350211874 MaxStep: 18446744073709551615 Step: 1762350211902 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: 7569236501468631340 RawX2: 30064773219 } Partitions { }
2025-11-05T13:43:31.856943Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.857235Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.857241Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state PLANNING
2025-11-05T13:43:31.857243Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State PLANNING
2025-11-05T13:43:31.857245Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PLANNING to PLANNED
2025-11-05T13:43:31.857249Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxQueue.size 1
2025-11-05T13:43:31.857252Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] New ExecStep 1762350211902, ExecTxId 281474976715671
2025-11-05T13:43:31.857371Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from PLANNED to CALCULATING
2025-11-05T13:43:31.857382Z node 7 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:31.857389Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:31.857457Z node 7 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:31.857511Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] bootstrapping 0 [7:7569236522943468876:2426]
2025-11-05T13:43:31.857746Z node 7 :PERSQUEUE DEBUG: [test-topic:0:Initializer] Initializing completed.
2025-11-05T13:43:31.857750Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037892, Partition: 0, State: StateInit] init complete for topic 'test-topic' partition 0 generation 1 [7:7569236522943468876:2426]
2025-11-05T13:43:31.857756Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] SYNC INIT topic test-topic partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:31.857829Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:31.857834Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.857851Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.857856Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:31.857859Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.857861Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.857863Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:31.857871Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Topic 'test-topic' partition 0 user test-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:31.857914Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350211902, TxId 281474976715671, Partition 0
2025-11-05T13:43:31.857916Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:31.857920Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] Partition responses 1/1
2025-11-05T13:43:31.857922Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-11-05T13:43:31.857924Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State CALCULATING
2025-11-05T13:43:31.857927Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State CALCULATING FrontTxId 281474976715671
2025-11-05T13:43:31.857931Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:43:31.857934Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from CALCULATING to CALCULATED
2025-11-05T13:43:31.857937Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:31.858005Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: CALCULATED MinStep: 1762350211874 MaxStep: 18446744073709551615 Step: 1762350211902 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: 7569236501468631340 RawX2: 30064773219 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:31.858021Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.858515Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.858521Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATED
2025-11-05T13:43:31.858522Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State CALCULATED
2025-11-05T13:43:31.858523Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State CALCULATED FrontTxId 281474976715671
2025-11-05T13:43:31.858525Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:31.858536Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:31.858538Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveParticipantsDecision 1
2025-11-05T13:43:31.858544Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:31.858546Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 0, Expected 1
2025-11-05T13:43:31.858557Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350211902, TxId 281474976715671
2025-11-05T13:43:31.858560Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.858562Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.858585Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.858613Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:31.861916Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:31.861934Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.861937Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.861985Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1762350211902, TxId 281474976715671, Partition 0
2025-11-05T13:43:31.861991Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-11-05T13:43:31.861994Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State EXECUTING
2025-11-05T13:43:31.861998Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State EXECUTING FrontTxId 281474976715671
2025-11-05T13:43:31.862002Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Received 1, Expected 1
2025-11-05T13:43:31.862010Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId: 281474976715671 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:31.862021Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] complete TxId 281474976715671
2025-11-05T13:43:31.862118Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 TotalPartitions: 1 ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } SourceIdMaxCounts: 6000000 } PartitionIds: 0 TopicName: "test-topic" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/test-topic" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 }
2025-11-05T13:43:31.862138Z node 7 :PERSQUEUE NOTICE: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:31.862151Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] delete partitions for TxId 281474976715671
2025-11-05T13:43:31.862154Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from EXECUTING to EXECUTED
2025-11-05T13:43:31.862161Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] write key for TxId 281474976715671
2025-11-05T13:43:31.862223Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] save tx TxId: 281474976715671 State: EXECUTED MinStep: 1762350211874 MaxStep: 18446744073709551615 Step: 1762350211902 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: 7569236501468631340 RawX2: 30064773219 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:31.862268Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.863411Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.863422Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTED
2025-11-05T13:43:31.863425Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State EXECUTED
2025-11-05T13:43:31.863428Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671 State EXECUTED FrontTxId 281474976715671
2025-11-05T13:43:31.863436Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:31.863439Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:31.863448Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] PredicateAcks: 0/0
2025-11-05T13:43:31.863451Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:31.863452Z node 7 :PQ_TX DEBUG: [TxId: 281474976715671] PredicateAcks: 0/0
2025-11-05T13:43:31.863455Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] add an TxId 281474976715671 to the list for deletion
2025-11-05T13:43:31.863459Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] TxId 281474976715671 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:31.863466Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] delete key for TxId 281474976715671
2025-11-05T13:43:31.863478Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.863731Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:31.864321Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:31.864364Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.864368Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Try execute txs with state DELETING
2025-11-05T13:43:31.864370Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] TxId 281474976715671, State DELETING
2025-11-05T13:43:31.864374Z node 7 :PQ_TX INFO: [PQ: 72075186224037892] delete TxId 281474976715671
2025-11-05T13:43:31.869552Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:31.869835Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:31.869843Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:7604
2025-11-05T13:43:31.875087Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "test-topic" message_group_id: "src" }
2025-11-05T13:43:31.877653Z node 7 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:31.877671Z node 7 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2025-11-05T13:43:31.877901Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "test-topic" message_group_id: "src" }
2025-11-05T13:43:31.877924Z node 7 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "test-topic" message_group_id: "src" from ipv6:[::1]:36086
2025-11-05T13:43:31.877929Z node 7 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36086 proto=v1  topic=test-topic durationSec=0
2025-11-05T13:43:31.877933Z node 7 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:31.878992Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  describe result for acl check
2025-11-05T13:43:31.879031Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:31.879033Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:31.879034Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:31.879046Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [7:7569236522943468921:2434] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:31.879049Z node 7 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 1 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:31.879339Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 7, Generation: 1
2025-11-05T13:43:31.879358Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server connected, pipe [7:7569236522943468924:2434], now have 1 active actors on pipe
2025-11-05T13:43:31.879429Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:43:31.879436Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:43:31.879463Z node 7 :PERSQUEUE INFO: new Cookie src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0 generated for partition 0 topic 'test-topic' owner src
2025-11-05T13:43:31.879475Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.879482Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.879495Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.879510Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:31.879529Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:31.879613Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'test-topic' requestId: <none>
2025-11-05T13:43:31.879616Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] got client message batch for topic 'test-topic' partition 0
2025-11-05T13:43:31.879628Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'test-topic' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:31.879639Z node 7 :PQ_WRITE_PROXY INFO: session inited cookie: 1 partition: 0 MaxSeqNo: 0 sessionId: src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0
2025-11-05T13:43:31.882212Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350211882 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:31.882250Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0" topic: "test-topic"
2025-11-05T13:43:31.882364Z :INFO: [/Root] MessageGroupId [src] SessionId [src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:31.882374Z :INFO: [/Root] MessageGroupId [src] SessionId [src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0] Write session will now close
2025-11-05T13:43:31.882382Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0] Write session: aborting
2025-11-05T13:43:31.882629Z :INFO: [/Root] MessageGroupId [src] SessionId [src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:31.882634Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0] Write session is aborting and will not restart
2025-11-05T13:43:31.882851Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0] Write session: destroy
2025-11-05T13:43:31.885857Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0 grpc read done: success: 0 data: 
2025-11-05T13:43:31.885870Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0 grpc read failed
2025-11-05T13:43:31.885879Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0 grpc closed
2025-11-05T13:43:31.885883Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: src|d2c3fd4a-bea7d327-22fffe64-1eb9c8cf_0 is DEAD
2025-11-05T13:43:31.886143Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:31.886531Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892] server disconnected, pipe [7:7569236522943468924:2434] destroyed
2025-11-05T13:43:31.886549Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:31.886556Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.886558Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.889890Z :WriteToTopic_Demo_28 INFO: Topic created
2025-11-05T13:43:31.905704Z node 7 :PQ_READ_PROXY DEBUG: new create topic request
2025-11-05T13:43:31.909734Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:31.909879Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:31.912709Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvInterconnect::TEvNodeInfo
2025-11-05T13:43:31.912868Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][] pipe [7:7569236522943468957:2800] connected; active server actors: 1
2025-11-05T13:43:31.912929Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] updating configuration. Deleted partitions []. Added partitions [0]
2025-11-05T13:43:31.913311Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:31.913368Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-11-05T13:43:31.913412Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] doesn't have tx info
2025-11-05T13:43:31.913445Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-11-05T13:43:31.913447Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] no config, start with empty partitions and default config
2025-11-05T13:43:31.913452Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Txs.size=0, PlannedTxs.size=0
2025-11-05T13:43:31.913457Z node 7 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:31.913467Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037894] doesn't have tx writes info
2025-11-05T13:43:31.913499Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:31.913517Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] BALANCER INIT DONE for topic_A: (0, 72075186224037894) 
2025-11-05T13:43:31.914064Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72057594046644480, NodeId 7, Generation 2
2025-11-05T13:43:31.914067Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] TEvClientConnected TabletId 72075186224037894, NodeId 7, Generation 1
2025-11-05T13:43:31.914076Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236522943469002:2448], now have 1 active actors on pipe
2025-11-05T13:43:31.956064Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.956082Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.959882Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236522943468956:2799], now have 1 active actors on pipe
2025-11-05T13:43:31.960049Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236501468631340 RawX2: 30064773219 } TxId: 281474976715672 Config { TabletConfig { PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 TotalPartitions: 1 ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } SourceIdMaxCounts: 6000000 } PartitionIds: 0 TopicName: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 } } }
2025-11-05T13:43:31.960097Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] Propose TxId 281474976715672, WriteId (empty maybe)
2025-11-05T13:43:31.960104Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state UNKNOWN
2025-11-05T13:43:31.960108Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State UNKNOWN
2025-11-05T13:43:31.960114Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] schedule TEvProposeTransactionResult(PREPARED)
2025-11-05T13:43:31.960119Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from UNKNOWN to PREPARING
2025-11-05T13:43:31.960131Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:31.960188Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: PREPARED MinStep: 1762350212000 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: 7569236501468631340 RawX2: 30064773219 } Partitions { }
2025-11-05T13:43:31.960219Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.960639Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.960655Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARING
2025-11-05T13:43:31.960657Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PREPARING
2025-11-05T13:43:31.960660Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PREPARING to PREPARED
2025-11-05T13:43:31.961473Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037894 TxId: 281474976715672
2025-11-05T13:43:31.961495Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236522943469015:2832], now have 1 active actors on pipe
2025-11-05T13:43:31.961515Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976715672 AckTo { RawX1: 0 RawX2: 0 } } Step: 1762350212007 MediatorID: 72057594046382081 TabletID: 72075186224037894
2025-11-05T13:43:31.961523Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PREPARED
2025-11-05T13:43:31.961525Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PREPARED
2025-11-05T13:43:31.961528Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PREPARED to PLANNING
2025-11-05T13:43:31.961533Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] PlanStep 1762350212007, PlanTxId 281474976715672
2025-11-05T13:43:31.961537Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:31.961609Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: PLANNED MinStep: 1762350212000 MaxStep: 18446744073709551615 Step: 1762350212007 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: 7569236501468631340 RawX2: 30064773219 } Partitions { }
2025-11-05T13:43:31.961635Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.961888Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.961900Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state PLANNING
2025-11-05T13:43:31.961902Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State PLANNING
2025-11-05T13:43:31.961908Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PLANNING to PLANNED
2025-11-05T13:43:31.961912Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxQueue.size 1
2025-11-05T13:43:31.961915Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] New ExecStep 1762350212007, ExecTxId 281474976715672
2025-11-05T13:43:31.962043Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from PLANNED to CALCULATING
2025-11-05T13:43:31.962057Z node 7 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:31.962067Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-11-05T13:43:31.962136Z node 7 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:31.962204Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] bootstrapping 0 [7:7569236522943469022:2452]
2025-11-05T13:43:31.968514Z node 7 :PERSQUEUE DEBUG: [topic_A:0:Initializer] Initializing completed.
2025-11-05T13:43:31.968535Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: 0, State: StateInit] init complete for topic 'topic_A' partition 0 generation 1 [7:7569236522943469022:2452]
2025-11-05T13:43:31.968543Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateInit] SYNC INIT topic topic_A partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:31.968630Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-11-05T13:43:31.968637Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.968672Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.968679Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:31.968682Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.968684Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.968686Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still pending for come commits
2025-11-05T13:43:31.968695Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:31.968772Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvProposePartitionConfigResult Step 1762350212007, TxId 281474976715672, Partition 0
2025-11-05T13:43:31.968776Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] Handle TEvProposePartitionConfigResult
2025-11-05T13:43:31.968779Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] Partition responses 1/1
2025-11-05T13:43:31.968783Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATING
2025-11-05T13:43:31.968785Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State CALCULATING
2025-11-05T13:43:31.968789Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State CALCULATING FrontTxId 281474976715672
2025-11-05T13:43:31.968794Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:43:31.968800Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from CALCULATING to CALCULATED
2025-11-05T13:43:31.968806Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:31.968926Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: CALCULATED MinStep: 1762350212000 MaxStep: 18446744073709551615 Step: 1762350212007 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: 7569236501468631340 RawX2: 30064773219 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:31.968957Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.969605Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.969612Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state CALCULATED
2025-11-05T13:43:31.969614Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State CALCULATED
2025-11-05T13:43:31.969616Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State CALCULATED FrontTxId 281474976715672
2025-11-05T13:43:31.969618Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from CALCULATED to WAIT_RS
2025-11-05T13:43:31.969633Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-11-05T13:43:31.969637Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveParticipantsDecision 1
2025-11-05T13:43:31.969648Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from WAIT_RS to EXECUTING
2025-11-05T13:43:31.969651Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 0, Expected 1
2025-11-05T13:43:31.969660Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1762350212007, TxId 281474976715672
2025-11-05T13:43:31.969664Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.969666Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.969700Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.969736Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:31.970057Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTxCommitDone Step 1762350212007, TxId 281474976715672, Partition 0
2025-11-05T13:43:31.970066Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTING
2025-11-05T13:43:31.970068Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State EXECUTING
2025-11-05T13:43:31.970069Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:31.970070Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State EXECUTING FrontTxId 281474976715672
2025-11-05T13:43:31.970073Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Received 1, Expected 1
2025-11-05T13:43:31.970076Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.970077Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.970079Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId: 281474976715672 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-11-05T13:43:31.970083Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] complete TxId 281474976715672
2025-11-05T13:43:31.970153Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Apply new config PartitionConfig { MaxCountInPartition: 2147483647 LifetimeSeconds: 3600 SourceIdLifetimeSeconds: 1382400 WriteSpeedInBytesPerSecond: 1048576 BurstSize: 1048576 TotalPartitions: 1 ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } ExplicitChannelProfiles { PoolKind: "test" } SourceIdMaxCounts: 6000000 } PartitionIds: 0 TopicName: "topic_A" Version: 0 RequireAuthWrite: true RequireAuthRead: true FormatVersion: 0 Codecs { } TopicPath: "/Root/topic_A" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "test-consumer" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } ServiceType: "data-streams" Version: 0 Generation: 0 }
2025-11-05T13:43:31.970174Z node 7 :PERSQUEUE NOTICE: [PQ: 72075186224037894] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-11-05T13:43:31.970184Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] delete partitions for TxId 281474976715672
2025-11-05T13:43:31.970186Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from EXECUTING to EXECUTED
2025-11-05T13:43:31.970190Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] write key for TxId 281474976715672
2025-11-05T13:43:31.970254Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] save tx TxId: 281474976715672 State: EXECUTED MinStep: 1762350212000 MaxStep: 18446744073709551615 Step: 1762350212007 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: 7569236501468631340 RawX2: 30064773219 } Partitions { Partition { PartitionId: 0 } }
2025-11-05T13:43:31.970285Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.971091Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037893][test-topic] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-11-05T13:43:31.971109Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037895
2025-11-05T13:43:31.971145Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.971148Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state EXECUTED
2025-11-05T13:43:31.971149Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State EXECUTED
2025-11-05T13:43:31.971152Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672 State EXECUTED FrontTxId 281474976715672
2025-11-05T13:43:31.971155Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TPersQueue::SendEvReadSetAckToSenders
2025-11-05T13:43:31.971158Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from EXECUTED to WAIT_RS_ACKS
2025-11-05T13:43:31.971161Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] PredicateAcks: 0/0
2025-11-05T13:43:31.971164Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-11-05T13:43:31.971166Z node 7 :PQ_TX DEBUG: [TxId: 281474976715672] PredicateAcks: 0/0
2025-11-05T13:43:31.971168Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] add an TxId 281474976715672 to the list for deletion
2025-11-05T13:43:31.971172Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715672 moved from WAIT_RS_ACKS to DELETING
2025-11-05T13:43:31.971176Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] delete key for TxId 281474976715672
2025-11-05T13:43:31.971184Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:31.971783Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-11-05T13:43:31.971795Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Registered with mediator time cast
2025-11-05T13:43:31.971822Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:31.971825Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Try execute txs with state DELETING
2025-11-05T13:43:31.971826Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxId 281474976715672, State DELETING
2025-11-05T13:43:31.971830Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] delete TxId 281474976715672
2025-11-05T13:43:31.975786Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: try to update token
2025-11-05T13:43:31.976033Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session: Do CDS request
2025-11-05T13:43:31.976039Z :INFO: [/Root] MessageGroupId [src] SessionId [] Start write session. Will connect to endpoint: localhost:7604
2025-11-05T13:43:31.979022Z :DEBUG: [/Root] MessageGroupId [src] SessionId [] Write session: send init request: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:43:31.979247Z node 7 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:31.979262Z node 7 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2025-11-05T13:43:31.979411Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic_A" message_group_id: "src" }
2025-11-05T13:43:31.979434Z node 7 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "topic_A" message_group_id: "src" from ipv6:[::1]:36086
2025-11-05T13:43:31.979439Z node 7 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36086 proto=v1  topic=topic_A durationSec=0
2025-11-05T13:43:31.979444Z node 7 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:31.980176Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2025-11-05T13:43:31.980211Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:31.980217Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:31.980219Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:31.980231Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [7:7569236522943469058:2460] (SourceId=src, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:31.980235Z node 7 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-11-05T13:43:31.980365Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 7, Generation: 1
2025-11-05T13:43:31.980387Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236522943469061:2460], now have 1 active actors on pipe
2025-11-05T13:43:31.980395Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:31.980401Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:31.980439Z node 7 :PERSQUEUE INFO: new Cookie src|27a8e39d-439f1b64-3a63c737-cc054d10_0 generated for partition 0 topic 'topic_A' owner src
2025-11-05T13:43:31.980456Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.980466Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.980478Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:31.980495Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:31.980520Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:31.980560Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:31.980563Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:31.980576Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:31.980596Z node 7 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: src|27a8e39d-439f1b64-3a63c737-cc054d10_0
2025-11-05T13:43:31.980854Z :INFO: [/Root] MessageGroupId [src] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350211980 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:31.980880Z :INFO: [/Root] MessageGroupId [src] SessionId [] Write session established. Init response: session_id: "src|27a8e39d-439f1b64-3a63c737-cc054d10_0" topic: "topic_A"
2025-11-05T13:43:31.981534Z :INFO: [/Root] MessageGroupId [src] SessionId [src|27a8e39d-439f1b64-3a63c737-cc054d10_0] Write session: close. Timeout = 0 ms
2025-11-05T13:43:31.981544Z :INFO: [/Root] MessageGroupId [src] SessionId [src|27a8e39d-439f1b64-3a63c737-cc054d10_0] Write session will now close
2025-11-05T13:43:31.981550Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|27a8e39d-439f1b64-3a63c737-cc054d10_0] Write session: aborting
2025-11-05T13:43:31.981697Z :INFO: [/Root] MessageGroupId [src] SessionId [src|27a8e39d-439f1b64-3a63c737-cc054d10_0] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:31.981702Z :DEBUG: [/Root] MessageGroupId [src] SessionId [src|27a8e39d-439f1b64-3a63c737-cc054d10_0] Write session: destroy
2025-11-05T13:43:31.981941Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: src|27a8e39d-439f1b64-3a63c737-cc054d10_0 grpc read done: success: 0 data: 
2025-11-05T13:43:31.981953Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|27a8e39d-439f1b64-3a63c737-cc054d10_0 grpc read failed
2025-11-05T13:43:31.981961Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|27a8e39d-439f1b64-3a63c737-cc054d10_0 grpc closed
2025-11-05T13:43:31.981964Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: src|27a8e39d-439f1b64-3a63c737-cc054d10_0 is DEAD
2025-11-05T13:43:31.982202Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:31.982639Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [7:7569236522943469061:2460] destroyed
2025-11-05T13:43:31.982661Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:31.982669Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:31.982672Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.001745Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Write session: try to update token
2025-11-05T13:43:32.001883Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:43:32.001894Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_A partition_id=0
2025-11-05T13:43:32.005470Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:43:32.006276Z node 7 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:43:32.006327Z node 7 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_A"
include_location: true
2025-11-05T13:43:32.006339Z node 7 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[7:7569236527238436366:2466]: Bootstrap
2025-11-05T13:43:32.006818Z node 7 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [7:7569236527238436366:2466]: Request location
2025-11-05T13:43:32.007583Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436375:2467] connected; active server actors: 1
2025-11-05T13:43:32.007672Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] addPartitionToResponse tabletId 72075186224037894, partitionId 0, NodeId 7, Generation 1
2025-11-05T13:43:32.007679Z node 7 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [7:7569236527238436366:2466]: Got location
2025-11-05T13:43:32.008170Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436375:2467] disconnected; active server actors: 1
2025-11-05T13:43:32.008176Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436375:2467] disconnected no session
2025-11-05T13:43:32.009732Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 7
    generation: 1
  }
}
2025-11-05T13:43:32.009747Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=7 pl_generation=1
2025-11-05T13:43:32.009754Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 7 exists in the endpoint pool.
2025-11-05T13:43:32.009761Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=7 Generation=1
2025-11-05T13:43:32.009765Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 7
2025-11-05T13:43:32.010139Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:43:32.010171Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: send init request: init_request { path: "topic_A" producer_id: "test-message_group_id_1" partition_with_generation { generation: 1 } }
2025-11-05T13:43:32.010175Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:43:32.010260Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:32.010464Z node 7 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:32.010473Z node 7 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2025-11-05T13:43:32.013582Z node 7 :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_1" partition_with_generation { generation: 1 } }
2025-11-05T13:43:32.013646Z node 7 :PQ_WRITE_PROXY INFO: session request cookie: 3 path: "topic_A" producer_id: "test-message_group_id_1" partition_with_generation { generation: 1 } from ipv6:[::1]:36086
2025-11-05T13:43:32.013650Z node 7 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="topic server" ip=ipv6:[::1]:36086 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:32.013655Z node 7 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:32.013669Z node 7 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:43:32.014103Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2025-11-05T13:43:32.014162Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:32.014164Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:32.014165Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:32.014171Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [7:7569236527238436381:2469] (SourceId=test-message_group_id_1, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:32.014175Z node 7 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:43:32.014310Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 7, Generation: 1
2025-11-05T13:43:32.014333Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236527238436384:2469], now have 1 active actors on pipe
2025-11-05T13:43:32.014340Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.014345Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.014371Z node 7 :PERSQUEUE INFO: new Cookie test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 generated for partition 0 topic 'topic_A' owner test-message_group_id_1
2025-11-05T13:43:32.014385Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.014389Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.014400Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.014412Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:32.014438Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.014533Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.014542Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.014578Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.014628Z node 7 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0
2025-11-05T13:43:32.015901Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:32.015929Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350212015 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:32.015956Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0"
2025-11-05T13:43:32.015961Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0
2025-11-05T13:43:32.016162Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] OnWrite: seqNo=1, txId=01k9a448x1fqvap3kz7kg56nq7, WriteCount=1, AckCount=0
2025-11-05T13:43:32.016181Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:43:32.016229Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:32.016236Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:43:32.016556Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:32.016633Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP for a WriteId. SessionId: ydb://session/3?node_id=7&id=YzA4Mjk4OGQtNWViY2RlNTctZWRjNmI1NGUtY2MwY2NiYzQ= TxId: 01k9a448x1fqvap3kz7kg56nq7
2025-11-05T13:43:32.016908Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 7, Generation: 1
2025-11-05T13:43:32.016932Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236527238436387:2469], now have 1 active actors on pipe
2025-11-05T13:43:32.017028Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of the request to KQP for the WriteId. SessionId: ydb://session/3?node_id=7&id=YzA4Mjk4OGQtNWViY2RlNTctZWRjNmI1NGUtY2MwY2NiYzQ= TxId: 01k9a448x1fqvap3kz7kg56nq7 Status: SUCCESS
2025-11-05T13:43:32.017031Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) SessionId: ydb://session/3?node_id=7&id=YzA4Mjk4OGQtNWViY2RlNTctZWRjNmI1NGUtY2MwY2NiYzQ= TxId: 01k9a448x1fqvap3kz7kg56nq7 WriteId: {7, 281474976715673}
2025-11-05T13:43:32.017048Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.017051Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.017059Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] partition {0, {7, 281474976715673}, 100000} for WriteId {7, 281474976715673}
2025-11-05T13:43:32.017112Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvSubscribeLock for WriteId {7, 281474976715673}
2025-11-05T13:43:32.017137Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:32.017347Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715673 LockNode: 7 Status: STATUS_SUBSCRIBED
2025-11-05T13:43:32.017353Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {7, 281474976715673}, TxId (empty maybe), Status STATUS_UNSPECIFIED
2025-11-05T13:43:32.017355Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] subscribed WriteId {7, 281474976715673}
2025-11-05T13:43:32.017564Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:32.017713Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitConfigStep
2025-11-05T13:43:32.017770Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitInternalFieldsStep
2025-11-05T13:43:32.017817Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateInit] bootstrapping {0, {7, 281474976715673}, 100000} [7:7569236527238436393:2471]
2025-11-05T13:43:32.018054Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitDiskStatusStep
2025-11-05T13:43:32.018148Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitMetaStep
2025-11-05T13:43:32.018170Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitInfoRangeStep
2025-11-05T13:43:32.018204Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitDataRangeStep
2025-11-05T13:43:32.018218Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitDataStep
2025-11-05T13:43:32.018221Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Start initializing step TInitEndWriteTimestampStep
2025-11-05T13:43:32.018224Z node 7 :PERSQUEUE INFO: [topic_A:{0, {7, 281474976715673}, 100000}:TInitEndWriteTimestampStep] Initializing EndWriteTimestamp skipped because already initialized.
2025-11-05T13:43:32.018226Z node 7 :PERSQUEUE DEBUG: [topic_A:{0, {7, 281474976715673}, 100000}:Initializer] Initializing completed.
2025-11-05T13:43:32.018231Z node 7 :PERSQUEUE INFO: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateInit] init complete for topic 'topic_A' partition {0, {7, 281474976715673}, 100000} generation 1 [7:7569236527238436393:2471]
2025-11-05T13:43:32.018238Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateInit] SYNC INIT topic topic_A partitition {0, {7, 281474976715673}, 100000} so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-11-05T13:43:32.018242Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Process pending events. Count 0
2025-11-05T13:43:32.018246Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.018248Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.018314Z node 7 :PERSQUEUE INFO: new Cookie test-message_group_id_1|c21f64ba-aa7d2174-81153cd4-7cdfcd33_0 generated for partition {0, {7, 281474976715673}, 100000} topic 'topic_A' owner test-message_group_id_1
2025-11-05T13:43:32.018319Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.018322Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.018328Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.018337Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] TPartition::ReplyOwnerOk. Partition: {0, {7, 281474976715673}, 100000}
2025-11-05T13:43:32.018347Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.018357Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Start of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=7&id=YzA4Mjk4OGQtNWViY2RlNTctZWRjNmI1NGUtY2MwY2NiYzQ= TxId: 01k9a448x1fqvap3kz7kg56nq7
2025-11-05T13:43:32.018459Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) End of a request to KQP to save PartitionId. SessionId: ydb://session/3?node_id=7&id=YzA4Mjk4OGQtNWViY2RlNTctZWRjNmI1NGUtY2MwY2NiYzQ= TxId: 01k9a448x1fqvap3kz7kg56nq7 Status: SUCCESS
2025-11-05T13:43:32.018481Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.018484Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.018498Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.018532Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.018533Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.018552Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Reserve bytes in transaction. Partition: 0, WriteId: { NodeId: 7 KeyId: 281474976715673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:32.018560Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:43:32.018571Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:32.018596Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.018598Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.018606Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Write in transaction. Partition: 0, WriteId: { NodeId: 7 KeyId: 281474976715673 KafkaTransaction: false }, NeedSupportivePartition: 0
2025-11-05T13:43:32.018615Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id_1' SeqNo: 1 partNo : 0 messageNo: 1 size 16072 offset: -1
2025-11-05T13:43:32.018631Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.018636Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.018651Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {7, 281474976715673}, 100000} part blob processing sourceId '\0test-message_group_id_1' seqNo 1 partNo 0
2025-11-05T13:43:32.018682Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Topic 'topic_A' partition {0, {7, 281474976715673}, 100000} part blob complete sourceId '\0test-message_group_id_1' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 16163 count 1 nextOffset 1 batches 1
2025-11-05T13:43:32.018687Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.018720Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Add new write blob: topic 'topic_A' partition {0, {7, 281474976715673}, 100000} compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 D0000100000_00000000000000000000_00000_0000000001_00000| size 16151 WTime 1762350212017
2025-11-05T13:43:32.018741Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:32.018748Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 100000 offset 0 partNo 0 count 1 size 16151
2025-11-05T13:43:32.019059Z node 7 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 100000 offset 0 count 1 size 16151 actorID [7:7569236522943468995:2451]
2025-11-05T13:43:32.019114Z node 7 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 0 size 16151
2025-11-05T13:43:32.020687Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 16096 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:32.020716Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] TPartition::ReplyWrite. Partition: {0, {7, 281474976715673}, 100000}
2025-11-05T13:43:32.020738Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Answering for message sourceid: '\0test-message_group_id_1', Topic: 'topic_A', Partition: {0, {7, 281474976715673}, 100000}, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2025-11-05T13:43:32.020775Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.020784Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.020817Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-11-05T13:43:32.020847Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:32.021650Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:32.021703Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 1 written_in_tx { } } write_statistics { persisting_time { nanos: 3000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:43:32.021716Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=01k9a448x1fqvap3kz7kg56nq7, WriteCount=1, AckCount=1
2025-11-05T13:43:32.021999Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:43:32.022985Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236527238436409:2867], now have 1 active actors on pipe
2025-11-05T13:43:32.023050Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7569236527238436406 RawX2: 4503629692144032 } TxId: 281474976715674 Data { Operations { PartitionId: 0 Path: "/Root/topic_A" SupportivePartition: 100000 } Op: Commit SendingShards: 72075186224037894 ReceivingShards: 72075186224037894 Immediate: true WriteId { NodeId: 7 KeyId: 281474976715673 } }
2025-11-05T13:43:32.023065Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] PartitionId {0, {7, 281474976715673}, 100000} for WriteId {7, 281474976715673}
2025-11-05T13:43:32.023072Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] TxId 281474976715674 has WriteId {7, 281474976715673}
2025-11-05T13:43:32.023076Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] immediate transaction
2025-11-05T13:43:32.023087Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Send TEvGetWriteInfoRequest for TxId (empty maybe)
2025-11-05T13:43:32.023091Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.023095Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] The Tx (empty maybe) is waiting for TEvGetWriteInfoResponse
2025-11-05T13:43:32.023098Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Still preprocessing - waiting for something
2025-11-05T13:43:32.023104Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Handle TEvPQ::TEvGetWriteInfoRequest
2025-11-05T13:43:32.023122Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Send TEvPQ::TEvGetWriteInfoResponse
2025-11-05T13:43:32.023132Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Handle TEvPQ::TEvGetWriteInfoResponse
2025-11-05T13:43:32.023135Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Received TEvGetWriteInfoResponse for TxId (empty maybe)
2025-11-05T13:43:32.023138Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.023148Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.023154Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::CommitWriteOperations TxId: (empty maybe)
2025-11-05T13:43:32.023162Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] t.WriteInfo->BodyKeys.size=0, t.WriteInfo->BlobsFromHead.size=1
2025-11-05T13:43:32.023169Z node 7 :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:43:32.023196Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob processing sourceId '\0test-message_group_id_1' seqNo 1 partNo 0
2025-11-05T13:43:32.023230Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob complete sourceId '\0test-message_group_id_1' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 16163 count 1 nextOffset 1 batches 1
2025-11-05T13:43:32.023244Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] schedule TEvPersQueue::TEvProposeTransactionResult(COMPLETE), reason=
2025-11-05T13:43:32.023251Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.023303Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Add new write blob: topic 'topic_A' partition 0 compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 d0000000000_00000000000000000000_00000_0000000001_00000| size 16151 WTime 1762350212023
2025-11-05T13:43:32.023338Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:32.023346Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 0 offset 0 partNo 0 count 1 size 16151
2025-11-05T13:43:32.023813Z node 7 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 0 offset 0 count 1 size 16151 actorID [7:7569236522943468995:2451]
2025-11-05T13:43:32.023848Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 16096
2025-11-05T13:43:32.023868Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:32.023871Z node 7 :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:43:32.023875Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.023877Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.024134Z node 7 :PQ_TX INFO: [PQ: 72075186224037894] Handle TEvPQ::TEvTransactionCompleted WriteId {7, 281474976715673}
2025-11-05T13:43:32.024138Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvPQ::TEvDeletePartition to partition {0, {7, 281474976715673}, 100000}
2025-11-05T13:43:32.024157Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Handle TEvPQ::TEvDeletePartition
2025-11-05T13:43:32.024176Z node 7 :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 1 max time lag 0ms effective offset 0
2025-11-05T13:43:32.024179Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] read cookie 0 added 0 blobs, size 0 count 0 last offset 0, current partition end offset: 1
2025-11-05T13:43:32.024186Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Reading cookie 0. All data is from uncompacted head.
2025-11-05T13:43:32.024191Z node 7 :PERSQUEUE DEBUG: FormAnswer for 0 blobs
2025-11-05T13:43:32.024207Z node 7 :PERSQUEUE DEBUG: Topic 'topic_A' partition 0 user test-consumer readTimeStamp done, result 1762350212017 queuesize 0 startOffset 0
2025-11-05T13:43:32.024214Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:32.024217Z node 7 :PERSQUEUE DEBUG: CacheProxy. Delete blobs from D0000100000(+) to D0000100001(-)
2025-11-05T13:43:32.024353Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvLongTxService::TEvLockStatus LockId: 281474976715673 LockNode: 7 Status: STATUS_NOT_FOUND
2025-11-05T13:43:32.024357Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] TxWriteInfo: WriteId {7, 281474976715673}, TxId 281474976715674, Status STATUS_SUBSCRIBED
2025-11-05T13:43:32.024359Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] there is already a transaction TxId 281474976715674 for WriteId {7, 281474976715673}
2025-11-05T13:43:32.024375Z node 7 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 0 offset 0 partno 0 count 1 parts 0 size 16151
2025-11-05T13:43:32.024664Z node 7 :PERSQUEUE DEBUG: Deleting head blob in L1. Partition 100000 offset 0 count 1 actorID [7:7569236522943468995:2451]
2025-11-05T13:43:32.024705Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.024708Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: {0, {7, 281474976715673}, 100000}, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.024744Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] Handle TEvPQ::TEvDeletePartitionDone {0, {7, 281474976715673}, 100000}
2025-11-05T13:43:32.024748Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] DeletePartition {0, {7, 281474976715673}, 100000}
2025-11-05T13:43:32.024754Z node 7 :PQ_TX DEBUG: [PQ: 72075186224037894] send TEvUnsubscribeLock for WriteId {7, 281474976715673}
2025-11-05T13:43:32.024758Z node 7 :PQ_TX WARN: [PQ: 72075186224037894] Unknown transaction 281474976715674
2025-11-05T13:43:32.024770Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-11-05T13:43:32.024877Z node 7 :PERSQUEUE DEBUG: PQ Cache (L2). Removed. Tablet '72075186224037894' partition 100000 offset 0 partno 0 count 1 parts 0
2025-11-05T13:43:32.025013Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-11-05T13:43:32.025595Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Write session: try to update token
2025-11-05T13:43:32.025819Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Get partition location async, partition 0, delay 0.000000s
2025-11-05T13:43:32.025829Z :TRACE: [/Root] TRACE_EVENT DescribePartitionRequest  path=/Root/topic_A partition_id=0
2025-11-05T13:43:32.025851Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0]  Getting partition location, partition 0
2025-11-05T13:43:32.026376Z node 7 :PQ_READ_PROXY DEBUG: new Describe partition request
2025-11-05T13:43:32.026404Z node 7 :PQ_READ_PROXY DEBUG: TDescribePartitionActor for request path: "/Root/topic_A"
include_location: true
2025-11-05T13:43:32.026413Z node 7 :PQ_READ_PROXY DEBUG: TDescribePartitionActor[7:7569236527238436420:2475]: Bootstrap
2025-11-05T13:43:32.026650Z node 7 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [7:7569236527238436420:2475]: Request location
2025-11-05T13:43:32.026734Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436422:2476] connected; active server actors: 1
2025-11-05T13:43:32.026745Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] addPartitionToResponse tabletId 72075186224037894, partitionId 0, NodeId 7, Generation 1
2025-11-05T13:43:32.026749Z node 7 :PQ_READ_PROXY DEBUG: DescribeTopicImpl [7:7569236527238436420:2475]: Got location
2025-11-05T13:43:32.026896Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436422:2476] disconnected; active server actors: 1
2025-11-05T13:43:32.026899Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436422:2476] disconnected no session
2025-11-05T13:43:32.027769Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] Got PartitionLocation response. Status SUCCESS, proto:
partition {
  active: true
  partition_location {
    node_id: 7
    generation: 1
  }
}
2025-11-05T13:43:32.027786Z :TRACE: [/Root] TRACE_EVENT DescribePartitionResponse  partition_id=0 active=1 pl_node_id=7 pl_generation=1
2025-11-05T13:43:32.027796Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [0] GetPreferredEndpoint: partitionId 0, partitionNodeId 7 exists in the endpoint pool.
2025-11-05T13:43:32.027804Z :TRACE: [/Root] TRACE_EVENT PreferredPartitionLocation  Endpoint= NodeId=7 Generation=1
2025-11-05T13:43:32.027809Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Start write session. Will connect to nodeId: 7
2025-11-05T13:43:32.028106Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: direct write to partition: 0, generation 1
2025-11-05T13:43:32.028139Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: send init request: init_request { path: "topic_A" producer_id: "test-message_group_id_2" partition_with_generation { generation: 1 } }
2025-11-05T13:43:32.028143Z :TRACE: [/Root] TRACE_EVENT InitRequest  pwg_partition_id=0 pwg_generation=1
2025-11-05T13:43:32.028246Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: OnWriteDone gRpcStatusCode: 0
2025-11-05T13:43:32.028416Z node 7 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-11-05T13:43:32.028425Z node 7 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2025-11-05T13:43:32.028541Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { path: "topic_A" producer_id: "test-message_group_id_2" partition_with_generation { generation: 1 } }
2025-11-05T13:43:32.028567Z node 7 :PQ_WRITE_PROXY INFO: session request cookie: 4 path: "topic_A" producer_id: "test-message_group_id_2" partition_with_generation { generation: 1 } from ipv6:[::1]:36086
2025-11-05T13:43:32.028571Z node 7 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="topic server" ip=ipv6:[::1]:36086 proto=topic  topic=topic_A durationSec=0
2025-11-05T13:43:32.028574Z node 7 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:32.028580Z node 7 :PQ_WRITE_PROXY INFO: session to partition: 0, generation: 1
2025-11-05T13:43:32.028856Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2025-11-05T13:43:32.028900Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint64; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `//Root/.metadata/TopicPartitionsMapping` WHERE Hash == $Hash AND Topic == $Topic AND ProducerId == $SourceId;
2025-11-05T13:43:32.028901Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64; DECLARE $SeqNo AS Uint64;
UPSERT INTO `//Root/.metadata/TopicPartitionsMapping` (Hash, Topic, ProducerId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-11-05T13:43:32.028903Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint64; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `//Root/.metadata/TopicPartitionsMapping` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND ProducerId = $SourceId AND Partition = $Partition;
2025-11-05T13:43:32.028911Z node 7 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [7:7569236527238436427:2478] (SourceId=test-message_group_id_2, PreferedPartition=0) ReplyResult: Partition=0, SeqNo=0
2025-11-05T13:43:32.028914Z node 7 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 0 expectedGeneration: 1
2025-11-05T13:43:32.029027Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037894, NodeId 7, Generation: 1
2025-11-05T13:43:32.029037Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236527238436430:2478], now have 1 active actors on pipe
2025-11-05T13:43:32.029045Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.029049Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.029073Z node 7 :PERSQUEUE INFO: new Cookie test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 generated for partition 0 topic 'topic_A' owner test-message_group_id_2
2025-11-05T13:43:32.029080Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.029084Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.029094Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.029104Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-11-05T13:43:32.029118Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.029237Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.029240Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.029259Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.029273Z node 7 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 0 MaxSeqNo: 0 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0
2025-11-05T13:43:32.056952Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.056960Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.029605Z :DEBUG: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:32.062173Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1762350212062 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:32.062211Z :INFO: [/Root]  TraceId []  SessionId []  PartitionId [0]  Generation [1] Write session established. Init response: session_id: "test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0"
2025-11-05T13:43:32.062216Z :TRACE: [/Root] TRACE_EVENT InitResponse  partition_id=0 session_id=test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0
2025-11-05T13:43:32.065502Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write 1 messages with Id from 1 to 1
2025-11-05T13:43:32.065540Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: try to update token
2025-11-05T13:43:32.065548Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Send 1 message(s) (0 left), first sequence number is 1
2025-11-05T13:43:32.065762Z :INFO: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Starting read session
2025-11-05T13:43:32.065767Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Starting single session
2025-11-05T13:43:32.066026Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] In Reconnect, ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-11-05T13:43:32.066031Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] New values: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-11-05T13:43:32.066036Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Reconnecting session to cluster  in 0.000000s
2025-11-05T13:43:32.066142Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-11-05T13:43:32.066287Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Successfully connected. Initializing session
2025-11-05T13:43:32.066298Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-11-05T13:43:32.066567Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.066581Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.066685Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2025-11-05T13:43:32.066713Z node 7 :PQ_READ_PROXY DEBUG: new grpc connection
2025-11-05T13:43:32.066715Z node 7 :PQ_READ_PROXY DEBUG: new session created cookie 1
2025-11-05T13:43:32.066717Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:32.066825Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.066833Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.066852Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message topic: topic_A partition: 0 SourceId: '\0test-message_group_id_2' SeqNo: 1 partNo : 0 messageNo: 1 size 20073 offset: -1
2025-11-05T13:43:32.066873Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { path: "topic_A" partition_ids: 0 } consumer: "test-consumer" } }
2025-11-05T13:43:32.066889Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.066898Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.066920Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 read init: from# ipv6:[::1]:36086, request# { init_request { topics_read_settings { path: "topic_A" partition_ids: 0 } consumer: "test-consumer" } }
2025-11-05T13:43:32.066932Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob processing sourceId '\0test-message_group_id_2' seqNo 1 partNo 0
2025-11-05T13:43:32.066973Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 part blob complete sourceId '\0test-message_group_id_2' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 20164 count 1 nextOffset 2 batches 1
2025-11-05T13:43:32.066978Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 auth for : test-consumer
2025-11-05T13:43:32.066981Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.067054Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Add new write blob: topic 'topic_A' partition 0 compactOffset 1,1 HeadOffset 0 endOffset 1 curOffset 2 d0000000000_00000000000000000001_00000_0000000001_00000| size 20154 WTime 1762350212066
2025-11-05T13:43:32.067100Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:32.067110Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough blob. Partition 0 offset 1 partNo 0 count 1 size 20154
2025-11-05T13:43:32.067233Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 Handle describe topics response
2025-11-05T13:43:32.067261Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 auth is DEAD
2025-11-05T13:43:32.067281Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 auth ok: topics# 1, initDone# 0
2025-11-05T13:43:32.067595Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 register session: topic# /Root/topic_A
2025-11-05T13:43:32.068027Z node 7 :PERSQUEUE DEBUG: Caching head blob in L1. Partition 0 offset 1 count 1 size 20154 actorID [7:7569236522943468995:2451]
2025-11-05T13:43:32.068059Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 20097 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:32.068068Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::ReplyWrite. Partition: 0
2025-11-05T13:43:32.068079Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Answering for message sourceid: '\0test-message_group_id_2', Topic: 'topic_A', Partition: 0, SeqNo: 1, partNo: 0, Offset: 1 is stored on disk
2025-11-05T13:43:32.068110Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.068112Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.068125Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2025-11-05T13:43:32.068142Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-11-05T13:43:32.068282Z node 7 :PERSQUEUE DEBUG: PQ Cache (L2). Adding blob. Tablet '72075186224037894' partition 0 offset 1 partno 0 count 1 parts 0 size 20154
2025-11-05T13:43:32.068377Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436437:2481] connected; active server actors: 1
2025-11-05T13:43:32.068446Z node 7 :PERSQUEUE_READ_BALANCER NOTICE: [72075186224037895][topic_A] consumer "test-consumer" register session for pipe [7:7569236527238436437:2481] session test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:32.068460Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer register readable partition 0
2025-11-05T13:43:32.068471Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer family created family=1 (Status=Free, Partitions=[0])
2025-11-05T13:43:32.068479Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] consumer test-consumer register reading session ReadingSession "test-consumer_7_1_1643132248296154647_v1" (Sender=[7:7569236527238436433:2481], Pipe=[7:7569236527238436437:2481], Partitions=[0], ActiveFamilyCount=0)
2025-11-05T13:43:32.068484Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer rebalancing was scheduled
2025-11-05T13:43:32.068495Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer balancing. Sessions=1, Families=1, UnradableFamilies=1 [1 (0), ], RequireBalancing=1 [1 (0), ]
2025-11-05T13:43:32.068503Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer balancing family=1 (Status=Free, Partitions=[0], SpecialSessions=1) for ReadingSession "test-consumer_7_1_1643132248296154647_v1" (Sender=[7:7569236527238436433:2481], Pipe=[7:7569236527238436437:2481], Partitions=[0], ActiveFamilyCount=0)
2025-11-05T13:43:32.068513Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] consumer test-consumer family 1 status Active partitions [0] session "test-consumer_7_1_1643132248296154647_v1" sender [7:7569236527238436433:2481] lock partition 0 for ReadingSession "test-consumer_7_1_1643132248296154647_v1" (Sender=[7:7569236527238436433:2481], Pipe=[7:7569236527238436437:2481], Partitions=[0], ActiveFamilyCount=1) generation 1 step 1
2025-11-05T13:43:32.068524Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer skip balancing family=1 (Status=Active, Partitions=[0], SpecialSessions=1, Session=ReadingSession "test-consumer_7_1_1643132248296154647_v1" (Sender=[7:7569236527238436433:2481], Pipe=[7:7569236527238436437:2481], Partitions=[0], ActiveFamilyCount=1)) because it is considered a session that does not read anything else.
2025-11-05T13:43:32.068527Z node 7 :PERSQUEUE_READ_BALANCER DEBUG: [72075186224037895][topic_A] consumer test-consumer balancing duration: 0.000029s
2025-11-05T13:43:32.068669Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 assign: record# { Partition: 0 TabletId: 72075186224037894 Topic: "topic_A" Generation: 1 Step: 1 Session: "test-consumer_7_1_1643132248296154647_v1" ClientId: "test-consumer" PipeClient { RawX1: 7569236527238436437 RawX2: 4503629692144049 } Path: "/Root/topic_A" }
2025-11-05T13:43:32.068684Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 INITING TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1)
2025-11-05T13:43:32.069113Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.069118Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.069222Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037894 Generation: 1, pipe: [7:7569236527238436441:2484]
2025-11-05T13:43:32.069235Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server connected, pipe [7:7569236527238436441:2484], now have 1 active actors on pipe
2025-11-05T13:43:32.069365Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.069373Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.069382Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Created session test-consumer_7_1_1643132248296154647_v1 on pipe: [7:7569236527238436441:2484]
2025-11-05T13:43:32.069397Z node 7 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: test-consumer_7_1_1643132248296154647_v1:1 with generation 1
2025-11-05T13:43:32.069410Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.069414Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.069460Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer session is set to 0 (startOffset 0) session test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:32.069464Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.069487Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:32.070666Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:32.070677Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.070680Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.070697Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-11-05T13:43:32.070743Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 2 WriteTimestampMS: 1762350212017 CreateTimestampMS: 1762350212016 SizeLag: 36305 WriteTimestampEstimateMS: 1762350212066 ClientHasAnyCommits: false } Cookie: 18446744073709551615 }
2025-11-05T13:43:32.070754Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 INIT DONE TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) EndOffset 2 readOffset 0 committedOffset 0
2025-11-05T13:43:32.070775Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 sending to client partition status
2025-11-05T13:43:32.073665Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: OnReadDone gRpcStatusCode: 0
2025-11-05T13:43:32.073714Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session got write response: acks { seq_no: 1 written { offset: 1 } } write_statistics { persisting_time { nanos: 1000000 } min_queue_wait_time { } max_queue_wait_time { } partition_quota_wait_time { } topic_quota_wait_time { } }
2025-11-05T13:43:32.073719Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] OnAck: seqNo=1, txId=?
2025-11-05T13:43:32.073723Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: acknoledged message 1
2025-11-05T13:43:32.073793Z :INFO: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Server session id: test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:32.073800Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] In ContinueReadingDataImpl, ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2025-11-05T13:43:32.073832Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] After sending read request: ReadSizeBudget = 0, ReadSizeServerDelta = 52428800
2025-11-05T13:43:32.073898Z :INFO: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Confirm partition stream create. Partition stream id: 1. Cluster: "-". Topic: "topic_A". Partition: 0. Read offset: (NULL)
2025-11-05T13:43:32.074081Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc read done: success# 1, data# { read_request { bytes_size: 52428800 } }
2025-11-05T13:43:32.074150Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 got read request: guid# c94731c5-a1849a0a-4ab7ee53-d53a18e9
2025-11-05T13:43:32.077547Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 1 } }
2025-11-05T13:43:32.077647Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 got StartRead from client: partition# TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1), readOffset# 0, commitOffset# (empty maybe)
2025-11-05T13:43:32.077671Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 Start reading TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) EndOffset 2 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-11-05T13:43:32.077675Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) ready for read with readOffset 0 endOffset 2
2025-11-05T13:43:32.077693Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 partition ready for read: partition# TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1), readOffset# 0, endOffset# 2, WTime# 1762350212017, sizeLag# 36305
2025-11-05T13:43:32.077696Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1TEvPartitionReady. Aval parts: 1
2025-11-05T13:43:32.077712Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 performing read request: guid# b97a3062-603a4e45-cc331484-de302b19, from# TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1), count# 2, size# 43566, partitionsAsked# 1, maxTimeLag# 0ms
2025-11-05T13:43:32.077740Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 READ FROM TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1)maxCount 2 maxSize 43566 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 2 ClientCommitOffset 0 committedOffset 0 Guid b97a3062-603a4e45-cc331484-de302b19
2025-11-05T13:43:32.077906Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.077920Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.077970Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] read cookie 1 Topic 'topic_A' partition 0 user test-consumer offset 0 count 2 size 43566 endOffset 2 max time lag 0ms effective offset 0
2025-11-05T13:43:32.077982Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] read cookie 1 added 0 blobs, size 0 count 0 last offset 0, current partition end offset: 2
2025-11-05T13:43:32.078006Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Reading cookie 1. All data is from uncompacted head.
2025-11-05T13:43:32.078018Z node 7 :PERSQUEUE DEBUG: FormAnswer for 0 blobs
2025-11-05T13:43:32.078063Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-11-05T13:43:32.078139Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 2 Result { Offset: 0 Data: "... 16072 bytes ..." SourceId: "\000test-message_group_id_1" SeqNo: 1 WriteTimestampMS: 1762350212017 CreateTimestampMS: 1762350212016 UncompressedSize: 16000 PartitionKey: "" ExplicitHash: "" } Result { Offset: 1 Data: "... 20073 bytes ..." SourceId: "\000test-message_group_id_2" SeqNo: 1 WriteTimestampMS: 1762350212066 CreateTimestampMS: 1762350212065 UncompressedSize: 20000 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 42 RealReadOffset: 1 WaitQuotaTimeMs: 0 EndOffset: 2 StartOffset: 0 } Cookie: 0 }
2025-11-05T13:43:32.078201Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) wait data in partition inited, cookie 1 from offset2
2025-11-05T13:43:32.078214Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 after read state TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) EndOffset 2 ReadOffset 2 ReadGuid b97a3062-603a4e45-cc331484-de302b19 has messages 1
2025-11-05T13:43:32.078231Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 read done: guid# b97a3062-603a4e45-cc331484-de302b19, partition# TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1), size# 36386
2025-11-05T13:43:32.078239Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 response to read: guid# b97a3062-603a4e45-cc331484-de302b19
2025-11-05T13:43:32.078354Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 Process answer. Aval parts: 0
2025-11-05T13:43:32.081550Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Got ReadResponse, serverBytesSize = 36386, now ReadSizeBudget = 0, ReadSizeServerDelta = 52392414
2025-11-05T13:43:32.081588Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] In ContinueReadingDataImpl, ReadSizeBudget = 0, ReadSizeServerDelta = 52392414
2025-11-05T13:43:32.081640Z :DEBUG: [/Root] Decompression task done. Partition/PartitionSessionId: 1 (0-1)
2025-11-05T13:43:32.081648Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Returning serverBytesSize = 36386 to budget
2025-11-05T13:43:32.081652Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] In ContinueReadingDataImpl, ReadSizeBudget = 36386, ReadSizeServerDelta = 52392414
2025-11-05T13:43:32.081731Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] After sending read request: ReadSizeBudget = 0, ReadSizeServerDelta = 52428800
2025-11-05T13:43:32.081827Z :DEBUG: [/Root] Take Data. Partition 0. Read: {0, 0} (0-0)
2025-11-05T13:43:32.081842Z :DEBUG: [/Root] Take Data. Partition 0. Read: {1, 0} (1-1)
2025-11-05T13:43:32.081853Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] The application data is transferred to the client. Number of messages 2, size 36000 bytes
2025-11-05T13:43:32.081860Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Returning serverBytesSize = 0 to budget
0 2
2025-11-05T13:43:32.081878Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Commit offsets [0, 2). Partition stream id: 1
2025-11-05T13:43:32.081945Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc read done: success# 1, data# { read_request { bytes_size: 36386 } }
2025-11-05T13:43:32.081992Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 got read request: guid# c733b37d-2c59af9f-9c9acc8d-d6ba953d
2025-11-05T13:43:32.082135Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc read done: success# 1, data# { commit_offset_request { commit_offsets { partition_session_id: 1 offsets { end: 2 } } } }
2025-11-05T13:43:32.082189Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) committing to position 2 prev 0 end 2 by cookie 2
2025-11-05T13:43:32.084439Z node 7 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'topic_A' requestId: <none>
2025-11-05T13:43:32.084462Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] got client message batch for topic 'topic_A' partition 0
2025-11-05T13:43:32.084497Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.084505Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.084526Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer offset is set to 2 (startOffset 0) session test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:32.084530Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.084570Z node 7 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-11-05T13:43:32.086677Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Topic 'topic_A' partition 0 user test-consumer readTimeStamp for offset 2 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-11-05T13:43:32.086709Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-11-05T13:43:32.086718Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.086722Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.086748Z node 7 :PERSQUEUE DEBUG: Answer ok topic: 'topic_A' partition: 0 messageNo: 0  requestId: <none> cookie: 2
2025-11-05T13:43:32.086792Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) initDone 1 event { Cookie: 2 }
2025-11-05T13:43:32.086800Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 TopicId: Topic /Root/topic_A in database: Root, partition 0(assignId:1) commit done to position 2 endOffset 2 with cookie 2
2025-11-05T13:43:32.086814Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 replying for commits: assignId# 1, from# 2, to# 2, offset# 2
2025-11-05T13:43:32.089703Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Committed response: { partitions_committed_offsets { partition_session_id: 1 committed_offset: 2 } }
2025-11-05T13:43:32.157889Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.157909Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.169061Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.169085Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.258132Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.258151Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.269399Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.269413Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.358425Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.358444Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.369743Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.369761Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.461498Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.461517Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.473590Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.473607Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.561733Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.561750Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.574025Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.574044Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.671655Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.671672Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.674350Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.674367Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.772162Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.772175Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.777796Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.777809Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.873030Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.873045Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.878430Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.878446Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.973730Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.973749Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:32.981481Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:32.981500Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.015442Z node 7 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:33.015863Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 describe result for acl check
2025-11-05T13:43:33.029872Z node 7 :PQ_WRITE_PROXY INFO: init check schema
2025-11-05T13:43:33.030593Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 describe result for acl check
2025-11-05T13:43:33.069326Z :INFO: [/Root] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): -:topic_A:0:1:1:2
2025-11-05T13:43:33.069356Z :INFO: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1003 BytesRead: 36000 MessagesRead: 2 BytesReadCompressed: 36000 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:33.069630Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 checking auth because of timeout
2025-11-05T13:43:33.069668Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 auth for : test-consumer
2025-11-05T13:43:33.070043Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 Handle describe topics response
2025-11-05T13:43:33.070067Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 auth is DEAD
2025-11-05T13:43:33.070097Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 auth ok: topics# 1, initDone# 1
2025-11-05T13:43:33.073786Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.073798Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.081814Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.081828Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.177837Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.177868Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.181841Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.181857Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.274971Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.274990Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.284695Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.284716Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.375694Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.375706Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.385253Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.385272Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.481514Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.481537Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.488584Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.488602Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.585482Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.585501Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.589815Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.589831Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.685606Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.685624Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.690202Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.690226Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.785913Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.785931Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.790555Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.790573Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.886721Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.886738Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.891424Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.891446Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.987138Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.987164Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:33.991772Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:33.991787Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.070045Z :INFO: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Closing read session. Close timeout: 0.000000s
2025-11-05T13:43:34.070064Z :INFO: [/Root] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): -:topic_A:0:1:1:2
2025-11-05T13:43:34.070079Z :INFO: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Counters: { Errors: 0 CurrentSessionLifetimeMs: 2004 BytesRead: 36000 MessagesRead: 2 BytesReadCompressed: 36000 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-11-05T13:43:34.070100Z :NOTICE: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Close with zero timeout " }
2025-11-05T13:43:34.070109Z :DEBUG: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] [] Abort session to cluster
2025-11-05T13:43:34.070241Z :NOTICE: [/Root] [/Root] [d102f769-1a7f934a-cfcacc4b-330b4d59] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Aborted " }
2025-11-05T13:43:34.070817Z node 7 :PQ_READ_PROXY DEBUG: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc read done: success# 0, data# {  }
2025-11-05T13:43:34.070835Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc read failed
2025-11-05T13:43:34.070842Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 grpc closed
2025-11-05T13:43:34.070853Z node 7 :PQ_READ_PROXY INFO: session cookie 1 consumer test-consumer session test-consumer_7_1_1643132248296154647_v1 is DEAD
2025-11-05T13:43:34.071045Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] Destroy direct read session test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:34.071061Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [7:7569236527238436441:2484] destroyed
2025-11-05T13:43:34.071081Z node 7 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:34.071133Z node 7 :PERSQUEUE_READ_BALANCER INFO: [72075186224037895][topic_A] pipe [7:7569236527238436437:2481] disconnected; active server actors: 1
2025-11-05T13:43:34.071136Z node 7 :PERSQUEUE_READ_BALANCER NOTICE: [72075186224037895][topic_A] pipe [7:7569236527238436437:2481] client test-consumer disconnected session test-consumer_7_1_1643132248296154647_v1
2025-11-05T13:43:34.077618Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 0.000000s
2025-11-05T13:43:34.077630Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:43:34.077638Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:43:34.077829Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.077835Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:43:34.078476Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.078491Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 grpc read failed
2025-11-05T13:43:34.078503Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 grpc closed
2025-11-05T13:43:34.078507Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: test-message_group_id_2|39fc5041-ef3d3925-1f575d61-bcc364ba_0 is DEAD
2025-11-05T13:43:34.078811Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.078980Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [7:7569236527238436430:2478] destroyed
2025-11-05T13:43:34.079014Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.079022Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.079026Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.082212Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: close. Timeout 0.000000s
2025-11-05T13:43:34.082220Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session will now close
2025-11-05T13:43:34.082227Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: aborting
2025-11-05T13:43:34.082407Z :INFO: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: gracefully shut down, all writes complete
2025-11-05T13:43:34.082413Z :DEBUG: [/Root]  TraceId []  SessionId [test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0]  PartitionId [0]  Generation [1] Write session: destroy
2025-11-05T13:43:34.083737Z node 7 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 grpc read done: success: 0 data: 
2025-11-05T13:43:34.083756Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 grpc read failed
2025-11-05T13:43:34.083769Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 grpc closed
2025-11-05T13:43:34.083774Z node 7 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: test-message_group_id_1|9b69547b-1fed2012-e217bf0d-312ede64_0 is DEAD
2025-11-05T13:43:34.084111Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.084120Z node 7 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037894 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-11-05T13:43:34.084190Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [7:7569236527238436384:2469] destroyed
2025-11-05T13:43:34.084196Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894] server disconnected, pipe [7:7569236527238436387:2469] destroyed
2025-11-05T13:43:34.084209Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] TPartition::DropOwner.
2025-11-05T13:43:34.084215Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.084217Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.088014Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.088021Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-11-05T13:43:34.092326Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-11-05T13:43:34.092343Z node 7 :PERSQUEUE DEBUG: [PQ: 72075186224037894, Partition: 0, State: StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
