2025-10-26T18:06:02.035983Z node 3 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[3:7565593319441404995:4098];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:02.037188Z node 3 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-10-26T18:06:02.043820Z node 4 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[4:7565593320370837558:4098];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:02.044624Z node 4 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2025-10-26T18:06:02.055089Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache created
2025-10-26T18:06:02.084188Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache created
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/70hy/000515/r3tmp/tmpDnjXXI/pdisk_1.dat
2025-10-26T18:06:02.371430Z node 3 :IMPORT WARN: Table profiles were not loaded
2025-10-26T18:06:02.401190Z node 3 :HIVE WARN: HIVE#72057594037968897 Node(3, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-26T18:06:02.401311Z node 3 :HIVE WARN: HIVE#72057594037968897 Node(3, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-26T18:06:02.402502Z node 3 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-26T18:06:02.402584Z node 3 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-26T18:06:02.406105Z node 3 :HIVE WARN: HIVE#72057594037968897 Handle TEvInterconnect::TEvNodeConnected, NodeId 4 Cookie 4
2025-10-26T18:06:02.406252Z node 3 :HIVE WARN: HIVE#72057594037968897 Node(3, (0,0,0,0)) VolatileState: Connecting -> Connected
2025-10-26T18:06:02.407069Z node 3 :HIVE WARN: HIVE#72057594037968897 Node(4, (0,0,0,0)) VolatileState: Connecting -> Connected
TServer::EnableGrpc on GrpcPort 27258, node 3
2025-10-26T18:06:02.496430Z node 3 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/70hy/000515/r3tmp/yandex6KFQB7.tmp
2025-10-26T18:06:02.496457Z node 3 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/70hy/000515/r3tmp/yandex6KFQB7.tmp
2025-10-26T18:06:02.496573Z node 3 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/70hy/000515/r3tmp/yandex6KFQB7.tmp
2025-10-26T18:06:02.496720Z node 3 :NET_CLASSIFIER ERROR: got bad distributable configuration
2025-10-26T18:06:02.552462Z INFO: TTestServer started on Port 4738 GrpcPort 27258
TClient is connected to server localhost:4738
PQClient connected to localhost:27258
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      PlanResolution: 7
      Coo...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-10-26T18:06:02.775242Z node 3 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976710657:0, at schemeshard:  72057594046644480
waiting...
waiting...
2025-10-26T18:06:02.838932Z node 3 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710659:0, at schemeshard:  72057594046644480
waiting...
waiting...
waiting...
2025-10-26T18:06:05.893890Z node 3 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [3:7565593332326307882:4296], status: SCHEME_ERROR, issues: <main>: Error: Type annotation, code: 1030
    <main>:3:16: Error: At function: KiReadTable!
        <main>:3:16: Error: Cannot find table 'db.[/Root/PQ/Config/V2/Cluster]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions., code: 2003
2025-10-26T18:06:05.898320Z node 3 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=3&id=ZjJlYTliNGQtYTA3ODE0NTMtYjE3Zjg1NmMtZDAwZTg5Nzg=, ActorId: [3:7565593332326307880:4285], ActorState: ExecuteState, TraceId: 01k8gv5vdz1rpmx1620pt6x1ac, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-10-26T18:06:05.899432Z node 3 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 3 column: 16 } message: "At function: KiReadTable!" end_position { row: 3 column: 16 } severity: 1 issues { position { row: 3 column: 16 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Cluster]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 3 column: 16 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2025-10-26T18:06:05.907994Z node 3 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710662:0, at schemeshard:  72057594046644480
2025-10-26T18:06:06.027570Z node 3 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710663:0, at schemeshard:  72057594046644480
2025-10-26T18:06:06.033453Z node 4 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [4:7565593337550707066:4295], status: SCHEME_ERROR, issues: <main>: Error: Type annotation, code: 1030
    <main>:5:17: Error: At function: KiReadTable!
        <main>:5:17: Error: Cannot find table 'db.[/Root/PQ/Config/V2/Versions]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions., code: 2003
2025-10-26T18:06:06.033790Z node 4 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=4&id=Zjc2MDk1NzQtNThkYWZjN2ItYzFhNmI4MmUtN2FjNTY1MzQ=, ActorId: [4:7565593333255739767:4292], ActorState: ExecuteState, TraceId: 01k8gv5vnh4vkd9rpgn5h3j1re, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-10-26T18:06:06.035975Z node 4 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 5 column: 17 } message: "At function: KiReadTable!" end_position { row: 5 column: 17 } severity: 1 issues { position { row: 5 column: 17 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Versions]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 5 column: 17 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2025-10-26T18:06:06.205328Z node 3 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710664:0, at schemeshard:  72057594046644480
=== Init DC: UPSERT INTO `/Root/PQ/Config/V2/Cluster` (name, balancer, local, enabled, weight) VALUES ("dc1", "localhost", true, true, 1000), ("dc2", "dc2.logbroker.yandex.net", false, true, 1000);
2025-10-26T18:06:06.559279Z node 3 :KQP_EXECUTER ERROR: TxId: 281474976710665. Ctx: { TraceId: 01k8gv5w0fbq8zs0xndw60vjne, Database: , DatabaseId: /Root, SessionId: ydb://session/3?node_id=3&id=MjgwOTBiMDAtMzUwNDllMzMtOTJlMDg3NC02YjY5NmJlNw==, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
=== CheckClustersList. Subcribe to ClusterTracker from [3:7565593336621275614:12322] 
2025-10-26T18:06:07.036277Z node 3 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[3:7565593319441404995:4098];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:07.036383Z node 3 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
2025-10-26T18:06:07.043994Z node 4 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[4:7565593320370837558:4098];send_to=[0:7307199536658146131:7762515];
2025-10-26T18:06:07.044097Z node 4 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
=== CheckClustersList. Ok
PQ Client: create topic: rt3.dc1--topic1 with 10 partitions
CallPersQueueGRPC request to localhost:27258
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-26T18:06:12.572680Z node 3 :PQ_METACACHE DEBUG: HandleDescribeAllTopics
2025-10-26T18:06:12.572711Z node 3 :PQ_METACACHE DEBUG: ProcessDescribeAllTopics
2025-10-26T18:06:12.572721Z node 3 :PQ_METACACHE DEBUG: Describe all topics - send empty response
2025-10-26T18:06:12.572735Z node 3 :PQ_METACACHE DEBUG: Send describe all topics response with 0 topics
2025-10-26T18:06:12.572814Z node 3 :PERSQUEUE INFO: proxy answer <none>
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
CallPersQueueGRPC request to localhost:27258
MetaRequest {
  CmdCreateTopic {
    Topic: "rt3.dc1--topic1"
    NumPartitions: 10
    Config {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxCounts: 6000000
      }
      LocalDC: true
      ReadRules: "user"
      ReadFromTimestampsMs: 0
      ConsumerFormatVersions: 0
      ConsumerCodecs {
      }
      Codecs {
        Ids: 0
        Ids: 1
        Ids: 2
        Codecs: "raw"
        Codecs: "gzip"
        Codecs: "lzop"
      }
      ReadRuleVersions: 0
    }
  }
}
CallPersQueueGRPC response:
Status: 129
ProxyErrorCode: 53
SchemeStatus: 1
FlatTxId {
  TxId: 281474976710679
  SchemeShardTabletId: 72057594046644480
  PathId: 9
}
ErrorCode: OK
AddTopic: rt3.dc1--topic1
===Run query:``DECLARE $version as Int64; DECLARE $path AS Utf8; DECLARE $cluster as Utf8; UPSERT INTO `/Root/PQ/Config/V2/Topics` (path, dc) VALUES ($path, $cluster); UPSERT INTO `/Root/PQ/Config/V2/Versions` (name, version) VALUES ("Topics", $version);`` with topic = topic1, dc = dc1
2025-10-26T18:06:12.613620Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvInterconnect::TEvNodeInfo
2025-10-26T18:06:12.614305Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Registered with mediator time cast
2025-10-26T18:06:12.621979Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-10-26T18:06:12.622223Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] doesn't have tx info
2025-10-26T18:06:12.622239Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-10-26T18:06:12.622252Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] no config, start with empty partitions and default config
2025-10-26T18:06:12.622269Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Txs.size=0, PlannedTxs.size=0
2025-10-26T18:06:12.622291Z node 3 :PERSQUEUE NOTICE: Tablet 72075186224037893 disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-26T18:06:12.622325Z node 3 :PERSQUEUE INFO: Tablet 72075186224037893 doesn't have tx writes info
2025-10-26T18:06:12.625759Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593362391079986:8472], now have 1 active actors on pipe
2025-10-26T18:06:12.626230Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 } TxId: 281474976710679 Config { TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 9 PartitionIds: 2 PartitionIds: 5 PartitionIds: 7 PartitionIds: 4 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 9 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 2 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 5 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 7 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 4 Status: Active CreateVersion: 1 TabletId: 0 } } }
2025-10-26T18:06:12.626317Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Propose TxId 281474976710679, WriteId (empty maybe)
2025-10-26T18:06:12.626339Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state UNKNOWN
2025-10-26T18:06:12.626355Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State UNKNOWN
2025-10-26T18:06:12.626371Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] schedule TEvProposeTransactionResult(PREPARED)
2025-10-26T18:06:12.626390Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState PREPARING
2025-10-26T18:06:12.626431Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] write key for TxId 281474976710679
2025-10-26T18:06:12.626816Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: PREPARED MinStep: 1761501972608 MaxStep: 18446744073709551615 Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 9 PartitionIds: 2 PartitionIds: 5 PartitionIds: 7 PartitionIds: 4 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 9 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 2 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 5 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 7 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 4 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.626924Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.628255Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-10-26T18:06:12.629268Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Registered with mediator time cast
2025-10-26T18:06:12.636066Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-10-26T18:06:12.636413Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] doesn't have tx info
2025-10-26T18:06:12.636434Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] PlanStep 0, PlanTxId 0, ExecStep 0, ExecTxId 0
2025-10-26T18:06:12.636453Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-10-26T18:06:12.636472Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Txs.size=0, PlannedTxs.size=0
2025-10-26T18:06:12.636497Z node 4 :PERSQUEUE NOTICE: Tablet 72075186224037892 disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-26T18:06:12.636527Z node 4 :PERSQUEUE INFO: Tablet 72075186224037892 doesn't have tx writes info
2025-10-26T18:06:12.637922Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.637965Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state PREPARING
2025-10-26T18:06:12.637984Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State PREPARING
2025-10-26T18:06:12.638005Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState PREPARED
2025-10-26T18:06:12.647529Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593362391079984:8518], now have 1 active actors on pipe
2025-10-26T18:06:12.647595Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic  pipe [3:7565593362391079987:8501] connected; active server actors: 1
2025-10-26T18:06:12.647854Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 updating configuration. Deleted partitions []. Added partitions [3, 0, 1, 6, 8, 9, 2, 5, 7, 4]
2025-10-26T18:06:12.649127Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037894
2025-10-26T18:06:12.649314Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransaction SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 } TxId: 281474976710679 Config { TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 3 PartitionIds: 0 PartitionIds: 1 PartitionIds: 6 PartitionIds: 8 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 3 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 6 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 8 Status: Active CreateVersion: 1 TabletId: 0 } } }
2025-10-26T18:06:12.649441Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Propose TxId 281474976710679, WriteId (empty maybe)
2025-10-26T18:06:12.649466Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state UNKNOWN
2025-10-26T18:06:12.649485Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State UNKNOWN
2025-10-26T18:06:12.649506Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] schedule TEvProposeTransactionResult(PREPARED)
2025-10-26T18:06:12.649539Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState PREPARING
2025-10-26T18:06:12.649597Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710679
2025-10-26T18:06:12.650018Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: PREPARED MinStep: 1761501972692 MaxStep: 18446744073709551615 Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 3 PartitionIds: 0 PartitionIds: 1 PartitionIds: 6 PartitionIds: 8 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 3 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 6 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 8 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.650142Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.652797Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [4:7565593363320511278:10], now have 1 active actors on pipe
2025-10-26T18:06:12.651589Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037894 topic rt3.dc1--topic1 TEvClientConnected TabletId 72075186224037892, NodeId 4, Generation 1
2025-10-26T18:06:12.651642Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [4:7565593363320511277:10], now have 1 active actors on pipe
2025-10-26T18:06:12.653401Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037894 topic rt3.dc1--topic1 TEvClientConnected TabletId 72075186224037893, NodeId 3, Generation 1
2025-10-26T18:06:12.655508Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: BALANCER INIT DONE for rt3.dc1--topic1: (0, 72075186224037892) (1, 72075186224037892) (2, 72075186224037893) (3, 72075186224037892) (4, 72075186224037893) (5, 72075186224037893) (6, 72075186224037892) (7, 72075186224037893) (8, 72075186224037892) (9, 72075186224037893) 
2025-10-26T18:06:12.657585Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037894 topic rt3.dc1--topic1 TEvClientConnected TabletId 72057594046644480, NodeId 3, Generation 2
2025-10-26T18:06:12.659225Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.659269Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARING
2025-10-26T18:06:12.659290Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State PREPARING
2025-10-26T18:06:12.659312Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState PREPARED
2025-10-26T18:06:12.662444Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:12.662475Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:12.667202Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037893 TxId: 281474976710679
2025-10-26T18:06:12.666998Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPersQueue::TEvProposeTransactionAttach TabletId: 72075186224037892 TxId: 281474976710679
2025-10-26T18:06:12.669898Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593362391080092:8504], now have 1 active actors on pipe
2025-10-26T18:06:12.669708Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593362391080093:8473], now have 1 active actors on pipe
2025-10-26T18:06:12.669841Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976710679 AckTo { RawX1: 7565593319441405581 RawX2: 12884910165 } } Step: 1761501972713 MediatorID: 72057594046382081 TabletID: 72075186224037893
2025-10-26T18:06:12.669894Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state PREPARED
2025-10-26T18:06:12.669922Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State PREPARED
2025-10-26T18:06:12.669941Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState PLANNING
2025-10-26T18:06:12.669961Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] PlanStep 1761501972713, PlanTxId 281474976710679
2025-10-26T18:06:12.669995Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] write key for TxId 281474976710679
2025-10-26T18:06:12.670590Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvTxProcessing::TEvPlanStep Transactions { TxId: 281474976710679 AckTo { RawX1: 7565593319441405581 RawX2: 12884910165 } } Step: 1761501972713 MediatorID: 72057594046382081 TabletID: 72075186224037892
2025-10-26T18:06:12.670640Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state PREPARED
2025-10-26T18:06:12.670656Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State PREPARED
2025-10-26T18:06:12.670674Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState PLANNING
2025-10-26T18:06:12.670695Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] PlanStep 1761501972713, PlanTxId 281474976710679
2025-10-26T18:06:12.670722Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710679
2025-10-26T18:06:12.670427Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: PLANNED MinStep: 1761501972608 MaxStep: 18446744073709551615 Step: 1761501972713 Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 9 PartitionIds: 2 PartitionIds: 5 PartitionIds: 7 PartitionIds: 4 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 9 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 2 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 5 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 7 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 4 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.670565Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.671113Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: PLANNED MinStep: 1761501972692 MaxStep: 18446744073709551615 Step: 1761501972713 Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 3 PartitionIds: 0 PartitionIds: 1 PartitionIds: 6 PartitionIds: 8 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 3 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 6 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 8 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.671204Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.674587Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.674643Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state PLANNING
2025-10-26T18:06:12.674658Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State PLANNING
2025-10-26T18:06:12.674676Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState PLANNED
2025-10-26T18:06:12.674701Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from PLANNING to PLANNED
2025-10-26T18:06:12.674718Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxQueue.size 1
2025-10-26T18:06:12.674734Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] New ExecStep 1761501972713, ExecTxId 281474976710679
2025-10-26T18:06:12.674989Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.675053Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state PLANNING
2025-10-26T18:06:12.675072Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State PLANNING
2025-10-26T18:06:12.675092Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState PLANNED
2025-10-26T18:06:12.675127Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from PLANNING to PLANNED
2025-10-26T18:06:12.675141Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxQueue.size 1
2025-10-26T18:06:12.675179Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] New ExecStep 1761501972713, ExecTxId 281474976710679
2025-10-26T18:06:12.676061Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 3. Step TInitConfigStep
2025-10-26T18:06:12.676796Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 0. Step TInitConfigStep
2025-10-26T18:06:12.678079Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 1. Step TInitConfigStep
2025-10-26T18:06:12.679677Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 6. Step TInitConfigStep
2025-10-26T18:06:12.680363Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState CALCULATING
2025-10-26T18:06:12.680403Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from PLANNED to CALCULATING
2025-10-26T18:06:12.680490Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 9. Step TInitConfigStep
2025-10-26T18:06:12.680554Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 9, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.680788Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState CALCULATING
2025-10-26T18:06:12.680817Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from PLANNED to CALCULATING
2025-10-26T18:06:12.680850Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 9. Step TInitInternalFieldsStep
2025-10-26T18:06:12.680830Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.680875Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.680916Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 1, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.680943Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 3, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.680983Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 8. Step TInitConfigStep
2025-10-26T18:06:12.681037Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 8, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.681118Z node 3 :PERSQUEUE INFO: bootstrapping 9 [3:7565593362391080104:4320]
2025-10-26T18:06:12.681291Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 3. Step TInitInternalFieldsStep
2025-10-26T18:06:12.681560Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 0. Step TInitInternalFieldsStep
2025-10-26T18:06:12.681669Z node 4 :PERSQUEUE INFO: bootstrapping 3 [4:7565593363320511293:4327]
2025-10-26T18:06:12.681822Z node 4 :PERSQUEUE INFO: bootstrapping 0 [4:7565593363320511294:4272]
2025-10-26T18:06:12.684356Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 9. Completed.
2025-10-26T18:06:12.684395Z node 3 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 9 generation 1 [3:7565593362391080104:4320]
2025-10-26T18:06:12.684416Z node 3 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 9 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.684798Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 0. Completed.
2025-10-26T18:06:12.684826Z node 4 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 0 generation 1 [4:7565593363320511294:4272]
2025-10-26T18:06:12.684830Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 3. Completed.
2025-10-26T18:06:12.684845Z node 4 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.684847Z node 4 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 3 generation 1 [4:7565593363320511293:4327]
2025-10-26T18:06:12.684865Z node 4 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 3 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.686008Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 9, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.686150Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 9 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.686414Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 9
2025-10-26T18:06:12.686438Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.686466Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 1/5
2025-10-26T18:06:12.686484Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state CALCULATING
2025-10-26T18:06:12.686502Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.686522Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.686534Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 1, Expected 5
2025-10-26T18:06:12.686550Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.686405Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.686414Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 3, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.686515Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.686516Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 3 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.686864Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 2. Step TInitConfigStep
2025-10-26T18:06:12.686771Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 1. Step TInitInternalFieldsStep
2025-10-26T18:06:12.686929Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 2, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.686784Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 6. Step TInitInternalFieldsStep
2025-10-26T18:06:12.686980Z node 4 :PERSQUEUE INFO: bootstrapping 1 [4:7565593363320511295:4310]
2025-10-26T18:06:12.686992Z node 4 :PERSQUEUE INFO: bootstrapping 6 [4:7565593363320511296:4287]
2025-10-26T18:06:12.689320Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 6. Completed.
2025-10-26T18:06:12.689337Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 1. Completed.
2025-10-26T18:06:12.689361Z node 4 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 6 generation 1 [4:7565593363320511296:4287]
2025-10-26T18:06:12.689368Z node 4 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 1 generation 1 [4:7565593363320511295:4310]
2025-10-26T18:06:12.689380Z node 4 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 6 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.689386Z node 4 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 1 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.687214Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 2. Step TInitInternalFieldsStep
2025-10-26T18:06:12.687437Z node 3 :PERSQUEUE INFO: bootstrapping 2 [3:7565593362391080107:4318]
2025-10-26T18:06:12.690713Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.690793Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 1, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.690830Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.690883Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.691181Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 8. Step TInitInternalFieldsStep
2025-10-26T18:06:12.691207Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 0
2025-10-26T18:06:12.691225Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.689920Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 2. Completed.
2025-10-26T18:06:12.691239Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 1/5
2025-10-26T18:06:12.691263Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-10-26T18:06:12.689942Z node 3 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 2 generation 1 [3:7565593362391080107:4318]
2025-10-26T18:06:12.691285Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.689958Z node 3 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 2 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.691308Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.691150Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 2, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.691247Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 2 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.691327Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 1, Expected 5
2025-10-26T18:06:12.691343Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.691372Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 3
2025-10-26T18:06:12.691384Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.691394Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 2/5
2025-10-26T18:06:12.691403Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-10-26T18:06:12.691411Z node 4 :PERSQUEUE INFO: bootstrapping 8 [4:7565593363320511297:4288]
2025-10-26T18:06:12.691414Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.691427Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.691435Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 2, Expected 5
2025-10-26T18:06:12.691444Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.691766Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 6
2025-10-26T18:06:12.691789Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.691799Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 3/5
2025-10-26T18:06:12.691810Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-10-26T18:06:12.691830Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.691844Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.691854Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 3, Expected 5
2025-10-26T18:06:12.691871Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.691906Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 1
2025-10-26T18:06:12.691917Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.691927Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 4/5
2025-10-26T18:06:12.691938Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-10-26T18:06:12.691949Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.691961Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.691971Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 4, Expected 5
2025-10-26T18:06:12.691980Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.691917Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 2
2025-10-26T18:06:12.691944Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.691955Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 2/5
2025-10-26T18:06:12.691970Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state CALCULATING
2025-10-26T18:06:12.691983Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.692000Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.692014Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 2, Expected 5
2025-10-26T18:06:12.692029Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.692283Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 5. Step TInitConfigStep
2025-10-26T18:06:12.692328Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.692611Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 5. Step TInitInternalFieldsStep
2025-10-26T18:06:12.692884Z node 3 :PERSQUEUE INFO: bootstrapping 5 [3:7565593362391080109:4282]
2025-10-26T18:06:12.693772Z node 4 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 8. Completed.
2025-10-26T18:06:12.693798Z node 4 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 8 generation 1 [4:7565593363320511297:4288]
2025-10-26T18:06:12.693818Z node 4 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 8 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.694944Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 8, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.695054Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 8 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.695112Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 8
2025-10-26T18:06:12.695146Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.695159Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 5/5
2025-10-26T18:06:12.695202Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATING
2025-10-26T18:06:12.695220Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.695239Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.695263Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 5, Expected 5
2025-10-26T18:06:12.695285Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState CALCULATED
2025-10-26T18:06:12.695305Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from CALCULATING to CALCULATED
2025-10-26T18:06:12.695326Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710679
2025-10-26T18:06:12.695779Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: CALCULATED MinStep: 1761501972692 MaxStep: 18446744073709551615 Step: 1761501972713 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 3 PartitionIds: 0 PartitionIds: 1 PartitionIds: 6 PartitionIds: 8 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 3 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 6 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 8 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.695900Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.696658Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 5. Completed.
2025-10-26T18:06:12.696695Z node 3 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 5 generation 1 [3:7565593362391080109:4282]
2025-10-26T18:06:12.696714Z node 3 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 5 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.700815Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.700855Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state CALCULATED
2025-10-26T18:06:12.700872Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State CALCULATED
2025-10-26T18:06:12.700890Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State CALCULATED FrontTxId 281474976710679
2025-10-26T18:06:12.700908Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState WAIT_RS
2025-10-26T18:06:12.700926Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from CALCULATED to WAIT_RS
2025-10-26T18:06:12.700948Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-10-26T18:06:12.700964Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] HaveParticipantsDecision 1
2025-10-26T18:06:12.701007Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState EXECUTING
2025-10-26T18:06:12.701023Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from WAIT_RS to EXECUTING
2025-10-26T18:06:12.701037Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 0, Expected 5
2025-10-26T18:06:12.701079Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.701396Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 8, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.701591Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 1, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.697939Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.698071Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 5 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.698281Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 5
2025-10-26T18:06:12.698300Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.698312Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 3/5
2025-10-26T18:06:12.698333Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state CALCULATING
2025-10-26T18:06:12.698348Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.698366Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.698378Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 3, Expected 5
2025-10-26T18:06:12.698393Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.701792Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 3, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.698581Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 7. Step TInitConfigStep
2025-10-26T18:06:12.701954Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.702124Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.702206Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.698628Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.698661Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 4. Step TInitConfigStep
2025-10-26T18:06:12.698685Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 4, State: StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-26T18:06:12.699086Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 7. Step TInitInternalFieldsStep
2025-10-26T18:06:12.699371Z node 3 :PERSQUEUE INFO: bootstrapping 7 [3:7565593362391080110:4289]
2025-10-26T18:06:12.702324Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.702379Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.702426Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.702541Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 7. Completed.
2025-10-26T18:06:12.702578Z node 3 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 7 generation 1 [3:7565593362391080110:4289]
2025-10-26T18:06:12.702602Z node 3 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 7 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.703899Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.704031Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.704287Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 4. Step TInitInternalFieldsStep
2025-10-26T18:06:12.704646Z node 3 :PERSQUEUE INFO: bootstrapping 4 [3:7565593362391080111:4286]
2025-10-26T18:06:12.707763Z node 3 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 4. Completed.
2025-10-26T18:06:12.707805Z node 3 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 4 generation 1 [3:7565593362391080111:4286]
2025-10-26T18:06:12.707826Z node 3 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 4 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2025-10-26T18:06:12.707892Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.708027Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 8, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.708156Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 0
2025-10-26T18:06:12.708179Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-10-26T18:06:12.708195Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.708223Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.708238Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 1, Expected 5
2025-10-26T18:06:12.708254Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.708287Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 8
2025-10-26T18:06:12.708298Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-10-26T18:06:12.708309Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.708319Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.708330Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 2, Expected 5
2025-10-26T18:06:12.708336Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 1, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.708340Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.708360Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 1
2025-10-26T18:06:12.708371Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-10-26T18:06:12.708383Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.709181Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 4, State: StateIdle] Process pending events. Count 1
2025-10-26T18:06:12.708394Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.708402Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 3, Expected 5
2025-10-26T18:06:12.708413Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.708481Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 3, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.708557Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 3
2025-10-26T18:06:12.708575Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-10-26T18:06:12.708578Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.708588Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.708603Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.708616Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 4, Expected 5
2025-10-26T18:06:12.708637Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.708674Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 6
2025-10-26T18:06:12.708685Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTING
2025-10-26T18:06:12.708695Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.708708Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.708717Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Received 5, Expected 5
2025-10-26T18:06:12.708741Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId: 281474976710679 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-10-26T18:06:12.708761Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] complete TxId 281474976710679
2025-10-26T18:06:12.709146Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Apply new config PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 3 PartitionIds: 0 PartitionIds: 1 PartitionIds: 6 PartitionIds: 8 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 3 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 6 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 8 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false }
2025-10-26T18:06:12.709311Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 4 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:12.709238Z node 4 :PERSQUEUE NOTICE: Tablet 72075186224037892 disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-26T18:06:12.709589Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 7
2025-10-26T18:06:12.709289Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] delete partitions for TxId 281474976710679
2025-10-26T18:06:12.709607Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.709307Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState EXECUTED
2025-10-26T18:06:12.709327Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from EXECUTING to EXECUTED
2025-10-26T18:06:12.709620Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 4/5
2025-10-26T18:06:12.709635Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state CALCULATING
2025-10-26T18:06:12.709364Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] write key for TxId 281474976710679
2025-10-26T18:06:12.709651Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.709786Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: EXECUTED MinStep: 1761501972692 MaxStep: 18446744073709551615 Step: 1761501972713 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 3 PartitionIds: 0 PartitionIds: 1 PartitionIds: 6 PartitionIds: 8 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 3 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 6 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 8 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.709670Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.709961Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.709908Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 4, Expected 5
2025-10-26T18:06:12.709930Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.710269Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvProposePartitionConfigResult Step 1761501972713, TxId 281474976710679, Partition 4
2025-10-26T18:06:12.710286Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Handle TEvProposePartitionConfigResult
2025-10-26T18:06:12.710299Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] Partition responses 5/5
2025-10-26T18:06:12.710313Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state CALCULATING
2025-10-26T18:06:12.710329Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State CALCULATING
2025-10-26T18:06:12.710346Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State CALCULATING FrontTxId 281474976710679
2025-10-26T18:06:12.710356Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 5, Expected 5
2025-10-26T18:06:12.710374Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState CALCULATED
2025-10-26T18:06:12.710395Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from CALCULATING to CALCULATED
2025-10-26T18:06:12.710413Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] write key for TxId 281474976710679
2025-10-26T18:06:12.710827Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: CALCULATED MinStep: 1761501972608 MaxStep: 18446744073709551615 Step: 1761501972713 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 9 PartitionIds: 2 PartitionIds: 5 PartitionIds: 7 PartitionIds: 4 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 9 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 2 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 5 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 7 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 4 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.710939Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.720901Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.720935Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state EXECUTED
2025-10-26T18:06:12.720951Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State EXECUTED
2025-10-26T18:06:12.720967Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 State EXECUTED FrontTxId 281474976710679
2025-10-26T18:06:12.720986Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TPersQueue::SendEvReadSetAckToSenders
2025-10-26T18:06:12.721005Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState WAIT_RS_ACKS
2025-10-26T18:06:12.721023Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679 moved from EXECUTED to WAIT_RS_ACKS
2025-10-26T18:06:12.721046Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] PredicateAcks: 0/0
2025-10-26T18:06:12.721056Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-10-26T18:06:12.721070Z node 4 :PERSQUEUE DEBUG: [TxId: 281474976710679] PredicateAcks: 0/0
2025-10-26T18:06:12.721085Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] add an TxId 281474976710679 to the list for deletion
2025-10-26T18:06:12.721105Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, NewState DELETING
2025-10-26T18:06:12.721125Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] delete key for TxId 281474976710679
2025-10-26T18:06:12.721176Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.720687Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.720727Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state CALCULATED
2025-10-26T18:06:12.720744Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State CALCULATED
2025-10-26T18:06:12.720765Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State CALCULATED FrontTxId 281474976710679
2025-10-26T18:06:12.720781Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState WAIT_RS
2025-10-26T18:06:12.720801Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from CALCULATED to WAIT_RS
2025-10-26T18:06:12.720824Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Send TEvTxProcessing::TEvReadSet to 0 receivers. Wait TEvTxProcessing::TEvReadSet from 0 senders.
2025-10-26T18:06:12.720842Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] HaveParticipantsDecision 1
2025-10-26T18:06:12.720885Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState EXECUTING
2025-10-26T18:06:12.720901Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from WAIT_RS to EXECUTING
2025-10-26T18:06:12.720915Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 0, Expected 5
2025-10-26T18:06:12.720957Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.721296Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 2, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.721575Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 9, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.721805Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 4, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.721981Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateIdle] Handle TEvPQ::TEvTxCommit Step 1761501972713, TxId 281474976710679
2025-10-26T18:06:12.722184Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.722273Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.722349Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.722401Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.722453Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:12.727225Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.727350Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 7
2025-10-26T18:06:12.727376Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state EXECUTING
2025-10-26T18:06:12.727394Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.727413Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.727427Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 1, Expected 5
2025-10-26T18:06:12.727443Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.727996Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.728048Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] Try execute txs with state DELETING
2025-10-26T18:06:12.728067Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] TxId 281474976710679, State DELETING
2025-10-26T18:06:12.728086Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892] delete TxId 281474976710679
2025-10-26T18:06:12.729470Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 2, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.729701Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 9, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.729906Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 4, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.730064Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:12.730149Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 2
2025-10-26T18:06:12.730181Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state EXECUTING
2025-10-26T18:06:12.730199Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.730217Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.730229Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 2, Expected 5
2025-10-26T18:06:12.730244Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.730282Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 9
2025-10-26T18:06:12.730293Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state EXECUTING
2025-10-26T18:06:12.730304Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.730317Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.730327Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 3, Expected 5
2025-10-26T18:06:12.730355Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.730378Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 4
2025-10-26T18:06:12.730389Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state EXECUTING
2025-10-26T18:06:12.730401Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.730412Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.730422Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 4, Expected 5
2025-10-26T18:06:12.730431Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 status has not changed
2025-10-26T18:06:12.730452Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvPQ::TEvTxCommitDone Step 1761501972713, TxId 281474976710679, Partition 5
2025-10-26T18:06:12.730462Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state EXECUTING
2025-10-26T18:06:12.730472Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State EXECUTING
2025-10-26T18:06:12.730482Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State EXECUTING FrontTxId 281474976710679
2025-10-26T18:06:12.730490Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Received 5, Expected 5
2025-10-26T18:06:12.730515Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId: 281474976710679 send TEvPersQueue::TEvProposeTransactionResult(COMPLETE)
2025-10-26T18:06:12.730545Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] complete TxId 281474976710679
2025-10-26T18:06:12.730975Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Apply new config PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 9 PartitionIds: 2 PartitionIds: 5 PartitionIds: 7 PartitionIds: 4 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 9 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 2 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 5 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 7 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 4 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false }
2025-10-26T18:06:12.731059Z node 3 :PERSQUEUE NOTICE: Tablet 72075186224037893 disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-26T18:06:12.731117Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] delete partitions for TxId 281474976710679
2025-10-26T18:06:12.731136Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState EXECUTED
2025-10-26T18:06:12.731155Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from EXECUTING to EXECUTED
2025-10-26T18:06:12.731175Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] write key for TxId 281474976710679
2025-10-26T18:06:12.731619Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] save tx TxId: 281474976710679 State: EXECUTED MinStep: 1761501972608 MaxStep: 18446744073709551615 Step: 1761501972713 Predicate: true Kind: KIND_CONFIG TabletConfig { PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 10 SourceIdMaxCounts: 6000000 } PartitionIds: 9 PartitionIds: 2 PartitionIds: 5 PartitionIds: 7 PartitionIds: 4 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true ReadRules: "user" ReadFromTimestampsMs: 0 ConsumerFormatVersions: 0 ConsumerCodecs { } Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } ReadRuleVersions: 0 TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 9 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 2 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 5 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 7 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 4 Status: Active CreateVersion: 1 TabletId: 0 } ReadRuleGenerations: 0 Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Codec { } Version: 0 Generation: 0 Important: false } } BootstrapConfig { } SourceActor { RawX1: 7565593319441405329 RawX2: 12884914221 }
2025-10-26T18:06:12.731846Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.741142Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.741172Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state EXECUTED
2025-10-26T18:06:12.741187Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State EXECUTED
2025-10-26T18:06:12.741208Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 State EXECUTED FrontTxId 281474976710679
2025-10-26T18:06:12.741229Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TPersQueue::SendEvReadSetAckToSenders
2025-10-26T18:06:12.741253Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState WAIT_RS_ACKS
2025-10-26T18:06:12.741270Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679 moved from EXECUTED to WAIT_RS_ACKS
2025-10-26T18:06:12.741294Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] PredicateAcks: 0/0
2025-10-26T18:06:12.741305Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] HaveAllRecipientsReceive 1, AllSupportivePartitionsHaveBeenDeleted 1
2025-10-26T18:06:12.741317Z node 3 :PERSQUEUE DEBUG: [TxId: 281474976710679] PredicateAcks: 0/0
2025-10-26T18:06:12.741334Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] add an TxId 281474976710679 to the list for deletion
2025-10-26T18:06:12.741366Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, NewState DELETING
2025-10-26T18:06:12.741382Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] delete key for TxId 281474976710679
2025-10-26T18:06:12.741422Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-26T18:06:12.747161Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-26T18:06:12.747203Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] Try execute txs with state DELETING
2025-10-26T18:06:12.747221Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] TxId 281474976710679, State DELETING
2025-10-26T18:06:12.747241Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893] delete TxId 281474976710679
2025-10-26T18:06:12.752482Z node 3 :KQP_EXECUTER ERROR: TxId: 281474976710680. Ctx: { TraceId: 01k8gv624netv4bvkzm5v3vvab, Database: , DatabaseId: /Root, SessionId: ydb://session/3?node_id=3&id=Zjc5MDBkOTEtNjAyOGRmMTUtM2MwODI4MWQtOWYwN2IxZjI=, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
2025-10-26T18:06:12.754848Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:12.767228Z node 4 :PQ_METACACHE DEBUG: Got config version: 1
2025-10-26T18:06:12.777989Z node 4 :PQ_METACACHE DEBUG: HandleGetTopicsResult
===Query complete
TClient::Ls request: /Root/PQ/rt3.dc1--topic1
2025-10-26T18:06:12.788587Z node 4 :PQ_METACACHE DEBUG: HandleGetTopicsResult
2025-10-26T18:06:12.788726Z node 4 :PQ_METACACHE DEBUG: Updated topics list with : 1 topics
2025-10-26T18:06:12.788754Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "rt3.dc1--topic1"
    PathId: 9
    SchemeshardId: 72057594046644480
    PathType: EPathTypePersQueueGroup
    CreateFinished: true
    CreateTxId: 281474976710679
    CreateStep: 1761501972713
    ParentPathId: 2
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 0
      PQVersion: 1
    }
    BalancerTabletID: 72075186224037894
  }
  PersQueueGroup {
    Name: "rt3.dc1--topic1"
    PathId: 9
    TotalGroupCount: 10
    PartitionPerTablet: 5
    PQTabletConfig {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMax...
(TRUNCATED)
GetTopicVersionFromPath:  record Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "rt3.dc1--topic1"
    PathId: 9
    SchemeshardId: 72057594046644480
    PathType: EPathTypePersQueueGroup
    CreateFinished: true
    CreateTxId: 281474976710679
    CreateStep: 1761501972713
    ParentPathId: 2
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 0
      PQVersion: 1
    }
    BalancerTabletID: 72075186224037894
  }
  PersQueueGroup {
    Name: "rt3.dc1--topic1"
    PathId: 9
    TotalGroupCount: 10
    PartitionPerTablet: 5
    PQTabletConfig {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxCounts: 6000000
      }
      LocalDC: true
      ReadRules: "user"
      ReadFromTimestampsMs: 0
      ConsumerFormatVersions: 0
      ConsumerCodecs {
      }
      Codecs {
        Ids: 0
        Ids: 1
        Ids: 2
        Codecs: "raw"
        Codecs: "gzip"
        Codecs: "lzop"
      }
      ReadRuleVersions: 0
      YdbDatabasePath: "/Root"
    }
    Partitions {
      PartitionId: 0
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 1
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 2
      TabletId: 72075186224037893
      Status: Active
    }
    Partitions {
      PartitionId: 3
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 4
      TabletId: 72075186224037893
      Status: Active
    }
    Partitions {
      PartitionId: 5
      TabletId: 72075186224037893
      Status: Active
    }
    Partitions {
      PartitionId: 6
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 7
      TabletId: 72075186224037893
      Status: Active
    }
    Partitions {
      PartitionId: 8
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 9
      TabletId: 72075186224037893
      Status: Active
    }
    AlterVersion: 1
    BalancerTabletID: 72075186224037894
    NextPartitionId: 10
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 1
      PlanResolution: 7
      Coordinators: 72057594046316545
      TimeCastBucketsPerMediator: 2
      Mediators: 72057594046382081
    }
    DomainKey {
      SchemeShard: 72057594046644480
      PathId: 1
    }
    PathsInside: 8
    PathsLimit: 10000
    ShardsInside: 7
    ShardsLimit: 200000
    ResourcesDomainKey {
      SchemeShard: 72057594046644480
      PathId: 1
    }
    DiskSpaceUsage {
      Tables {
        TotalSize: 0
        DataSize: 0
        IndexSize: 0
      }
      Topics {
        ReserveSize: 0
        AccountSize: 0
        DataSize: 0
        UsedReserveSize: 0
      }
    }
    PQPartitionsInside: 10
    PQPartitionsLimit: 1000000
  }
}
Path: "/Root/PQ/rt3.dc1--topic1"
 name rt3.dc1--topic1 version1
CallPersQueueGRPC request to localhost:27258
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-26T18:06:12.830429Z node 3 :PQ_METACACHE DEBUG: HandleDescribeAllTopics
2025-10-26T18:06:12.830456Z node 3 :PQ_METACACHE DEBUG: ProcessDescribeAllTopics
2025-10-26T18:06:12.830465Z node 3 :PQ_METACACHE DEBUG: Describe all topics - send empty response
2025-10-26T18:06:12.830479Z node 3 :PQ_METACACHE DEBUG: Send describe all topics response with 0 topics
2025-10-26T18:06:12.830525Z node 3 :PERSQUEUE INFO: proxy answer <none>
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
CallPersQueueGRPC request to localhost:27258
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
2025-10-26T18:06:13.335873Z node 3 :PQ_METACACHE DEBUG: HandleDescribeAllTopics
2025-10-26T18:06:13.335902Z node 3 :PQ_METACACHE DEBUG: ProcessDescribeAllTopics
2025-10-26T18:06:13.335911Z node 3 :PQ_METACACHE DEBUG: Describe all topics - send empty response
2025-10-26T18:06:13.335924Z node 3 :PQ_METACACHE DEBUG: Send describe all topics response with 0 topics
2025-10-26T18:06:13.335971Z node 3 :PERSQUEUE INFO: proxy answer <none>
2025-10-26T18:06:13.514648Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:13.521134Z node 3 :PQ_METACACHE DEBUG: Got config version: 1
2025-10-26T18:06:13.529456Z node 3 :PQ_METACACHE DEBUG: HandleGetTopicsResult
2025-10-26T18:06:13.541762Z node 3 :PQ_METACACHE DEBUG: HandleGetTopicsResult
2025-10-26T18:06:13.541865Z node 3 :PQ_METACACHE DEBUG: Updated topics list with : 1 topics
2025-10-26T18:06:13.541884Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:13.789925Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:13.803874Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
CallPersQueueGRPC request to localhost:27258
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-26T18:06:13.841054Z node 3 :PQ_METACACHE DEBUG: HandleDescribeAllTopics
2025-10-26T18:06:13.841079Z node 3 :PQ_METACACHE DEBUG: ProcessDescribeAllTopics
2025-10-26T18:06:13.841088Z node 3 :PQ_METACACHE DEBUG: ProcessDescribeAllTopics SendSchemeCacheRequest
2025-10-26T18:06:13.841101Z node 3 :PQ_METACACHE DEBUG: SendSchemeCacheRequest
2025-10-26T18:06:13.841152Z node 3 :PQ_METACACHE DEBUG: send request for  all 1 topics, got 1 requests infly, db = ""
2025-10-26T18:06:13.842422Z node 3 :PQ_METACACHE DEBUG: Handle SchemeCache response: result# { ErrorCount: 0 DatabaseName:  DomainOwnerId: 0 Instant: 2 ResultSet [{ Path: Root/PQ/rt3.dc1--topic1 TableId: [72057594046644480:9:0] RequestType: ByPath Operation: OpList RedirectRequired: true ShowPrivatePath: false SyncVersion: false Status: Ok Kind: KindTopic DomainInfo { DomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] ResourcesDomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] Params { Version: 1 PlanResolution: 7 Coordinators: 72057594046316545 TimeCastBucketsPerMediator: 2 Mediators: 72057594046382081 } ServerlessComputeResourcesMode: (empty maybe) } }] }
2025-10-26T18:06:13.842435Z node 3 :PQ_METACACHE DEBUG: Got describe all topics SC response
2025-10-26T18:06:13.842542Z node 3 :PQ_METACACHE DEBUG: Updated topics cache with 1
2025-10-26T18:06:13.842553Z node 3 :PQ_METACACHE DEBUG: Send describe all topics response with 1 topics
2025-10-26T18:06:13.842757Z node 3 :PERSQUEUE INFO: proxy answer <none>
CallPersQueueGRPC response:
Status: 1
ErrorCode: OK
MetaResponse {
  CmdGetTopicMetadataResult {
    TopicInfo {
      Topic: "rt3.dc1--topic1"
      NumPartitions: 10
      Config {
        PartitionConfig {
          LifetimeSeconds: 86400
          LowWatermark: 8388608
          SourceIdLifetimeSeconds: 86400
          WriteSpeedInBytesPerSecond: 20000000
          BurstSize: 20000000
          SourceIdMaxCounts: 6000000
        }
        Version: 1
        LocalDC: true
        ReadRules: "user"
        ReadFromTimestampsMs: 0
        ConsumerFormatVersions: 0
        ConsumerCodecs {
        }
        Codecs {
          Ids: 0
          Ids: 1
          Ids: 2
          Codecs: "raw"
          Codecs: "gzip"
          Codecs: "lzop"
        }
        ReadRuleVersions: 0
        TopicPath: "/Root/PQ/rt3.dc1--topic1"
        YdbDatabasePath: "/Root"
        Consumers {
          Name: "user"
          ReadFromTimestampsMs: 0
          FormatVersion: 0
          Codec {
          }
          Version: 0
       ...
(TRUNCATED)
=== Topic created, have version: 1
2025-10-26T18:06:13.855170Z node 3 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:13.855209Z node 3 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2025-10-26T18:06:13.862141Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "12345678" }
2025-10-26T18:06:13.862272Z node 3 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "topic1" message_group_id: "12345678" from ipv6:[::1]:36692
2025-10-26T18:06:13.862299Z node 3 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36692 proto=v1  topic=topic1 durationSec=0
2025-10-26T18:06:13.862314Z node 3 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:13.862506Z node 3 :PQ_METACACHE DEBUG: Handle describe topics
2025-10-26T18:06:13.862546Z node 3 :PQ_METACACHE DEBUG: SendSchemeCacheRequest
2025-10-26T18:06:13.862609Z node 3 :PQ_METACACHE DEBUG: send request for 1 topics, got 1 requests infly, db = ""
2025-10-26T18:06:13.863048Z node 3 :PQ_METACACHE DEBUG: Handle SchemeCache response: result# { ErrorCount: 0 DatabaseName:  DomainOwnerId: 0 Instant: 3 ResultSet [{ Path: Root/PQ/rt3.dc1--topic1 TableId: [72057594046644480:9:0] RequestType: ByPath Operation: OpList RedirectRequired: true ShowPrivatePath: false SyncVersion: true Status: Ok Kind: KindTopic DomainInfo { DomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] ResourcesDomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] Params { Version: 1 PlanResolution: 7 Coordinators: 72057594046316545 TimeCastBucketsPerMediator: 2 Mediators: 72057594046382081 } ServerlessComputeResourcesMode: (empty maybe) } }] }
2025-10-26T18:06:13.863137Z node 3 :PQ_METACACHE DEBUG: Got describe topics SC response
2025-10-26T18:06:13.866739Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  describe result for acl check
2025-10-26T18:06:13.866897Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-26T18:06:13.866917Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-26T18:06:13.866928Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-26T18:06:13.866945Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:13.869231Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:13.919175Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:13.919204Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:14.013070Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:14.013102Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:14.019196Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) RequestPQRB
2025-10-26T18:06:14.019688Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981014975:4308] connected; active server actors: 1
2025-10-26T18:06:14.019977Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) Received partition 5 from PQRB for SourceId=12345678
2025-10-26T18:06:14.019998Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:14.020505Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981014975:4308] disconnected; active server actors: 1
2025-10-26T18:06:14.020530Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981014975:4308] disconnected no session
2025-10-26T18:06:14.143342Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:14.143392Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) ReplyResult: Partition=5, SeqNo=(NULL)
2025-10-26T18:06:14.143410Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593366686047619:4308] (SourceId=12345678, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:14.143440Z node 3 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 1 sessionId:  partition: 5 expectedGeneration: (NULL)
2025-10-26T18:06:14.144496Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015000:4308], now have 1 active actors on pipe
2025-10-26T18:06:14.144553Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=5) TEvClientConnected Status OK, TabletId: 72075186224037893, NodeId 3, Generation: 1
2025-10-26T18:06:14.144640Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.144670Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 5
2025-10-26T18:06:14.144758Z node 3 :PERSQUEUE INFO: new Cookie 12345678|772cf00b-84e63d0f-d2d9db34-bba4ccf7_0 generated for partition 5 topic 'rt3.dc1--topic1' owner 12345678
2025-10-26T18:06:14.144836Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 5
2025-10-26T18:06:14.144885Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 5 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.145107Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.145120Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 5
2025-10-26T18:06:14.145187Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 5 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.145310Z node 3 :PQ_WRITE_PROXY INFO: session inited cookie: 1 partition: 5 MaxSeqNo: 0 sessionId: 12345678|772cf00b-84e63d0f-d2d9db34-bba4ccf7_0
2025-10-26T18:06:14.149873Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: 12345678|772cf00b-84e63d0f-d2d9db34-bba4ccf7_0 grpc read done: success: 0 data: 
2025-10-26T18:06:14.149902Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: 12345678|772cf00b-84e63d0f-d2d9db34-bba4ccf7_0 grpc read failed
2025-10-26T18:06:14.150162Z node 3 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 1 sessionId: 12345678|772cf00b-84e63d0f-d2d9db34-bba4ccf7_0
2025-10-26T18:06:14.150178Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: 12345678|772cf00b-84e63d0f-d2d9db34-bba4ccf7_0 is DEAD
2025-10-26T18:06:14.150473Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=5) Received event: NActors::TEvents::TEvPoison
2025-10-26T18:06:14.151018Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015000:4308] destroyed
2025-10-26T18:06:14.151067Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateIdle] TPartition::DropOwner.
Finish: 0 
===Writer started
2025-10-26T18:06:14.157735Z node 3 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:14.157766Z node 3 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2025-10-26T18:06:14.158323Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } }
2025-10-26T18:06:14.158488Z node 3 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } from ipv6:[::1]:36692
2025-10-26T18:06:14.158505Z node 3 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36692 proto=v1  topic=topic1 durationSec=0
2025-10-26T18:06:14.158520Z node 3 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:14.158710Z node 3 :PQ_METACACHE DEBUG: Handle describe topics
2025-10-26T18:06:14.158724Z node 3 :PQ_METACACHE DEBUG: SendSchemeCacheRequest
2025-10-26T18:06:14.158773Z node 3 :PQ_METACACHE DEBUG: send request for 1 topics, got 1 requests infly, db = ""
2025-10-26T18:06:14.159214Z node 3 :PQ_METACACHE DEBUG: Handle SchemeCache response: result# { ErrorCount: 0 DatabaseName:  DomainOwnerId: 0 Instant: 4 ResultSet [{ Path: Root/PQ/rt3.dc1--topic1 TableId: [72057594046644480:9:0] RequestType: ByPath Operation: OpList RedirectRequired: true ShowPrivatePath: false SyncVersion: true Status: Ok Kind: KindTopic DomainInfo { DomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] ResourcesDomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] Params { Version: 1 PlanResolution: 7 Coordinators: 72057594046316545 TimeCastBucketsPerMediator: 2 Mediators: 72057594046382081 } ServerlessComputeResourcesMode: (empty maybe) } }] }
2025-10-26T18:06:14.159288Z node 3 :PQ_METACACHE DEBUG: Got describe topics SC response
2025-10-26T18:06:14.160675Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2025-10-26T18:06:14.160823Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-26T18:06:14.160836Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-26T18:06:14.160846Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-26T18:06:14.160865Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:14.163393Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:14.170800Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) RequestPQRB
2025-10-26T18:06:14.171454Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015023:4304] connected; active server actors: 1
2025-10-26T18:06:14.171842Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) Received partition 6 from PQRB for SourceId=source1
2025-10-26T18:06:14.171868Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:14.172344Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015023:4304] disconnected; active server actors: 1
2025-10-26T18:06:14.172369Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015023:4304] disconnected no session
2025-10-26T18:06:14.185864Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:14.185936Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) ReplyResult: Partition=6, SeqNo=(NULL)
2025-10-26T18:06:14.185956Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015005:4304] (SourceId=source1, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:14.185996Z node 3 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 6 expectedGeneration: (NULL)
2025-10-26T18:06:14.187968Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593370981015031:4304], now have 1 active actors on pipe
2025-10-26T18:06:14.188365Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 4, Generation: 1
2025-10-26T18:06:14.188710Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.188742Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.188828Z node 4 :PERSQUEUE INFO: new Cookie source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 generated for partition 6 topic 'rt3.dc1--topic1' owner source1
2025-10-26T18:06:14.188929Z node 4 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 6
2025-10-26T18:06:14.188997Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.189828Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.189855Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.190086Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 0  requestId: <none> cookie: 0
request: { write_request { sequence_numbers: 2 created_at_ms: 1761501974191 sent_at_ms: 1761501974191 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue1" } }
2025-10-26T18:06:14.190527Z node 3 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 6 MaxSeqNo: 0 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0
2025-10-26T18:06:14.192078Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.192358Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.192940Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.192965Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.193059Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 0  requestId: <none> cookie: 1
2025-10-26T18:06:14.193427Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
2025-10-26T18:06:14.194128Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.194153Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.194482Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 6 SourceId: '\0source1' SeqNo: 2 partNo : 0 messageNo: 1 size 104 offset: -1
2025-10-26T18:06:14.194700Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob processing sourceId '\0source1' seqNo 2 partNo 0
2025-10-26T18:06:14.196472Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob complete sourceId '\0source1' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 179 count 1 nextOffset 1 batches 1
2025-10-26T18:06:14.197070Z node 4 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 6 compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 d0000000006_00000000000000000000_00000_0000000001_00000| size 167 WTime 1761501974196
2025-10-26T18:06:14.197276Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.200969Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.201016Z node 4 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 6
2025-10-26T18:06:14.201055Z node 4 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 6, SeqNo: 2, partNo: 0, Offset: 0 is stored on disk
2025-10-26T18:06:14.201195Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:14.201220Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 user user send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-10-26T18:06:14.201306Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 1  requestId: <none> cookie: 1
2025-10-26T18:06:14.201435Z node 4 :PERSQUEUE DEBUG: read cookie 0 Topic 'rt3.dc1--topic1' partition 6 user user offset 0 count 1 size 1024000 endOffset 1 max time lag 0ms effective offset 0
2025-10-26T18:06:14.201460Z node 4 :PERSQUEUE DEBUG: read cookie 0 added 0 blobs, size 0 count 0 last offset 0
2025-10-26T18:06:14.201488Z node 4 :PERSQUEUE DEBUG: Reading cookie 0. All data is from uncompacted head.
2025-10-26T18:06:14.201509Z node 4 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:14.201576Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 user user readTimeStamp done, result 1761501974194 queuesize 0 startOffset 0
2025-10-26T18:06:14.202306Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
request: { write_request { sequence_numbers: 3 created_at_ms: 1761501974203 sent_at_ms: 1761501974203 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue1" } }
2025-10-26T18:06:14.203784Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.204078Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.204612Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.204663Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.204757Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 2  requestId: <none> cookie: 2
2025-10-26T18:06:14.205246Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
2025-10-26T18:06:14.205746Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.205769Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.205828Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 6 SourceId: '\0source1' SeqNo: 3 partNo : 0 messageNo: 3 size 104 offset: -1
2025-10-26T18:06:14.206022Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob processing sourceId '\0source1' seqNo 3 partNo 0
2025-10-26T18:06:14.248477Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob complete sourceId '\0source1' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 179 count 1 nextOffset 2 batches 1
2025-10-26T18:06:14.248972Z node 4 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 6 compactOffset 1,1 HeadOffset 0 endOffset 1 curOffset 2 d0000000006_00000000000000000001_00000_0000000001_00000| size 167 WTime 1761501974248
2025-10-26T18:06:14.249188Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.253536Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
request: { write_request { sequence_numbers: 4 created_at_ms: 1761501974254 sent_at_ms: 1761501974254 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue1" } }
2025-10-26T18:06:14.252979Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.253019Z node 4 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 6
2025-10-26T18:06:14.253055Z node 4 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 6, SeqNo: 3, partNo: 0, Offset: 1 is stored on disk
2025-10-26T18:06:14.253114Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 3  requestId: <none> cookie: 2
2025-10-26T18:06:14.258163Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.258516Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.259006Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.259042Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.259179Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 4  requestId: <none> cookie: 3
2025-10-26T18:06:14.259386Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
2025-10-26T18:06:14.259774Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.259801Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.259850Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 6 SourceId: '\0source1' SeqNo: 4 partNo : 0 messageNo: 5 size 104 offset: -1
2025-10-26T18:06:14.260043Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob processing sourceId '\0source1' seqNo 4 partNo 0
2025-10-26T18:06:14.261583Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob complete sourceId '\0source1' seqNo 4 partNo 0 FormedBlobsCount 0 NewHead: Offset 2 PartNo 0 PackedSize 179 count 1 nextOffset 3 batches 1
2025-10-26T18:06:14.262132Z node 4 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 6 compactOffset 2,1 HeadOffset 0 endOffset 2 curOffset 3 d0000000006_00000000000000000002_00000_0000000001_00000| size 167 WTime 1761501974262
2025-10-26T18:06:14.262318Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.267441Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.267485Z node 4 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 6
2025-10-26T18:06:14.267518Z node 4 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 6, SeqNo: 4, partNo: 0, Offset: 2 is stored on disk
2025-10-26T18:06:14.267678Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 5  requestId: <none> cookie: 3
2025-10-26T18:06:14.267942Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
request: { write_request { sequence_numbers: 5 created_at_ms: 1761501974268 sent_at_ms: 1761501974268 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue1" } }
2025-10-26T18:06:14.269945Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.270260Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.271221Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
2025-10-26T18:06:14.270839Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.270886Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.270984Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 6  requestId: <none> cookie: 4
2025-10-26T18:06:14.271604Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.271619Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.271666Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 6 SourceId: '\0source1' SeqNo: 5 partNo : 0 messageNo: 7 size 104 offset: -1
2025-10-26T18:06:14.271835Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob processing sourceId '\0source1' seqNo 5 partNo 0
2025-10-26T18:06:14.277645Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 part blob complete sourceId '\0source1' seqNo 5 partNo 0 FormedBlobsCount 0 NewHead: Offset 3 PartNo 0 PackedSize 179 count 1 nextOffset 4 batches 1
2025-10-26T18:06:14.278150Z node 4 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 6 compactOffset 3,1 HeadOffset 0 endOffset 3 curOffset 4 d0000000006_00000000000000000003_00000_0000000001_00000| size 167 WTime 1761501974277
2025-10-26T18:06:14.278342Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.283509Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.283551Z node 4 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 6
2025-10-26T18:06:14.283593Z node 4 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 6, SeqNo: 5, partNo: 0, Offset: 3 is stored on disk
2025-10-26T18:06:14.283776Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 7  requestId: <none> cookie: 4
2025-10-26T18:06:14.284253Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::IEventHandle
2025-10-26T18:06:14.290021Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 grpc read done: success: 0 data: 
2025-10-26T18:06:14.290051Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 grpc read failed
2025-10-26T18:06:14.290271Z node 3 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0
2025-10-26T18:06:14.290297Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source1|127ff47a-7970923c-7ecf5bdd-c83fff9a_0 is DEAD
2025-10-26T18:06:14.290623Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=6) Received event: NActors::TEvents::TEvPoison
1 0 
2025-10-26T18:06:14.291233Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [3:7565593370981015031:4304] destroyed
2025-10-26T18:06:14.291294Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::DropOwner.
2025-10-26T18:06:14.298276Z node 3 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:14.298317Z node 3 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2025-10-26T18:06:14.301855Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "12345678" }
2025-10-26T18:06:14.302009Z node 3 :PQ_WRITE_PROXY INFO: session request cookie: 3 topic: "topic1" message_group_id: "12345678" from ipv6:[::1]:36692
2025-10-26T18:06:14.302040Z node 3 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36692 proto=v1  topic=topic1 durationSec=0
2025-10-26T18:06:14.302054Z node 3 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:14.302100Z node 3 :PQ_METACACHE DEBUG: Handle describe topics
2025-10-26T18:06:14.302117Z node 3 :PQ_METACACHE DEBUG: SendSchemeCacheRequest
2025-10-26T18:06:14.302185Z node 3 :PQ_METACACHE DEBUG: send request for 1 topics, got 1 requests infly, db = ""
2025-10-26T18:06:14.302655Z node 3 :PQ_METACACHE DEBUG: Handle SchemeCache response: result# { ErrorCount: 0 DatabaseName:  DomainOwnerId: 0 Instant: 5 ResultSet [{ Path: Root/PQ/rt3.dc1--topic1 TableId: [72057594046644480:9:0] RequestType: ByPath Operation: OpList RedirectRequired: true ShowPrivatePath: false SyncVersion: true Status: Ok Kind: KindTopic DomainInfo { DomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] ResourcesDomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] Params { Version: 1 PlanResolution: 7 Coordinators: 72057594046316545 TimeCastBucketsPerMediator: 2 Mediators: 72057594046382081 } ServerlessComputeResourcesMode: (empty maybe) } }] }
2025-10-26T18:06:14.302766Z node 3 :PQ_METACACHE DEBUG: Got describe topics SC response
2025-10-26T18:06:14.306765Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2025-10-26T18:06:14.306917Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-26T18:06:14.306928Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-26T18:06:14.306939Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-26T18:06:14.306960Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015043:4334] (SourceId=12345678, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:14.308845Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015043:4334] (SourceId=12345678, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:14.315976Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015043:4334] (SourceId=12345678, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:14.328383Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015043:4334] (SourceId=12345678, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:14.328437Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015043:4334] (SourceId=12345678, PreferedPartition=(NULL)) ReplyResult: Partition=5, SeqNo=0
2025-10-26T18:06:14.328457Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015043:4334] (SourceId=12345678, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:14.328484Z node 3 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 5 expectedGeneration: (NULL)
2025-10-26T18:06:14.329414Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=5) TEvClientConnected Status OK, TabletId: 72075186224037893, NodeId 3, Generation: 1
2025-10-26T18:06:14.329474Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015068:4334], now have 1 active actors on pipe
2025-10-26T18:06:14.329574Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.329595Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 5
2025-10-26T18:06:14.329666Z node 3 :PERSQUEUE INFO: new Cookie 12345678|6793a9d7-213a2623-4101cf3a-dca0ae22_0 generated for partition 5 topic 'rt3.dc1--topic1' owner 12345678
2025-10-26T18:06:14.329769Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 5
2025-10-26T18:06:14.329826Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 5 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.329983Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.329997Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 5
2025-10-26T18:06:14.330064Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 5 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.330184Z node 3 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 5 MaxSeqNo: 0 sessionId: 12345678|6793a9d7-213a2623-4101cf3a-dca0ae22_0
2025-10-26T18:06:14.334759Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: 12345678|6793a9d7-213a2623-4101cf3a-dca0ae22_0 grpc read done: success: 0 data: 
2025-10-26T18:06:14.334784Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: 12345678|6793a9d7-213a2623-4101cf3a-dca0ae22_0 grpc read failed
Finish: 0 
2025-10-26T18:06:14.336602Z node 3 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 3 sessionId: 12345678|6793a9d7-213a2623-4101cf3a-dca0ae22_0
2025-10-26T18:06:14.336633Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: 12345678|6793a9d7-213a2623-4101cf3a-dca0ae22_0 is DEAD
2025-10-26T18:06:14.336958Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=5) Received event: NActors::TEvents::TEvPoison
2025-10-26T18:06:14.337245Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015068:4334] destroyed
2025-10-26T18:06:14.337287Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateIdle] TPartition::DropOwner.
2025-10-26T18:06:14.346072Z node 3 :PQ_WRITE_PROXY DEBUG: new grpc connection
2025-10-26T18:06:14.346106Z node 3 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2025-10-26T18:06:14.349349Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source2" session_meta { key: "key" value: "value" } }
2025-10-26T18:06:14.349551Z node 3 :PQ_WRITE_PROXY INFO: session request cookie: 4 topic: "topic1" message_group_id: "source2" session_meta { key: "key" value: "value" } from ipv6:[::1]:36692
2025-10-26T18:06:14.349568Z node 3 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:36692 proto=v1  topic=topic1 durationSec=0
2025-10-26T18:06:14.349580Z node 3 :PQ_WRITE_PROXY INFO: init check schema
2025-10-26T18:06:14.349754Z node 3 :PQ_METACACHE DEBUG: Handle describe topics
2025-10-26T18:06:14.349769Z node 3 :PQ_METACACHE DEBUG: SendSchemeCacheRequest
2025-10-26T18:06:14.349824Z node 3 :PQ_METACACHE DEBUG: send request for 1 topics, got 1 requests infly, db = ""
2025-10-26T18:06:14.350301Z node 3 :PQ_METACACHE DEBUG: Handle SchemeCache response: result# { ErrorCount: 0 DatabaseName:  DomainOwnerId: 0 Instant: 6 ResultSet [{ Path: Root/PQ/rt3.dc1--topic1 TableId: [72057594046644480:9:0] RequestType: ByPath Operation: OpList RedirectRequired: true ShowPrivatePath: false SyncVersion: true Status: Ok Kind: KindTopic DomainInfo { DomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] ResourcesDomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] Params { Version: 1 PlanResolution: 7 Coordinators: 72057594046316545 TimeCastBucketsPerMediator: 2 Mediators: 72057594046382081 } ServerlessComputeResourcesMode: (empty maybe) } }] }
2025-10-26T18:06:14.350385Z node 3 :PQ_METACACHE DEBUG: Got describe topics SC response
2025-10-26T18:06:14.351367Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2025-10-26T18:06:14.351549Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2025-10-26T18:06:14.351569Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2025-10-26T18:06:14.351579Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2025-10-26T18:06:14.351599Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) StartKqpSession
2025-10-26T18:06:14.353996Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) Select from the table
2025-10-26T18:06:14.360423Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) RequestPQRB
2025-10-26T18:06:14.361036Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015088:4315] connected; active server actors: 1
2025-10-26T18:06:14.361514Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) Received partition 7 from PQRB for SourceId=source2
2025-10-26T18:06:14.361542Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) Update the table
2025-10-26T18:06:14.362033Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015088:4315] disconnected; active server actors: 1
2025-10-26T18:06:14.362058Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015088:4315] disconnected no session
2025-10-26T18:06:14.371119Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-26T18:06:14.371180Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) ReplyResult: Partition=7, SeqNo=(NULL)
2025-10-26T18:06:14.371200Z node 3 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [3:7565593370981015073:4315] (SourceId=source2, PreferedPartition=(NULL)) Start idle
2025-10-26T18:06:14.371227Z node 3 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 7 expectedGeneration: (NULL)
2025-10-26T18:06:14.373490Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) TEvClientConnected Status OK, TabletId: 72075186224037893, NodeId 3, Generation: 1
2025-10-26T18:06:14.373530Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015096:4315], now have 1 active actors on pipe
2025-10-26T18:06:14.374972Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.375009Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.375088Z node 3 :PERSQUEUE INFO: new Cookie source2|915c4325-5de2b46f-b011ea63-555716c8_0 generated for partition 7 topic 'rt3.dc1--topic1' owner source2
2025-10-26T18:06:14.375171Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 7
2025-10-26T18:06:14.375221Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.378197Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.378241Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.378363Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:14.378564Z node 3 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 7 MaxSeqNo: 0 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0
request: { write_request { sequence_numbers: 2 created_at_ms: 1761501974379 sent_at_ms: 1761501974379 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue2" } }
2025-10-26T18:06:14.385787Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.386154Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.386370Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.386407Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.386517Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 0  requestId: <none> cookie: 1
2025-10-26T18:06:14.386582Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-26T18:06:14.386833Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.386859Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.387174Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message topic: rt3.dc1--topic1 partition: 7 SourceId: '\0source2' SeqNo: 2 partNo : 0 messageNo: 1 size 104 offset: -1
2025-10-26T18:06:14.387366Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob processing sourceId '\0source2' seqNo 2 partNo 0
2025-10-26T18:06:14.420068Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob complete sourceId '\0source2' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 179 count 1 nextOffset 1 batches 1
2025-10-26T18:06:14.420603Z node 3 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 7 compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 d0000000007_00000000000000000000_00000_0000000001_00000| size 167 WTime 1761501974420
2025-10-26T18:06:14.420808Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.425570Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.425622Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 7
2025-10-26T18:06:14.425667Z node 3 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source2', Topic: 'rt3.dc1--topic1', Partition: 7, SeqNo: 2, partNo: 0, Offset: 0 is stored on disk
2025-10-26T18:06:14.425730Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 1  requestId: <none> cookie: 1
2025-10-26T18:06:14.425826Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-26T18:06:14.425836Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-26T18:06:14.425844Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 user user send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-10-26T18:06:14.425968Z node 3 :PERSQUEUE DEBUG: read cookie 0 Topic 'rt3.dc1--topic1' partition 7 user user offset 0 count 1 size 1024000 endOffset 1 max time lag 0ms effective offset 0
2025-10-26T18:06:14.425987Z node 3 :PERSQUEUE DEBUG: read cookie 0 added 0 blobs, size 0 count 0 last offset 0
2025-10-26T18:06:14.426015Z node 3 :PERSQUEUE DEBUG: Reading cookie 0. All data is from uncompacted head.
2025-10-26T18:06:14.426037Z node 3 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:14.426106Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 user user readTimeStamp done, result 1761501974386 queuesize 0 startOffset 0
request: { write_request { sequence_numbers: 3 created_at_ms: 1761501974428 sent_at_ms: 1761501974428 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue2" } }
2025-10-26T18:06:14.429976Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.430229Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.430416Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.430450Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.430563Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 2  requestId: <none> cookie: 2
2025-10-26T18:06:14.430634Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-26T18:06:14.430903Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.430933Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.430983Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message topic: rt3.dc1--topic1 partition: 7 SourceId: '\0source2' SeqNo: 3 partNo : 0 messageNo: 3 size 104 offset: -1
2025-10-26T18:06:14.431171Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob processing sourceId '\0source2' seqNo 3 partNo 0
2025-10-26T18:06:14.432693Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob complete sourceId '\0source2' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 179 count 1 nextOffset 2 batches 1
2025-10-26T18:06:14.433203Z node 3 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 7 compactOffset 1,1 HeadOffset 0 endOffset 1 curOffset 2 d0000000007_00000000000000000001_00000_0000000001_00000| size 167 WTime 1761501974433
2025-10-26T18:06:14.433410Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.436187Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.436228Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 7
2025-10-26T18:06:14.436262Z node 3 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source2', Topic: 'rt3.dc1--topic1', Partition: 7, SeqNo: 3, partNo: 0, Offset: 1 is stored on disk
2025-10-26T18:06:14.436329Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 3  requestId: <none> cookie: 2
2025-10-26T18:06:14.436441Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
request: { write_request { sequence_numbers: 4 created_at_ms: 1761501974438 sent_at_ms: 1761501974438 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue2" } }
2025-10-26T18:06:14.438814Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.439078Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.439399Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.439426Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.439512Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 4  requestId: <none> cookie: 3
2025-10-26T18:06:14.439560Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-26T18:06:14.439756Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.439771Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.439820Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message topic: rt3.dc1--topic1 partition: 7 SourceId: '\0source2' SeqNo: 4 partNo : 0 messageNo: 5 size 104 offset: -1
2025-10-26T18:06:14.439978Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob processing sourceId '\0source2' seqNo 4 partNo 0
2025-10-26T18:06:14.441417Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob complete sourceId '\0source2' seqNo 4 partNo 0 FormedBlobsCount 0 NewHead: Offset 2 PartNo 0 PackedSize 179 count 1 nextOffset 3 batches 1
2025-10-26T18:06:14.441950Z node 3 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 7 compactOffset 2,1 HeadOffset 0 endOffset 2 curOffset 3 d0000000007_00000000000000000002_00000_0000000001_00000| size 167 WTime 1761501974441
2025-10-26T18:06:14.442116Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.446638Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.446674Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 7
2025-10-26T18:06:14.446700Z node 3 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source2', Topic: 'rt3.dc1--topic1', Partition: 7, SeqNo: 4, partNo: 0, Offset: 2 is stored on disk
2025-10-26T18:06:14.446839Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 5  requestId: <none> cookie: 3
2025-10-26T18:06:14.446890Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
request: { write_request { sequence_numbers: 5 created_at_ms: 1761501974447 sent_at_ms: 1761501974447 message_sizes: 16 blocks_offsets: 0 blocks_part_numbers: 0 blocks_message_counts: 1 blocks_uncompressed_sizes: 16 blocks_headers: "\000" blocks_data: "valuevaluevalue2" } }
2025-10-26T18:06:14.448200Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-26T18:06:14.448438Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-26T18:06:14.448725Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.448751Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.448832Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 6  requestId: <none> cookie: 4
2025-10-26T18:06:14.448881Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-26T18:06:14.449111Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.449126Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.449171Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message topic: rt3.dc1--topic1 partition: 7 SourceId: '\0source2' SeqNo: 5 partNo : 0 messageNo: 7 size 104 offset: -1
2025-10-26T18:06:14.449334Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob processing sourceId '\0source2' seqNo 5 partNo 0
2025-10-26T18:06:14.450834Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 part blob complete sourceId '\0source2' seqNo 5 partNo 0 FormedBlobsCount 0 NewHead: Offset 3 PartNo 0 PackedSize 179 count 1 nextOffset 4 batches 1
2025-10-26T18:06:14.451343Z node 3 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 7 compactOffset 3,1 HeadOffset 0 endOffset 3 curOffset 4 d0000000007_00000000000000000003_00000_0000000001_00000| size 167 WTime 1761501974450
2025-10-26T18:06:14.451530Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.453977Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.454018Z node 3 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 7
2025-10-26T18:06:14.454055Z node 3 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source2', Topic: 'rt3.dc1--topic1', Partition: 7, SeqNo: 5, partNo: 0, Offset: 3 is stored on disk
2025-10-26T18:06:14.454239Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 7  requestId: <none> cookie: 4
2025-10-26T18:06:14.454304Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-26T18:06:14.455574Z node 3 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 grpc read done: success: 0 data: 
2025-10-26T18:06:14.455595Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 grpc read failed
2025-10-26T18:06:14.455761Z node 3 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0
2025-10-26T18:06:14.455778Z node 3 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source2|915c4325-5de2b46f-b011ea63-555716c8_0 is DEAD
2025-10-26T18:06:14.456088Z node 3 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037893 (partition=7) Received event: NActors::TEvents::TEvPoison
1 0 
===Writer - writes done
2025-10-26T18:06:14.458518Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015096:4315] destroyed
2025-10-26T18:06:14.458572Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::DropOwner.
===Try to get read response
2025-10-26T18:06:14.461789Z node 3 :PQ_READ_PROXY DEBUG: new grpc connection
2025-10-26T18:06:14.461822Z node 3 :PQ_READ_PROXY DEBUG: new session created cookie 1
2025-10-26T18:06:14.473041Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { path: "topic1" } consumer: "user" } }
2025-10-26T18:06:14.474761Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 read init: from# ipv6:[::1]:36692, request# { init_request { topics_read_settings { path: "topic1" } consumer: "user" } }
2025-10-26T18:06:14.475290Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 auth for : user
2025-10-26T18:06:14.475954Z node 3 :PQ_METACACHE DEBUG: Handle describe topics
2025-10-26T18:06:14.475977Z node 3 :PQ_METACACHE DEBUG: SendSchemeCacheRequest
2025-10-26T18:06:14.476031Z node 3 :PQ_METACACHE DEBUG: send request for 1 topics, got 1 requests infly, db = ""
2025-10-26T18:06:14.476515Z node 3 :PQ_METACACHE DEBUG: Handle SchemeCache response: result# { ErrorCount: 0 DatabaseName:  DomainOwnerId: 0 Instant: 7 ResultSet [{ Path: Root/PQ/rt3.dc1--topic1 TableId: [72057594046644480:9:0] RequestType: ByPath Operation: OpList RedirectRequired: true ShowPrivatePath: true SyncVersion: true Status: Ok Kind: KindTopic DomainInfo { DomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] ResourcesDomainKey: [OwnerId: 72057594046644480, LocalPathId: 1] Params { Version: 1 PlanResolution: 7 Coordinators: 72057594046316545 TimeCastBucketsPerMediator: 2 Mediators: 72057594046382081 } ServerlessComputeResourcesMode: (empty maybe) } }] }
2025-10-26T18:06:14.476595Z node 3 :PQ_METACACHE DEBUG: Got describe topics SC response
2025-10-26T18:06:14.477776Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Handle describe topics response
2025-10-26T18:06:14.478013Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 auth is DEAD
2025-10-26T18:06:14.478135Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 auth ok: topics# 1, initDone# 0
2025-10-26T18:06:14.479497Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 register session: topic# rt3.dc1--topic1
Read server response: status: SUCCESS init_response { session_id: "shared/user_3_1_945927665081292278_v1" }
2025-10-26T18:06:14.484920Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015125:4272] connected; active server actors: 1
2025-10-26T18:06:14.485516Z node 4 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer "user" register session for pipe [3:7565593370981015125:4272] session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.485570Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 0
2025-10-26T18:06:14.485627Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=1 (Status=Free, Partitions=[0])
2025-10-26T18:06:14.485648Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 1
2025-10-26T18:06:14.485677Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=2 (Status=Free, Partitions=[1])
2025-10-26T18:06:14.485715Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 2
2025-10-26T18:06:14.485747Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=3 (Status=Free, Partitions=[2])
2025-10-26T18:06:14.485766Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 3
2025-10-26T18:06:14.485793Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=4 (Status=Free, Partitions=[3])
2025-10-26T18:06:14.485813Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 4
2025-10-26T18:06:14.485837Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=5 (Status=Free, Partitions=[4])
2025-10-26T18:06:14.485861Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 5
2025-10-26T18:06:14.485891Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=6 (Status=Free, Partitions=[5])
2025-10-26T18:06:14.485914Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 6
2025-10-26T18:06:14.485938Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=7 (Status=Free, Partitions=[6])
2025-10-26T18:06:14.485954Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 7
2025-10-26T18:06:14.485979Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=8 (Status=Free, Partitions=[7])
2025-10-26T18:06:14.485996Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 8
2025-10-26T18:06:14.486021Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=9 (Status=Free, Partitions=[8])
2025-10-26T18:06:14.486039Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register readable partition 9
2025-10-26T18:06:14.486064Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family created family=10 (Status=Free, Partitions=[9])
2025-10-26T18:06:14.486105Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user register reading session ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:14.486132Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user rebalancing was scheduled
2025-10-26T18:06:14.486214Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing. Sessions=1, Families=10, UnradableFamilies=10 [10 (9), 9 (8), 8 (7), 7 (6), 6 (5), 5 (4), 4 (3), 3 (2), 2 (1), 1 (0), ], RequireBalancing=0 []
2025-10-26T18:06:14.486270Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=10 (Status=Free, Partitions=[9]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=0)
2025-10-26T18:06:14.486328Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 10 status Active partitions [9] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 9 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=1) generation 1 step 1
2025-10-26T18:06:14.486392Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=9 (Status=Free, Partitions=[8]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=1)
2025-10-26T18:06:14.486427Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 9 status Active partitions [8] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 8 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=2) generation 1 step 2
2025-10-26T18:06:14.486463Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=8 (Status=Free, Partitions=[7]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=2)
2025-10-26T18:06:14.486495Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 8 status Active partitions [7] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 7 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=3) generation 1 step 3
2025-10-26T18:06:14.486530Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=7 (Status=Free, Partitions=[6]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=3)
2025-10-26T18:06:14.486560Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 7 status Active partitions [6] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 6 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=4) generation 1 step 4
2025-10-26T18:06:14.486595Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=6 (Status=Free, Partitions=[5]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=4)
2025-10-26T18:06:14.486623Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 6 status Active partitions [5] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 5 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=5) generation 1 step 5
2025-10-26T18:06:14.486656Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=5 (Status=Free, Partitions=[4]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=5)
2025-10-26T18:06:14.486687Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 5 status Active partitions [4] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 4 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=6) generation 1 step 6
2025-10-26T18:06:14.486723Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=4 (Status=Free, Partitions=[3]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=6)
2025-10-26T18:06:14.486752Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 4 status Active partitions [3] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 3 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=7) generation 1 step 7
2025-10-26T18:06:14.486786Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=3 (Status=Free, Partitions=[2]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=7)
2025-10-26T18:06:14.486818Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 3 status Active partitions [2] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 2 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=8) generation 1 step 8
2025-10-26T18:06:14.486861Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=2 (Status=Free, Partitions=[1]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=8)
2025-10-26T18:06:14.486894Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 2 status Active partitions [1] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 1 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=9) generation 1 step 9
2025-10-26T18:06:14.486927Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing family=1 (Status=Free, Partitions=[0]) for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=9)
2025-10-26T18:06:14.486956Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user family 1 status Active partitions [0] session "shared/user_3_1_945927665081292278_v1" sender [3:7565593370981015122:4272] lock partition 0 for ReadingSession "shared/user_3_1_945927665081292278_v1" (Sender=[3:7565593370981015122:4272], Pipe=[3:7565593370981015125:4272], Partitions=[], ActiveFamilyCount=10) generation 1 step 10
2025-10-26T18:06:14.487000Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user start rebalancing. familyCount=10, sessionCount=1, desiredFamilyCount=10, allowPlusOne=0
2025-10-26T18:06:14.487037Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user balancing duration: 0.000799s
2025-10-26T18:06:14.489174Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 9 TabletId: 72075186224037893 Topic: "rt3.dc1--topic1" Generation: 1 Step: 1 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.492104Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593370981015139:4302], now have 1 active actors on pipe
2025-10-26T18:06:14.492132Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593370981015142:4329], now have 1 active actors on pipe
2025-10-26T18:06:14.492148Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593370981015144:4313], now have 1 active actors on pipe
2025-10-26T18:06:14.492162Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593370981015145:4334], now have 1 active actors on pipe
2025-10-26T18:06:14.492180Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [3:7565593370981015137:4338], now have 1 active actors on pipe
2025-10-26T18:06:14.493808Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.493839Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:14.493864Z node 4 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015139:4302]
2025-10-26T18:06:14.493926Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.493937Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 3
2025-10-26T18:06:14.493949Z node 4 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015142:4329]
2025-10-26T18:06:14.489339Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 8 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 2 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.489481Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 7 TabletId: 72075186224037893 Topic: "rt3.dc1--topic1" Generation: 1 Step: 3 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.489585Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 6 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 4 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.489701Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 5 TabletId: 72075186224037893 Topic: "rt3.dc1--topic1" Generation: 1 Step: 5 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.489809Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 4 TabletId: 72075186224037893 Topic: "rt3.dc1--topic1" Generation: 1 Step: 6 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.489912Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 3 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 7 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.490016Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 2 TabletId: 72075186224037893 Topic: "rt3.dc1--topic1" Generation: 1 Step: 8 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.490118Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 1 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 9 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.490229Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 assign: record# { Partition: 0 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 10 Session: "shared/user_3_1_945927665081292278_v1" ClientId: "user" PipeClient { RawX1: 7565593370981015125 RawX2: 4503612512276656 } Path: "/Root/PQ/rt3.dc1--topic1" }
2025-10-26T18:06:14.490309Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1)
2025-10-26T18:06:14.490391Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2)
2025-10-26T18:06:14.490438Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3)
2025-10-26T18:06:14.490481Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4)
2025-10-26T18:06:14.490522Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5)
2025-10-26T18:06:14.490569Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6)
2025-10-26T18:06:14.490611Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7)
2025-10-26T18:06:14.490651Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8)
2025-10-26T18:06:14.490691Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9)
2025-10-26T18:06:14.490731Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10)
2025-10-26T18:06:14.491321Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037893 Generation: 1
2025-10-26T18:06:14.491359Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015141:4288], now have 1 active actors on pipe
2025-10-26T18:06:14.491376Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015143:4331], now have 1 active actors on pipe
2025-10-26T18:06:14.491390Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015136:4305], now have 1 active actors on pipe
2025-10-26T18:06:14.491405Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015138:4339], now have 1 active actors on pipe
2025-10-26T18:06:14.491423Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server connected, pipe [3:7565593370981015140:4321], now have 1 active actors on pipe
2025-10-26T18:06:14.491452Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037893 Generation: 1
2025-10-26T18:06:14.491479Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037893 Generation: 1
2025-10-26T18:06:14.491505Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037893 Generation: 1
2025-10-26T18:06:14.491535Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037893 Generation: 1
2025-10-26T18:06:14.491748Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.491768Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 5
2025-10-26T18:06:14.491788Z node 3 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015140:4321]
2025-10-26T18:06:14.491829Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.491837Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 4
2025-10-26T18:06:14.491848Z node 3 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015141:4288]
2025-10-26T18:06:14.491868Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.491875Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 2
2025-10-26T18:06:14.491887Z node 3 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015143:4331]
2025-10-26T18:06:14.491905Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.491913Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 9
2025-10-26T18:06:14.491924Z node 3 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015136:4305]
2025-10-26T18:06:14.491946Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.491955Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:14.491966Z node 3 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015138:4339]
2025-10-26T18:06:14.492053Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 7 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.492182Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.492240Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:5 with generation 1
2025-10-26T18:06:14.492284Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:6 with generation 1
2025-10-26T18:06:14.492304Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:8 with generation 1
2025-10-26T18:06:14.492319Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:1 with generation 1
2025-10-26T18:06:14.492332Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:3 with generation 1
2025-10-26T18:06:14.492829Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:14.492891Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:14.492946Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:14.493003Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:14.493091Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2025-10-26T18:06:14.493151Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 5 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.493284Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 4 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.493386Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 2 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.493476Z node 3 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 9 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.493537Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.493594Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.493634Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.493678Z node 3 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.494763Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 7, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.494812Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.494940Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 4 WriteTimestampMS: 1761501974386 CreateTimestampMS: 1761501974379 SizeLag: 668 WriteTimestampEstimateMS: 1761501974458 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.494968Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) EndOffset 4 readOffset 0 committedOffset 0
2025-10-26T18:06:14.495032Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.493981Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.493995Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-26T18:06:14.494007Z node 4 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015144:4313]
2025-10-26T18:06:14.494038Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.494048Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2025-10-26T18:06:14.494058Z node 4 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015145:4334]
2025-10-26T18:06:14.494090Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:14.494099Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 8
2025-10-26T18:06:14.494110Z node 4 :PERSQUEUE DEBUG: Created session shared/user_3_1_945927665081292278_v1 on pipe: [3:7565593370981015137:4338]
2025-10-26T18:06:14.494178Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.494294Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 8 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.494355Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.494403Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.494959Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 6 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.495064Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 3 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.495149Z node 4 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user session is set to 0 (startOffset 0) session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:14.495208Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.495253Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.495288Z node 4 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2025-10-26T18:06:14.496083Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:4 with generation 1
2025-10-26T18:06:14.496120Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:7 with generation 1
2025-10-26T18:06:14.496143Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:9 with generation 1
2025-10-26T18:06:14.496164Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:10 with generation 1
2025-10-26T18:06:14.496188Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_3_1_945927665081292278_v1:2 with generation 1
2025-10-26T18:06:14.499282Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 5, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.499372Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 4, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.499432Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 2, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.499494Z node 3 :PERSQUEUE DEBUG: [PQ: 72075186224037893, Partition: 9, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.499535Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 5 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.499571Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 4 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.499592Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 2 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.499610Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 9 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.499733Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972696 CreateTimestampMS: 1761501972696 SizeLag: 0 WriteTimestampEstimateMS: 1761501974413 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.499765Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.499846Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972707 CreateTimestampMS: 1761501972707 SizeLag: 0 WriteTimestampEstimateMS: 1761501974422 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.499864Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.499926Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972689 CreateTimestampMS: 1761501972689 SizeLag: 0 WriteTimestampEstimateMS: 1761501974405 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.499942Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.499999Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972684 CreateTimestampMS: 1761501972684 SizeLag: 0 WriteTimestampEstimateMS: 1761501974399 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.500015Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.500082Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.500360Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.500389Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.500407Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.503559Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 3, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.503649Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 1, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.503691Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 3 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.503739Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.503799Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 0, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.503858Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 8, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.504156Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972689 CreateTimestampMS: 1761501972689 SizeLag: 0 WriteTimestampEstimateMS: 1761501974406 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.504199Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.504291Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972684 CreateTimestampMS: 1761501972684 SizeLag: 0 WriteTimestampEstimateMS: 1761501974406 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.504309Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.504377Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972693 CreateTimestampMS: 1761501972693 SizeLag: 0 WriteTimestampEstimateMS: 1761501974406 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.504396Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.504457Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 4 WriteTimestampMS: 1761501974194 CreateTimestampMS: 1761501974191 SizeLag: 668 WriteTimestampEstimateMS: 1761501974449 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.504472Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) EndOffset 4 readOffset 0 committedOffset 0
2025-10-26T18:06:14.504517Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.504783Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.504808Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.504826Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.504919Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1761501972684 CreateTimestampMS: 1761501972684 SizeLag: 0 WriteTimestampEstimateMS: 1761501974406 } Cookie: 18446744073709551615 }
2025-10-26T18:06:14.504941Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7) EndOffset 0 readOffset 0 committedOffset 0
2025-10-26T18:06:14.504974Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 sending to client partition status
2025-10-26T18:06:14.503899Z node 4 :PERSQUEUE DEBUG: [PQ: 72075186224037892, Partition: 6, State: StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-26T18:06:14.503931Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.503956Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 8 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.503974Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2025-10-26T18:06:14.546135Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:14.553057Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:14.805344Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:14.812458Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:15.202068Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:15.202090Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:15.284494Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:15.284527Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:15.553889Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:15.560040Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:15.813180Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:15.822219Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:16.513707Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:16.513731Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:16.561776Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:16.568158Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:16.656237Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:16.656270Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:16.823200Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:16.830692Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:17.206013Z node 3 :FLAT_TX_SCHEMESHARD WARN: Cannot get console configs
2025-10-26T18:06:17.206050Z node 3 :IMPORT WARN: Table profiles were not loaded
2025-10-26T18:06:17.569853Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:17.585004Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:17.829063Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:17.839110Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:17.905953Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:17.905980Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:17.986312Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:17.986356Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:18.585866Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:18.605592Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:18.839313Z node 4 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:18.846015Z node 4 :PQ_METACACHE DEBUG: Metacache: reset
2025-10-26T18:06:19.258339Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:19.258374Z node 3 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:19.366163Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate
2025-10-26T18:06:19.366199Z node 4 :PQ_METACACHE DEBUG: HandleClustersUpdate LocalCluster !LocalCluster.empty()
2025-10-26T18:06:19.485337Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.485591Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# a022c036-a092cee5-73ec2e2f-540145ca
2025-10-26T18:06:19.485660Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.485798Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 1c8de818-a4b834af-92f1ba04-891ba45b
2025-10-26T18:06:19.488347Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user Reading of the partition 7 was started by user.
2025-10-26T18:06:19.485943Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.486037Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 5dd59772-521bf515-8ccfd09e-75d076ea
2025-10-26T18:06:19.486176Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.486256Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 851a2598-19c933d7-52a7f479-a580c6a3
2025-10-26T18:06:19.486407Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.486495Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 6209bbd6-c7ab7571-d68143a2-ba5ee06f
2025-10-26T18:06:19.486643Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.486717Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 9b514a38-e4c173dc-8054c1c1-74a9b0df
2025-10-26T18:06:19.486796Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.486861Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 17d9d902-726eb3d7-34db50b5-6c5843fb
2025-10-26T18:06:19.486973Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.487044Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# d900f38e-88130cb0-c501db9-d8173783
2025-10-26T18:06:19.487174Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.487243Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# b1a6b865-66f97de9-1647d734-b06c1cb4
2025-10-26T18:06:19.487321Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { read_request { bytes_size: 256000 } }
2025-10-26T18:06:19.487383Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got read request: guid# 9e1f6cce-75fdb4cb-4875e4c2-ce4bd2c7
2025-10-26T18:06:19.487492Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 3 } }
2025-10-26T18:06:19.487612Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.487667Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) EndOffset 4 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.487697Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) ready for read with readOffset 0 endOffset 4
2025-10-26T18:06:19.487772Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3), readOffset# 0, endOffset# 4, WTime# 1761501974386, sizeLag# 668
2025-10-26T18:06:19.487792Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1TEvPartitionReady. Aval parts: 1
2025-10-26T18:06:19.487842Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 performing read request: guid# 4773c884-5fd3c4ed-75ab6532-ec655f5b, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3), count# 4, size# 801, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-26T18:06:19.487932Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3)maxCount 4 maxSize 801 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 4 ClientCommitOffset 0 committedOffset 0 Guid 4773c884-5fd3c4ed-75ab6532-ec655f5b
2025-10-26T18:06:19.488059Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 5 } }
2025-10-26T18:06:19.488166Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.488191Z node 3 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:19.488203Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.488214Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 got client message batch for topic 'rt3.dc1--topic1' partition 7
2025-10-26T18:06:19.488232Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 5(assignId:5) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.488271Z node 3 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2025-10-26T18:06:19.488339Z node 3 :PERSQUEUE DEBUG: read cookie 1 Topic 'rt3.dc1--topic1' partition 7 user user offset 0 count 4 size 801 endOffset 4 max time lag 0ms effective offset 0
2025-10-26T18:06:19.488354Z node 3 :PERSQUEUE DEBUG: read cookie 1 added 0 blobs, size 0 count 0 last offset 0
2025-10-26T18:06:19.488404Z node 3 :PERSQUEUE DEBUG: Reading cookie 1. All data is from uncompacted head.
2025-10-26T18:06:19.488420Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 6 } }
2025-10-26T18:06:19.488423Z node 3 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:19.488494Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.488568Z node 3 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 7 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:19.488568Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.488594Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 4(assignId:6) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.488869Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 8 } }
2025-10-26T18:06:19.488948Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.488990Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.489005Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) initDone 1 event { CmdReadResult { MaxOffset: 4 Result { Offset: 0 Data: "... 104 bytes ..." SourceId: "\000source2" SeqNo: 2 WriteTimestampMS: 1761501974386 CreateTimestampMS: 1761501974379 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } Result { Offset: 1 Data: "... 104 bytes ..." SourceId: "\000source2" SeqNo: 3 WriteTimestampMS: 1761501974431 CreateTimestampMS: 1761501974428 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } Result { Offset: 2 Data: "... 104 bytes ..." SourceId: "\000source2" SeqNo: 4 WriteTimestampMS: 1761501974439 CreateTimestampMS: 1761501974438 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } Result { Offset: 3 Data: "... 104 bytes ..." SourceId: "\000source2" SeqNo: 5 WriteTimestampMS: 1761501974448 CreateTimestampMS: 1761501974447 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 80 RealReadOffset: 3 WaitQuotaTimeMs: 0 } Cookie: 0 }
2025-10-26T18:06:19.489010Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 2(assignId:8) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.489175Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 1 } }
2025-10-26T18:06:19.489248Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.489260Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) wait data in partition inited, cookie 1 from offset4
2025-10-26T18:06:19.489286Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.489290Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3) EndOffset 4 ReadOffset 4 ReadGuid 4773c884-5fd3c4ed-75ab6532-ec655f5b has messages 1
2025-10-26T18:06:19.489305Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 9(assignId:1) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.489387Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 read done: guid# 4773c884-5fd3c4ed-75ab6532-ec655f5b, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 7(assignId:3), size# 738
2025-10-26T18:06:19.489448Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 response to read: guid# 4773c884-5fd3c4ed-75ab6532-ec655f5b
2025-10-26T18:06:19.489670Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Process answer. Aval parts: 0
2025-10-26T18:06:19.490393Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 9 } }
2025-10-26T18:06:19.490510Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.490550Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.490573Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:9) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.490802Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 10 } }
2025-10-26T18:06:19.490885Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.490919Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.490938Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:10) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.491118Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 2 } }
2025-10-26T18:06:19.491199Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.491226Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.491245Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 8(assignId:2) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.491416Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 4 } }
2025-10-26T18:06:19.491489Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.491516Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) EndOffset 4 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.491537Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) ready for read with readOffset 0 endOffset 4
2025-10-26T18:06:19.491586Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4), readOffset# 0, endOffset# 4, WTime# 1761501974194, sizeLag# 668
2025-10-26T18:06:19.491598Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1TEvPartitionReady. Aval parts: 1
2025-10-26T18:06:19.491630Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 performing read request: guid# e88028ee-90c91768-6b8b4b8e-a9914359, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4), count# 4, size# 801, partitionsAsked# 1, maxTimeLag# 0ms
2025-10-26T18:06:19.491713Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4)maxCount 4 maxSize 801 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 4 ClientCommitOffset 0 committedOffset 0 Guid e88028ee-90c91768-6b8b4b8e-a9914359
2025-10-26T18:06:19.491961Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 1, data# { start_partition_session_response { partition_session_id: 7 } }
2025-10-26T18:06:19.492013Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7), readOffset# 0, commitOffset# (empty maybe)
2025-10-26T18:06:19.492038Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset (empty maybe) clientReadOffset 0
2025-10-26T18:06:19.492057Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 3(assignId:7) wait data in partition inited, cookie 1 from offset0
2025-10-26T18:06:19.494359Z node 4 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-26T18:06:19.494395Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 6
2025-10-26T18:06:19.494507Z node 4 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037894] topic rt3.dc1--topic1 consumer user Reading of the partition 6 was started by user.
2025-10-26T18:06:19.494627Z node 4 :PERSQUEUE DEBUG: read cookie 1 Topic 'rt3.dc1--topic1' partition 6 user user offset 0 count 4 size 801 endOffset 4 max time lag 0ms effective offset 0
2025-10-26T18:06:19.494644Z node 4 :PERSQUEUE DEBUG: read cookie 1 added 0 blobs, size 0 count 0 last offset 0
2025-10-26T18:06:19.494681Z node 4 :PERSQUEUE DEBUG: Reading cookie 1. All data is from uncompacted head.
2025-10-26T18:06:19.494696Z node 4 :PERSQUEUE DEBUG: FormAnswer 0
2025-10-26T18:06:19.494832Z node 4 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 6 messageNo: 0  requestId: <none> cookie: 0
2025-10-26T18:06:19.494890Z node 4 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2025-10-26T18:06:19.497557Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) initDone 1 event { CmdReadResult { MaxOffset: 4 Result { Offset: 0 Data: "... 104 bytes ..." SourceId: "\000source1" SeqNo: 2 WriteTimestampMS: 1761501974194 CreateTimestampMS: 1761501974191 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } Result { Offset: 1 Data: "... 104 bytes ..." SourceId: "\000source1" SeqNo: 3 WriteTimestampMS: 1761501974205 CreateTimestampMS: 1761501974203 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } Result { Offset: 2 Data: "... 104 bytes ..." SourceId: "\000source1" SeqNo: 4 WriteTimestampMS: 1761501974259 CreateTimestampMS: 1761501974254 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } Result { Offset: 3 Data: "... 104 bytes ..." SourceId: "\000source1" SeqNo: 5 WriteTimestampMS: 1761501974270 CreateTimestampMS: 1761501974268 UncompressedSize: 16 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 80 RealReadOffset: 3 WaitQuotaTimeMs: 0 } Cookie: 0 }
2025-10-26T18:06:19.497781Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) wait data in partition inited, cookie 1 from offset4
2025-10-26T18:06:19.497814Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4) EndOffset 4 ReadOffset 4 ReadGuid e88028ee-90c91768-6b8b4b8e-a9914359 has messages 1
2025-10-26T18:06:19.497956Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 read done: guid# e88028ee-90c91768-6b8b4b8e-a9914359, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 6(assignId:4), size# 731
2025-10-26T18:06:19.497989Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 response to read: guid# e88028ee-90c91768-6b8b4b8e-a9914359
2025-10-26T18:06:19.498268Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 Process answer. Aval parts: 0
2025-10-26T18:06:19.500163Z node 3 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read done: success# 0, data# {  }
2025-10-26T18:06:19.500196Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc read failed
2025-10-26T18:06:19.500226Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 grpc closed
2025-10-26T18:06:19.500311Z node 3 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_3_1_945927665081292278_v1 is DEAD
2025-10-26T18:06:19.501404Z node 3 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501448Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015141:4288] destroyed
2025-10-26T18:06:19.501465Z node 3 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501479Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015140:4321] destroyed
2025-10-26T18:06:19.501491Z node 3 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501493Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501501Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015138:4339] destroyed
2025-10-26T18:06:19.501608Z node 4 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015125:4272] disconnected; active server actors: 1
2025-10-26T18:06:19.501512Z node 3 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501516Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501641Z node 4 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037894] topic rt3.dc1--topic1 pipe [3:7565593370981015125:4272] client user disconnected session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501525Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015136:4305] destroyed
2025-10-26T18:06:19.501821Z node 4 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501843Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [3:7565593370981015139:4302] destroyed
2025-10-26T18:06:19.501531Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501860Z node 4 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501545Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501874Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [3:7565593370981015137:4338] destroyed
2025-10-26T18:06:19.501735Z node 3 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501886Z node 4 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501750Z node 3 :PERSQUEUE DEBUG: Tablet 72075186224037893 server disconnected, pipe [3:7565593370981015143:4331] destroyed
2025-10-26T18:06:19.501907Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [3:7565593370981015145:4334] destroyed
2025-10-26T18:06:19.501923Z node 4 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.501937Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [3:7565593370981015144:4313] destroyed
2025-10-26T18:06:19.502371Z node 3 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.502502Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.502594Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.502621Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.502649Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.502898Z node 4 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.502943Z node 4 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [3:7565593370981015142:4329] destroyed
2025-10-26T18:06:19.508824Z node 4 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_3_1_945927665081292278_v1
2025-10-26T18:06:19.600184Z node 3 :PQ_METACACHE DEBUG: Check version rescan
2025-10-26T18:06:19.606417Z node 3 :PQ_METACACHE DEBUG: Metacache: reset
