2025-10-27T11:20:51.132991Z node 8 :METADATA_PROVIDER WARN: log.cpp:841: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[8:7565859991859462342:2069];send_to=[0:7307199536658146131:7762515];
2025-10-27T11:20:51.133098Z node 8 :METADATA_PROVIDER ERROR: log.cpp:841: fline=accessor_snapshot_base.cpp:71;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/ccie/0017c3/r3tmp/tmprxXCOm/pdisk_1.dat
2025-10-27T11:20:51.180191Z node 8 :PQ_READ_PROXY DEBUG: caching_service.cpp:44: Direct read cache: : Created
2025-10-27T11:20:51.183877Z node 8 :KQP_PROXY WARN: kqp_finalize_script_service.cpp:135: [ScriptExecutions] [TKqpFinalizeScriptService] Failed to check script execution tables existence, scheme status: LookupError, path: Root/.metadata/script_executions
2025-10-27T11:20:51.288390Z node 8 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(8, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-10-27T11:20:51.288473Z node 8 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(8, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-10-27T11:20:51.291941Z node 8 :IMPORT WARN: schemeshard_import.cpp:307: Table profiles were not loaded
2025-10-27T11:20:51.309698Z node 8 :HIVE WARN: node_info.cpp:25: HIVE#72057594037968897 Node(8, (0,0,0,0)) VolatileState: Connecting -> Connected
TServer::EnableGrpc on GrpcPort 23917, node 8
2025-10-27T11:20:51.361938Z node 8 :NET_CLASSIFIER WARN: net_classifier.cpp:190: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/ccie/0017c3/r3tmp/yandex5xfcpu.tmp
2025-10-27T11:20:51.361972Z node 8 :NET_CLASSIFIER WARN: net_classifier.cpp:196: will try to initialize from file: /home/runner/.ya/build/build_root/ccie/0017c3/r3tmp/yandex5xfcpu.tmp
2025-10-27T11:20:51.362131Z node 8 :NET_CLASSIFIER WARN: net_classifier.cpp:202: successfully initialized from file: /home/runner/.ya/build/build_root/ccie/0017c3/r3tmp/yandex5xfcpu.tmp
2025-10-27T11:20:51.362321Z node 8 :NET_CLASSIFIER ERROR: net_classifier.cpp:228: got bad distributable configuration
2025-10-27T11:20:51.390204Z node 8 :KQP_PROXY WARN: kqp_finalize_script_service.cpp:135: [ScriptExecutions] [TKqpFinalizeScriptService] Failed to check script execution tables existence, scheme status: PathErrorUnknown, path: Root/.metadata/script_executions
2025-10-27T11:20:51.412592Z INFO: TTestServer started on Port 12639 GrpcPort 23917
TClient is connected to server localhost:12639
PQClient connected to localhost:23917
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
    ChildrenExist: false
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      Pl...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-10-27T11:20:51.703116Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976715657:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_alter_subdomain.cpp:311)
waiting...
waiting...
2025-10-27T11:20:51.729958Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715659:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:686)
waiting...
waiting...
2025-10-27T11:20:51.836134Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__notify.cpp:122: NotifyTxCompletion, unknown transaction, txId: 281474976715660, at schemeshard: 72057594046644480
waiting...
2025-10-27T11:20:52.157936Z node 8 :TX_CONVEYOR ERROR: log.cpp:841: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-10-27T11:20:55.313010Z node 8 :KQP_COMPILE_ACTOR ERROR: kqp_compile_actor.cpp:565: Compilation failed, self: [8:7565860009039332306:2322], 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-27T11:20:55.315607Z node 8 :KQP_SESSION WARN: kqp_session_actor.cpp:2395: SessionId: ydb://session/3?node_id=8&id=ZGZjZGJiNWMtMWVmYzNmOGQtMWRlZTQ4MjktMzdlYjA4M2Q=, ActorId: [8:7565860009039332303:2320], ActorState: ExecuteState, TraceId: 01k8jpcnqf97zzz3yydn7hx9bn, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2025-10-27T11:20:55.316043Z node 8 :PERSQUEUE_CLUSTER_TRACKER ERROR: cluster_tracker.cpp:167: 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-27T11:20:55.329224Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715662:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:686)
2025-10-27T11:20:55.368812Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715663:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:686)
2025-10-27T11:20:55.464057Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976715664:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_create_table.cpp:686)
=== 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-27T11:20:55.759509Z node 8 :KQP_EXECUTER ERROR: kqp_planner.cpp:123: TxId: 281474976715665. Ctx: { TraceId: 01k8jpcnzjfbthd5bvhfhcs3s8, Database: , SessionId: ydb://session/3?node_id=8&id=Y2FhMDgzMzEtY2JmY2FhMGUtYjk3Mjg0MDQtMTYwOTBiMDg=, PoolId: , DatabaseId: /Root}. Database not set, use /Root
=== CheckClustersList. Subcribe to ClusterTracker from [8:7565860009039332585:2579] 
2025-10-27T11:20:56.133066Z node 8 :METADATA_PROVIDER ERROR: log.cpp:841: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[8:7565859991859462342:2069];send_to=[0:7307199536658146131:7762515];
2025-10-27T11:20:56.133181Z node 8 :METADATA_PROVIDER ERROR: log.cpp:841: fline=accessor_snapshot_base.cpp:71;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
=== CheckClustersList. Ok
PQ Client: create topic: rt3.dc1--topic1 with 2 partitions
CallPersQueueGRPC request to localhost:23917
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-27T11:21:00.940584Z node 8 :PERSQUEUE INFO: msgbus_server_persqueue.cpp:1531: 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:23917
MetaRequest {
  CmdCreateTopic {
    Topic: "rt3.dc1--topic1"
    NumPartitions: 2
    Config {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxCounts: 6000000
      }
      LocalDC: true
      Codecs {
        Ids: 0
        Ids: 1
        Ids: 2
        Codecs: "raw"
        Codecs: "gzip"
        Codecs: "lzop"
      }
      Consumers {
        Name: "user"
        ReadFromTimestampsMs: 0
        FormatVersion: 0
        Version: 0
      }
    }
  }
}
CallPersQueueGRPC response:
Status: 129
ProxyErrorCode: 53
SchemeStatus: 1
FlatTxId {
  TxId: 281474976715674
  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-27T11:21:00.956584Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037893][] pipe [8:7565860030514169311:2680] connected; active server actors: 1
2025-10-27T11:21:00.957281Z node 8 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer__balancing.cpp:1517: [72075186224037893][rt3.dc1--topic1] updating configuration. Deleted partitions []. Added partitions [1, 0]
2025-10-27T11:21:00.957844Z node 8 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:940: [72075186224037893][rt3.dc1--topic1] Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2025-10-27T11:21:00.957952Z node 8 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:138: [72075186224037893][rt3.dc1--topic1] BALANCER INIT DONE for rt3.dc1--topic1: (0, 72075186224037892) (1, 72075186224037892) 
2025-10-27T11:21:01.039643Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2962: [PQ: 72075186224037892] Handle TEvInterconnect::TEvNodeInfo
2025-10-27T11:21:01.040482Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2994: [PQ: 72075186224037892] Transactions request. From tx_00000000000000000000, To tx_18446744073709551615
2025-10-27T11:21:01.040682Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:787: [PQ: 72075186224037892] no config, start with empty partitions and default config
2025-10-27T11:21:01.040722Z node 8 :PERSQUEUE NOTICE: pq_impl.cpp:913: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-27T11:21:01.040759Z node 8 :PERSQUEUE INFO: pq_impl.cpp:612: [PQ: 72075186224037892] doesn't have tx writes info
2025-10-27T11:21:01.040980Z node 8 :PERSQUEUE_READ_BALANCER DEBUG: read_balancer.cpp:402: [72075186224037893][rt3.dc1--topic1] TEvClientConnected TabletId 72075186224037892, NodeId 8, Generation 1
2025-10-27T11:21:01.041050Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860030514169354:2434], now have 1 active actors on pipe
2025-10-27T11:21:01.041079Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860030514169308:2679], now have 1 active actors on pipe
2025-10-27T11:21:01.041865Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:3572: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-27T11:21:01.042446Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:1045: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-27T11:21:01.044202Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860034809136678:2719], now have 1 active actors on pipe
2025-10-27T11:21:01.044460Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:3572: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-27T11:21:01.044967Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:1045: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-27T11:21:01.046434Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--topic1:1:Initializer] Start initializing step TInitConfigStep
2025-10-27T11:21:01.046464Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--topic1:0:Initializer] Start initializing step TInitConfigStep
2025-10-27T11:21:01.046484Z node 8 :PERSQUEUE DEBUG: partition.cpp:1277: [72075186224037892][Partition][0][StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-27T11:21:01.046497Z node 8 :PERSQUEUE DEBUG: partition.cpp:1277: [72075186224037892][Partition][1][StateInit] HandleOnInit TEvPQ::TEvProposePartitionConfig
2025-10-27T11:21:01.046778Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--topic1:1:Initializer] Start initializing step TInitInternalFieldsStep
2025-10-27T11:21:01.046948Z node 8 :PERSQUEUE INFO: partition_init.cpp:1095: [72075186224037892][Partition][1][StateInit] bootstrapping 1 [8:7565860034809136684:2435]
2025-10-27T11:21:01.049187Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--topic1:1:Initializer] Start initializing step TInitFieldsStep
2025-10-27T11:21:01.049215Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:61: [rt3.dc1--topic1:1:Initializer] Initializing completed.
2025-10-27T11:21:01.049229Z node 8 :PERSQUEUE INFO: partition.cpp:697: [72075186224037892][Partition][1][StateInit] init complete for topic 'rt3.dc1--topic1' partition 1 generation 1 [8:7565860034809136684:2435]
2025-10-27T11:21:01.049249Z node 8 :PERSQUEUE DEBUG: partition.cpp:711: [72075186224037892][Partition][1][StateInit] 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-27T11:21:01.050452Z node 8 :PERSQUEUE DEBUG: partition.cpp:4312: [72075186224037892][Partition][1][StateIdle] Process pending events. Count 1
2025-10-27T11:21:01.050492Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.050570Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.050586Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:01.050601Z node 8 :PERSQUEUE DEBUG: partition.cpp:2352: [72075186224037892][Partition][1][StateIdle] Still pending for come commits
2025-10-27T11:21:01.050610Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.050617Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.050627Z node 8 :PERSQUEUE DEBUG: partition.cpp:2352: [72075186224037892][Partition][1][StateIdle] Still pending for come commits
2025-10-27T11:21:01.050652Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:907: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-27T11:21:01.050864Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--topic1:0:Initializer] Start initializing step TInitInternalFieldsStep
2025-10-27T11:21:01.051064Z node 8 :PERSQUEUE INFO: partition_init.cpp:1095: [72075186224037892][Partition][0][StateInit] bootstrapping 0 [8:7565860034809136685:2435]
2025-10-27T11:21:01.052855Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:81: [rt3.dc1--topic1:0:Initializer] Start initializing step TInitFieldsStep
2025-10-27T11:21:01.052885Z node 8 :PERSQUEUE DEBUG: partition_init.cpp:61: [rt3.dc1--topic1:0:Initializer] Initializing completed.
2025-10-27T11:21:01.052905Z node 8 :PERSQUEUE INFO: partition.cpp:697: [72075186224037892][Partition][0][StateInit] init complete for topic 'rt3.dc1--topic1' partition 0 generation 1 [8:7565860034809136685:2435]
2025-10-27T11:21:01.052933Z node 8 :PERSQUEUE DEBUG: partition.cpp:711: [72075186224037892][Partition][0][StateInit] 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-27T11:21:01.053940Z node 8 :PERSQUEUE DEBUG: partition.cpp:4312: [72075186224037892][Partition][0][StateIdle] Process pending events. Count 1
2025-10-27T11:21:01.053975Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.054069Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.054087Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][0][StateIdle] Batch completed (1)
2025-10-27T11:21:01.054106Z node 8 :PERSQUEUE DEBUG: partition.cpp:2352: [72075186224037892][Partition][0][StateIdle] Still pending for come commits
2025-10-27T11:21:01.054119Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.054128Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.054140Z node 8 :PERSQUEUE DEBUG: partition.cpp:2352: [72075186224037892][Partition][0][StateIdle] Still pending for come commits
2025-10-27T11:21:01.054172Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:907: [72075186224037892][Partition][0][StateIdle] Topic 'rt3.dc1--topic1' partition 0 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-27T11:21:01.054411Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:01.054651Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:3572: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-27T11:21:01.054787Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037892][Partition][0][StateIdle] No data for blobs compaction
2025-10-27T11:21:01.055827Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:1045: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-27T11:21:01.055960Z node 8 :PERSQUEUE DEBUG: partition.cpp:1381: [72075186224037892][Partition][0][StateIdle] Handle TEvPQ::TEvTxCommit Step 1761564061089, TxId 281474976715674
2025-10-27T11:21:01.055983Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.055994Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.056123Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.056320Z node 8 :PERSQUEUE DEBUG: partition.cpp:1381: [72075186224037892][Partition][1][StateIdle] Handle TEvPQ::TEvTxCommit Step 1761564061089, TxId 281474976715674
2025-10-27T11:21:01.056337Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.056345Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.056434Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.056554Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:01.056592Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:01.057367Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][0][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:01.057615Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][0][StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:01.057643Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.057657Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.057669Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.057692Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037892][Partition][0][StateIdle] No data for blobs compaction
2025-10-27T11:21:01.057844Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:01.058016Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 0 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:01.058038Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.058049Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.058058Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.058075Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:183: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:01.058437Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:398: [PQ: 72075186224037892] Apply new config PartitionConfig { LifetimeSeconds: 86400 LowWatermark: 8388608 SourceIdLifetimeSeconds: 86400 WriteSpeedInBytesPerSecond: 20000000 BurstSize: 20000000 TotalPartitions: 2 SourceIdMaxCounts: 6000000 } PartitionIds: 1 PartitionIds: 0 TopicName: "rt3.dc1--topic1" Version: 0 LocalDC: true Codecs { Ids: 0 Ids: 1 Ids: 2 Codecs: "raw" Codecs: "gzip" Codecs: "lzop" } TopicPath: "/Root/PQ/rt3.dc1--topic1" YcCloudId: "" YcFolderId: "" YdbDatabaseId: "" YdbDatabasePath: "/Root" Partitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } Partitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } AllPartitions { PartitionId: 1 Status: Active CreateVersion: 1 TabletId: 0 } AllPartitions { PartitionId: 0 Status: Active CreateVersion: 1 TabletId: 0 } Consumers { Name: "user" ReadFromTimestampsMs: 0 FormatVersion: 0 Version: 0 Generation: 0 } MonitoringProjectId: ""
2025-10-27T11:21:01.058551Z node 8 :PERSQUEUE NOTICE: pq_impl.cpp:913: [PQ: 72075186224037892] disable metering: reason# billing is not enabled in BillingMeteringConfig
2025-10-27T11:21:01.058862Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:3572: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-27T11:21:01.059571Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:1045: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-27T11:21:01.059657Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:3572: [PQ: 72075186224037892] Send TEvKeyValue::TEvRequest (WRITE_TX_COOKIE)
2025-10-27T11:21:01.060701Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:1045: [PQ: 72075186224037892] Handle TEvKeyValue::TEvResponse (WRITE_TX_COOKIE)
2025-10-27T11:21:01.141071Z node 8 :KQP_EXECUTER ERROR: kqp_planner.cpp:123: TxId: 281474976715677. Ctx: { TraceId: 01k8jpcv9m0jja81n2qxat3xh6, Database: , SessionId: ydb://session/3?node_id=8&id=NjFjNmZiNmMtMmQxOTVlZjItYzgyMjk1YzMtOTNlNzAzMjE=, PoolId: , DatabaseId: /Root}. Database not set, use /Root
2025-10-27T11:21:01.151138Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.151176Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.151190Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.154207Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.154238Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.154251Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
===Query complete
TClient::Ls request: /Root/PQ/rt3.dc1--topic1
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "rt3.dc1--topic1"
    PathId: 9
    SchemeshardId: 72057594046644480
    PathType: EPathTypePersQueueGroup
    CreateFinished: true
    CreateTxId: 281474976715674
    CreateStep: 1761564061089
    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
    }
    ChildrenExist: false
  }
  PersQueueGroup {
    Name: "rt3.dc1--topic1"
    PathId: 9
    TotalGroupCount: 2
    PartitionPerTablet: 5
    PQTabletConfig {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxCounts: 6000000
...
(TRUNCATED)
GetTopicVersionFromPath:  record Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "rt3.dc1--topic1"
    PathId: 9
    SchemeshardId: 72057594046644480
    PathType: EPathTypePersQueueGroup
    CreateFinished: true
    CreateTxId: 281474976715674
    CreateStep: 1761564061089
    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
    }
    ChildrenExist: false
  }
  PersQueueGroup {
    Name: "rt3.dc1--topic1"
    PathId: 9
    TotalGroupCount: 2
    PartitionPerTablet: 5
    PQTabletConfig {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxCounts: 6000000
      }
      LocalDC: true
      Codecs {
        Ids: 0
        Ids: 1
        Ids: 2
        Codecs: "raw"
        Codecs: "gzip"
        Codecs: "lzop"
      }
      YdbDatabasePath: "/Root"
      Consumers {
        Name: "user"
        ReadFromTimestampsMs: 0
        FormatVersion: 0
        Version: 0
      }
    }
    Partitions {
      PartitionId: 0
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 1
      TabletId: 72075186224037892
      Status: Active
    }
    AlterVersion: 1
    BalancerTabletID: 72075186224037893
    NextPartitionId: 2
  }
  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: 6
    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: 2
    PQPartitionsLimit: 1000000
    SchemeLimits {
      MaxDepth: 32
      MaxPaths: 10000
      MaxChildrenInDir: 100000
      MaxAclBytesSize: 10240
      MaxTableColumns: 200
      MaxTableColumnNameLength: 255
      MaxTableKeyColumns: 30
      MaxTableIndices: 20
      MaxShards: 200000
      MaxShardsInPath: 35000
      MaxConsistentCopyTargets: 10000
      MaxPathElementLength: 255
      ExtraPathSymbolsAllowed: "!\"#$%&\'()*+,-.:;<=>?@[\\]^_`{|}~"
      MaxPQPartitions: 1000000
      MaxTableCdcStreams: 5
      MaxExports: 10
      MaxImports: 10
      MaxColumnTableColumns: 10000
    }
  }
}
Path: "/Root/PQ/rt3.dc1--topic1"
 name rt3.dc1--topic1 version1
CallPersQueueGRPC request to localhost:23917
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-27T11:21:01.162681Z node 8 :PERSQUEUE INFO: msgbus_server_persqueue.cpp:1531: proxy answer <none>
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
2025-10-27T11:21:01.251542Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.251582Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.251598Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.254557Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.254589Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.254602Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.351887Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.351928Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.351944Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.354907Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.354940Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.354954Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.452179Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.452216Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.452231Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.455263Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.455298Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.455311Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.552543Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.552577Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.552594Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.555601Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.555629Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.555643Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.652888Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.652918Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.652931Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.655932Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.655964Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.655978Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
CallPersQueueGRPC request to localhost:23917
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-27T11:21:01.665508Z node 8 :PERSQUEUE INFO: msgbus_server_persqueue.cpp:1531: proxy answer <none>
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
2025-10-27T11:21:01.753277Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.753319Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.753335Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.756312Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.756345Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.756358Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.853626Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.853668Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.853685Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.856690Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.856729Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.856742Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:01.953941Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.953974Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.953989Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:01.957010Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:01.957039Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:01.957052Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.054357Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.054393Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.054408Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.057381Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.057428Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.057443Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.154693Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.154730Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.154744Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.157688Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.157719Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.157732Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
CallPersQueueGRPC request to localhost:23917
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2025-10-27T11:21:02.170363Z node 8 :PERSQUEUE INFO: msgbus_server_persqueue.cpp:1531: proxy answer <none>
CallPersQueueGRPC response:
Status: 1
ErrorCode: OK
MetaResponse {
  CmdGetTopicMetadataResult {
    TopicInfo {
      Topic: "rt3.dc1--topic1"
      NumPartitions: 2
      Config {
        PartitionConfig {
          LifetimeSeconds: 86400
          LowWatermark: 8388608
          SourceIdLifetimeSeconds: 86400
          WriteSpeedInBytesPerSecond: 20000000
          BurstSize: 20000000
          SourceIdMaxCounts: 6000000
        }
        Version: 1
        LocalDC: true
        Codecs {
          Ids: 0
          Ids: 1
          Ids: 2
          Codecs: "raw"
          Codecs: "gzip"
          Codecs: "lzop"
        }
        TopicPath: "/Root/PQ/rt3.dc1--topic1"
        YdbDatabasePath: "/Root"
        Consumers {
          Name: "user"
          ReadFromTimestampsMs: 0
          FormatVersion: 0
          Version: 0
        }
      }
      ErrorCode: OK
    }
  }
}
=== Topic created, have version: 1
2025-10-27T11:21:02.175930Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.175975Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 1
2025-10-27T11:21:02.176361Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "12345678" }
2025-10-27T11:21:02.176489Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 1 topic: "topic1" message_group_id: "12345678" from ipv6:[::1]:47518
2025-10-27T11:21:02.176513Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47518 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.176523Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.178021Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 1 sessionId:  describe result for acl check
2025-10-27T11:21:02.178126Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: 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-27T11:21:02.178140Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: 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-27T11:21:02.178149Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: 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-27T11:21:02.178160Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) StartKqpSession
2025-10-27T11:21:02.180994Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) Select from the table
2025-10-27T11:21:02.346454Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.346491Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.346504Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.346556Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.346565Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.346571Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.359609Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:67: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) RequestPQRB
2025-10-27T11:21:02.360323Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104166:2476] connected; active server actors: 1
2025-10-27T11:21:02.360366Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:80: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=12345678
2025-10-27T11:21:02.360380Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) Update the table
2025-10-27T11:21:02.360605Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1665: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104166:2476] disconnected; active server actors: 1
2025-10-27T11:21:02.360626Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1689: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104166:2476] disconnected no session
2025-10-27T11:21:02.446554Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.446587Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.446614Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.446667Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.446676Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.446683Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.541879Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-27T11:21:02.541935Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2025-10-27T11:21:02.541953Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [8:7565860039104104134:2476] (SourceId=12345678, PreferedPartition=(NULL)) Start idle
2025-10-27T11:21:02.541989Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 1 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-27T11:21:02.542568Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860039104104201:2476], now have 1 active actors on pipe
2025-10-27T11:21:02.542572Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 8, Generation: 1
2025-10-27T11:21:02.542623Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.542645Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 0
2025-10-27T11:21:02.542713Z node 8 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie 12345678|82f6ec0b-709dcb9a-6c6b5cfa-dd5d115f_0 generated for partition 0 topic 'rt3.dc1--topic1' owner 12345678
2025-10-27T11:21:02.542758Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.542779Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.542788Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][0][StateIdle] Batch completed (1)
2025-10-27T11:21:02.542828Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.542875Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][0][StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-10-27T11:21:02.542933Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.543067Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.543094Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 0
2025-10-27T11:21:02.543147Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.543273Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 1 partition: 0 MaxSeqNo: 0 sessionId: 12345678|82f6ec0b-709dcb9a-6c6b5cfa-dd5d115f_0
2025-10-27T11:21:02.544110Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 1 sessionId: 12345678|82f6ec0b-709dcb9a-6c6b5cfa-dd5d115f_0 grpc read done: success: 0 data: 
2025-10-27T11:21:02.544127Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:256: session v1 cookie: 1 sessionId: 12345678|82f6ec0b-709dcb9a-6c6b5cfa-dd5d115f_0 grpc read failed
2025-10-27T11:21:02.544244Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:824: session v1 closed cookie: 1 sessionId: 12345678|82f6ec0b-709dcb9a-6c6b5cfa-dd5d115f_0
2025-10-27T11:21:02.544264Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 1 sessionId: 12345678|82f6ec0b-709dcb9a-6c6b5cfa-dd5d115f_0 is DEAD
Finish: 0 
2025-10-27T11:21:02.544555Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-10-27T11:21:02.544663Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2748: [PQ: 72075186224037892] server disconnected, pipe [8:7565860039104104201:2476] destroyed
2025-10-27T11:21:02.544695Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][0][StateIdle] TPartition::DropOwner.
2025-10-27T11:21:02.544728Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.544745Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.544754Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.546793Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.546823Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.546833Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.546881Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.546886Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.546890Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.548738Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.548764Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 2
2025-10-27T11:21:02.549057Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "12345678" }
2025-10-27T11:21:02.549164Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 2 topic: "topic1" message_group_id: "12345678" from ipv6:[::1]:47518
2025-10-27T11:21:02.549184Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47518 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.549194Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.550535Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 2 sessionId:  describe result for acl check
2025-10-27T11:21:02.550656Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: 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-27T11:21:02.550677Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: 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-27T11:21:02.550688Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: 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-27T11:21:02.550715Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [8:7565860039104104205:2491] (SourceId=12345678, PreferedPartition=(NULL)) StartKqpSession
2025-10-27T11:21:02.553535Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [8:7565860039104104205:2491] (SourceId=12345678, PreferedPartition=(NULL)) Select from the table
2025-10-27T11:21:02.562536Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [8:7565860039104104205:2491] (SourceId=12345678, PreferedPartition=(NULL)) Update the table
2025-10-27T11:21:02.569651Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [8:7565860039104104205:2491] (SourceId=12345678, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-27T11:21:02.569717Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [8:7565860039104104205:2491] (SourceId=12345678, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=0
2025-10-27T11:21:02.569740Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [8:7565860039104104205:2491] (SourceId=12345678, PreferedPartition=(NULL)) Start idle
2025-10-27T11:21:02.569779Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 2 sessionId:  partition: 0 expectedGeneration: (NULL)
2025-10-27T11:21:02.570387Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 8, Generation: 1
2025-10-27T11:21:02.570435Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860039104104231:2491], now have 1 active actors on pipe
2025-10-27T11:21:02.570478Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.570508Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 0
2025-10-27T11:21:02.570598Z node 8 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie 12345678|af3e01b5-10f7253e-d00c1332-a24104c0_0 generated for partition 0 topic 'rt3.dc1--topic1' owner 12345678
2025-10-27T11:21:02.570650Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.570682Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.570697Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][0][StateIdle] Batch completed (1)
2025-10-27T11:21:02.570747Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.570800Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][0][StateIdle] TPartition::ReplyOwnerOk. Partition: 0
2025-10-27T11:21:02.570903Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.571048Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.571082Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 0
2025-10-27T11:21:02.571160Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.571313Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 2 partition: 0 MaxSeqNo: 0 sessionId: 12345678|af3e01b5-10f7253e-d00c1332-a24104c0_0
2025-10-27T11:21:02.572501Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 2 sessionId: 12345678|af3e01b5-10f7253e-d00c1332-a24104c0_0 grpc read done: success: 0 data: 
2025-10-27T11:21:02.572529Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:256: session v1 cookie: 2 sessionId: 12345678|af3e01b5-10f7253e-d00c1332-a24104c0_0 grpc read failed
2025-10-27T11:21:02.572713Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:824: session v1 closed cookie: 2 sessionId: 12345678|af3e01b5-10f7253e-d00c1332-a24104c0_0
2025-10-27T11:21:02.572740Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 2 sessionId: 12345678|af3e01b5-10f7253e-d00c1332-a24104c0_0 is DEAD
Finish: 0 
2025-10-27T11:21:02.573108Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2025-10-27T11:21:02.573227Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2748: [PQ: 72075186224037892] server disconnected, pipe [8:7565860039104104231:2491] destroyed
2025-10-27T11:21:02.573266Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][0][StateIdle] TPartition::DropOwner.
2025-10-27T11:21:02.573297Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.573321Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.573337Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.573940Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.573965Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 3
2025-10-27T11:21:02.574536Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 3 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } }
2025-10-27T11:21:02.574739Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 3 topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } from ipv6:[::1]:47518
2025-10-27T11:21:02.574764Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=3 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47518 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.575121Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 3 sessionId:  is DEAD
16 unauthenticated, Unauthenticated access is forbidden, please provide credentials
{  }
2025-10-27T11:21:02.577353Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.577381Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 4
2025-10-27T11:21:02.577718Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } }
2025-10-27T11:21:02.577840Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 4 topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } from ipv6:[::1]:47518
2025-10-27T11:21:02.577857Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=4 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47518 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.577865Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.579178Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 4 sessionId:  describe result for acl check
2025-10-27T11:21:02.579283Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:815: session v1 error cookie: 4 reason: access to topic 'Topic topic1 in dc dc1' denied for 'topic1@builtin' due to 'no WriteTopic rights', Marker# PQ1125 sessionId: 
2025-10-27T11:21:02.579541Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 4 sessionId:  is DEAD
{ status: UNAUTHORIZED issues { message: "access to topic \'Topic topic1 in dc dc1\' denied for \'topic1@builtin\' due to \'no WriteTopic rights\', Marker# PQ1125" issue_code: 500018 severity: 1 } }
BEFORE MODIFY PERMISSIONS
2025-10-27T11:21:02.594967Z node 8 :FLAT_TX_SCHEMESHARD WARN: schemeshard__operation.cpp:183: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpModifyACL, opId: 281474976715686:0, at schemeshard:  72057594046644480, first GetDB called at:  (GetDB first called at /home/runner/actions_runner/_work/ydb/ydb/ydb/core/tx/schemeshard/schemeshard__operation_modify_acl.cpp:101)
2025-10-27T11:21:02.598006Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.598036Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 5
2025-10-27T11:21:02.598863Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } }
2025-10-27T11:21:02.599001Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 5 topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } from ipv6:[::1]:47518
2025-10-27T11:21:02.599019Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=5 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47518 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.599026Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.600394Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 5 sessionId:  describe result for acl check
2025-10-27T11:21:02.600545Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: 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-27T11:21:02.600559Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: 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-27T11:21:02.600566Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: 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-27T11:21:02.600578Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) StartKqpSession
2025-10-27T11:21:02.603306Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) Select from the table
2025-10-27T11:21:02.609306Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:67: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) RequestPQRB
2025-10-27T11:21:02.609625Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104267:2504] connected; active server actors: 1
2025-10-27T11:21:02.609678Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:80: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=source1
2025-10-27T11:21:02.609696Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) Update the table
2025-10-27T11:21:02.610057Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1665: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104267:2504] disconnected; active server actors: 1
2025-10-27T11:21:02.610075Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1689: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104267:2504] disconnected no session
2025-10-27T11:21:02.615613Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-27T11:21:02.615653Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2025-10-27T11:21:02.615667Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [8:7565860039104104251:2504] (SourceId=source1, PreferedPartition=(NULL)) Start idle
2025-10-27T11:21:02.615694Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 5 sessionId:  partition: 1 expectedGeneration: (NULL)
2025-10-27T11:21:02.616164Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 8, Generation: 1
2025-10-27T11:21:02.616203Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860039104104278:2504], now have 1 active actors on pipe
2025-10-27T11:21:02.616236Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.616267Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.616364Z node 8 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 generated for partition 1 topic 'rt3.dc1--topic1' owner source1
2025-10-27T11:21:02.616411Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.616442Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.616456Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.616497Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.616540Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyOwnerOk. Partition: 1
2025-10-27T11:21:02.616599Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.616792Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.616823Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.616896Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.617041Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 5 partition: 1 MaxSeqNo: 0 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0
update user token request: { update_token_request { token: "topic1@builtin" } }
2025-10-27T11:21:02.618147Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 2 created_at_ms: 1761564062619 sent_at_ms: 1761564062619 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-27T11:21:02.619648Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.619981Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.620149Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.620175Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.620261Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2025-10-27T11:21:02.620315Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.620404Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.620420Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.620814Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source1' SeqNo: 2 partNo : 0 messageNo: 1 size 104 offset: -1
2025-10-27T11:21:02.620861Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.620912Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.620944Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.620959Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.621077Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source1' seqNo 2 partNo 0
2025-10-27T11:21:02.621883Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 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-27T11:21:02.621937Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.622492Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 d0000000001_00000000000000000000_00000_0000000001_00000? size 167 WTime 1761564062621
2025-10-27T11:21:02.622661Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.622794Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 0 partNo 0 count 1 size 167
2025-10-27T11:21:02.623743Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 0 count 1 size 167 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.623816Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.623852Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 0 partno 0 count 1 parts 0 suffix '63' size 167
2025-10-27T11:21:02.623884Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.623921Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.623962Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 2, partNo: 0, Offset: 0 is stored on disk
2025-10-27T11:21:02.624180Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:907: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2025-10-27T11:21:02.624209Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:949: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 user user send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2025-10-27T11:21:02.624231Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.624248Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.624260Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.624293Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.624338Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2025-10-27T11:21:02.624424Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.624487Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:864: [72075186224037892][Partition][1][StateIdle] read cookie 3 Topic 'rt3.dc1--topic1' partition 1 user user offset 0 count 1 size 1024000 endOffset 1 max time lag 0ms effective offset 0
2025-10-27T11:21:02.624731Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:1078: [72075186224037892][Partition][1][StateIdle] read cookie 3 added 1 blobs, size 167 count 1 last offset 0, current partition end offset: 1
update user token request: { 2025-10-27T11:21:02.624765Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:1104: [72075186224037892][Partition][1][StateIdle] Reading cookie 3. Send blob request.
2025-10-27T11:21:02.624813Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:497: Got data from cache. Partition 1 offset 0 partno 0 count 1 parts_count 0 source 1 size 167 accessed 0 times before, last time 2025-10-27T11:21:02.000000Z
2025-10-27T11:21:02.624851Z node 8 :PERSQUEUE DEBUG: read.h:126: [72075186224037892][PQCacheProxy]Reading cookie 3. All 1 blobs are from cache.
2025-10-27T11:21:02.624901Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:570: FormAnswer for 1 blobs
2025-10-27T11:21:02.625043Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:487: FormAnswer processing batch offset 0 totakecount 1 count 1 size 147 from pos 0 cbcount 1
update_token_request { token: "topic1@builtin" } }
2025-10-27T11:21:02.625125Z node 8 :PERSQUEUE DEBUG: partition_read.cpp:999: Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp done, result 1761564062620 queuesize 0 startOffset 0
2025-10-27T11:21:02.625270Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:201: PQ Cache (L2). Touched. Tablet '72075186224037892' partition 1 offset 0 partno 0 count 1 parts 0 suffix '63'
2025-10-27T11:21:02.625480Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 3 created_at_ms: 1761564062625 sent_at_ms: 1761564062625 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-27T11:21:02.626405Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.626665Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.626824Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.626856Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.626916Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 2  requestId: <none> cookie: 2
2025-10-27T11:21:02.626966Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.627099Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.627119Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.627180Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source1' SeqNo: 3 partNo : 0 messageNo: 3 size 104 offset: -1
2025-10-27T11:21:02.627220Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.627264Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.627293Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.627313Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.627451Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source1' seqNo 3 partNo 0
2025-10-27T11:21:02.672536Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 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-27T11:21:02.672610Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.673204Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 1,1 HeadOffset 1 endOffset 1 curOffset 2 d0000000001_00000000000000000001_00000_0000000001_00000? size 167 WTime 1761564062673
2025-10-27T11:21:02.673432Z node 8 :PERSQUEUE DEBUG: partition.cpp:2302: [72075186224037892][Partition][1][StateIdle] Writing. Can't process transactions and user actions
2025-10-27T11:21:02.673464Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.673480Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.673493Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.673530Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.673664Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 1 partNo 0 count 1 size 167
2025-10-27T11:21:02.674707Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 1 count 1 size 167 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.674782Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.674836Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.674872Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.674886Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 1 partno 0 count 1 parts 0 suffix '63' size 167
2025-10-27T11:21:02.674912Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 3, partNo: 0, Offset: 1 is stored on disk
2025-10-27T11:21:02.675138Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.675161Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.675173Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.675206Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.675251Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 3  requestId: <none> cookie: 2
2025-10-27T11:21:02.675343Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
update user token request: { update_token_request { token: "topic1@builtin" } }
2025-10-27T11:21:02.676590Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 4 created_at_ms: 1761564062676 sent_at_ms: 1761564062676 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-27T11:21:02.677510Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.677839Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.677999Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.678036Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.678124Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 4  requestId: <none> cookie: 3
2025-10-27T11:21:02.678202Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.678322Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.678340Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.678410Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source1' SeqNo: 4 partNo : 0 messageNo: 5 size 104 offset: -1
2025-10-27T11:21:02.678448Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.678494Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.678521Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.678535Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.678651Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source1' seqNo 4 partNo 0
2025-10-27T11:21:02.679555Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 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-27T11:21:02.679591Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.680202Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 2,1 HeadOffset 2 endOffset 2 curOffset 3 d0000000001_00000000000000000002_00000_0000000001_00000? size 167 WTime 1761564062679
2025-10-27T11:21:02.680369Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.680500Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 2 partNo 0 count 1 size 167
2025-10-27T11:21:02.681455Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 2 count 1 size 167 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.681500Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.681553Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.681582Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 2 partno 0 count 1 parts 0 suffix '63' size 167
2025-10-27T11:21:02.681584Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.681611Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 4, partNo: 0, Offset: 2 is stored on disk
2025-10-27T11:21:02.681832Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.681847Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.681860Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.681896Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.681936Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 5  requestId: <none> cookie: 3
2025-10-27T11:21:02.682017Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
update user token request: { update_token_request { token: "topic1@builtin" } }
2025-10-27T11:21:02.683068Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  update_token_request [content omitted]
request: { write_request { sequence_numbers: 5 created_at_ms: 1761564062683 sent_at_ms: 1761564062683 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-27T11:21:02.683840Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.684105Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.684297Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.684337Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.684425Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 6  requestId: <none> cookie: 4
2025-10-27T11:21:02.684512Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.684631Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.684655Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.684721Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source1' SeqNo: 5 partNo : 0 messageNo: 7 size 104 offset: -1
2025-10-27T11:21:02.684771Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.684824Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.684854Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.684871Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.684987Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source1' seqNo 5 partNo 0
2025-10-27T11:21:02.685848Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 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-27T11:21:02.685900Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.686477Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 3,1 HeadOffset 3 endOffset 3 curOffset 4 d0000000001_00000000000000000003_00000_0000000001_00000? size 167 WTime 1761564062685
2025-10-27T11:21:02.686632Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.686765Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 3 partNo 0 count 1 size 167
2025-10-27T11:21:02.687761Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 3 count 1 size 167 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.687832Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.687884Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 112 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.687898Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 3 partno 0 count 1 parts 0 suffix '63' size 167
2025-10-27T11:21:02.687917Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.687969Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 5, partNo: 0, Offset: 3 is stored on disk
2025-10-27T11:21:02.688195Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.688212Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.688224Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.688261Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.688305Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 7  requestId: <none> cookie: 4
2025-10-27T11:21:02.688409Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.691289Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read done: success: 0 data: 
2025-10-27T11:21:02.691317Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:256: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 grpc read failed
2025-10-27T11:21:02.691595Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:824: session v1 closed cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0
2025-10-27T11:21:02.691621Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 5 sessionId: source1|ef4402e7-ded20f9d-74d71bca-c5015479_0 is DEAD
1 0 
2025-10-27T11:21:02.692105Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2025-10-27T11:21:02.692273Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2748: [PQ: 72075186224037892] server disconnected, pipe [8:7565860039104104278:2504] destroyed
2025-10-27T11:21:02.692316Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][1][StateIdle] TPartition::DropOwner.
2025-10-27T11:21:02.692350Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.692364Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.692378Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.693271Z node 8 :TICKET_PARSER ERROR: ticket_parser_impl.h:1008: Ticket **** (E7252F7C): Could not find correct token validator
2025-10-27T11:21:02.693364Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.693397Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 6
2025-10-27T11:21:02.693858Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 6 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } }
2025-10-27T11:21:02.694027Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 6 topic: "topic1" message_group_id: "source1" session_meta { key: "key" value: "value" } from ipv6:[::1]:47518
2025-10-27T11:21:02.694051Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=6 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47518 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.694327Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 6 sessionId:  is DEAD
16 unauthenticated, Unauthenticated access is forbidden, please provide credentials
{  }
2025-10-27T11:21:02.703686Z :DEBUG: [] MessageGroupId [123] SessionId [] Write session: try to update token
2025-10-27T11:21:02.704404Z :INFO: [] MessageGroupId [123] SessionId [] Write session: Do CDS request
2025-10-27T11:21:02.704445Z :INFO: [] MessageGroupId [123] SessionId [] Start write session. Will connect to endpoint: localhost:23917
2025-10-27T11:21:02.714098Z :DEBUG: [] MessageGroupId [123] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "123" }
2025-10-27T11:21:02.714474Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.714507Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 7
2025-10-27T11:21:02.714851Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 7 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "123" }
2025-10-27T11:21:02.715013Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 7 topic: "topic1" message_group_id: "123" from ipv6:[::1]:47586
2025-10-27T11:21:02.715038Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=7 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47586 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.715057Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.716702Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 7 sessionId:  describe result for acl check
2025-10-27T11:21:02.716871Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: 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-27T11:21:02.716894Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: 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-27T11:21:02.716908Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: 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-27T11:21:02.716929Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) StartKqpSession
2025-10-27T11:21:02.719767Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) Select from the table
2025-10-27T11:21:02.725345Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:67: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) RequestPQRB
2025-10-27T11:21:02.725598Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1653: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104318:2517] connected; active server actors: 1
2025-10-27T11:21:02.725654Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__old_chooser_actor.h:80: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=123
2025-10-27T11:21:02.725671Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) Update the table
2025-10-27T11:21:02.726000Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1665: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104318:2517] disconnected; active server actors: 1
2025-10-27T11:21:02.726027Z node 8 :PERSQUEUE_READ_BALANCER INFO: read_balancer__balancing.cpp:1689: [72075186224037893][rt3.dc1--topic1] pipe [8:7565860039104104318:2517] disconnected no session
2025-10-27T11:21:02.731832Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-27T11:21:02.731877Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2025-10-27T11:21:02.731895Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [8:7565860039104104301:2517] (SourceId=123, PreferedPartition=(NULL)) Start idle
2025-10-27T11:21:02.731928Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 7 sessionId:  partition: 1 expectedGeneration: (NULL)
2025-10-27T11:21:02.732468Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 8, Generation: 1
2025-10-27T11:21:02.732477Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860039104104329:2517], now have 1 active actors on pipe
2025-10-27T11:21:02.732509Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.732532Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.732610Z node 8 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie 123|b2800e03-744245d9-172a15ac-9a218dcc_0 generated for partition 1 topic 'rt3.dc1--topic1' owner 123
2025-10-27T11:21:02.732649Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.732675Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.732691Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.732730Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.732775Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyOwnerOk. Partition: 1
2025-10-27T11:21:02.732830Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.732970Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.733000Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.733092Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.733206Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 7 partition: 1 MaxSeqNo: 0 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0
2025-10-27T11:21:02.733812Z :INFO: [] MessageGroupId [123] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1761564062733 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-10-27T11:21:02.733949Z :INFO: [] MessageGroupId [123] SessionId [] Write session established. Init response: session_id: "123|b2800e03-744245d9-172a15ac-9a218dcc_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
ReadyToAcceptEvent
2025-10-27T11:21:02.734227Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write 1 messages with Id from 1 to 1
ReadyToAcceptEvent
2025-10-27T11:21:02.734774Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session: try to update token
2025-10-27T11:21:02.734840Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Send 1 message(s) (0 left), first sequence number is 1
2025-10-27T11:21:02.735311Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 7 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.735573Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.735669Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.735693Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.735744Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2025-10-27T11:21:02.735793Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.735907Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.735928Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.735987Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\000123' SeqNo: 1 partNo : 0 messageNo: 1 size 92 offset: -1
2025-10-27T11:21:02.736025Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.736068Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.736096Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.736114Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.736218Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\000123' seqNo 1 partNo 0
2025-10-27T11:21:02.763264Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\000123' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 4 PartNo 0 PackedSize 163 count 1 nextOffset 5 batches 1
2025-10-27T11:21:02.763322Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.763825Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 4,1 HeadOffset 4 endOffset 4 curOffset 5 d0000000001_00000000000000000004_00000_0000000001_00000? size 151 WTime 1761564062763
2025-10-27T11:21:02.763978Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.764084Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 4 partNo 0 count 1 size 151
2025-10-27T11:21:02.764905Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 4 count 1 size 151 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.764963Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.765032Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 96 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.765048Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 4 partno 0 count 1 parts 0 suffix '63' size 151
2025-10-27T11:21:02.765067Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.765106Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\000123', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 1, partNo: 0, Offset: 4 is stored on disk
2025-10-27T11:21:02.765292Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.765317Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.765329Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.765360Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.765410Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2025-10-27T11:21:02.765538Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.766295Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session got write response: sequence_numbers: 1 offsets: 4 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 2 queued_in_partition_duration_ms: 27 }
2025-10-27T11:21:02.766343Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session: acknoledged message 1
AcksEvent: { seqNo : 1, State : EES_WRITTEN, offset : 4, partitionId : 1 } write stat: Write time 0.002000s total time in partition queue 0.027000s partition quoted time 0.000000s topic quoted time 0.000000s
Set token user_without_rights@builtin
2025-10-27T11:21:02.766612Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write 1 messages with Id from 2 to 2
ReadyToAcceptEvent
2025-10-27T11:21:02.767108Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session: try to update token
2025-10-27T11:21:02.767192Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session: updating token
2025-10-27T11:21:02.767568Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Send 1 message(s) (0 left), first sequence number is 2
2025-10-27T11:21:02.767851Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 7 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0 grpc read done: success: 1 data:  update_token_request [content omitted]
2025-10-27T11:21:02.768137Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 7 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.768378Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1352: updating token
2025-10-27T11:21:02.768435Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.768519Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.768659Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.768692Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.768756Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 2  requestId: <none> cookie: 2
2025-10-27T11:21:02.768802Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.769178Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 7 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0 describe result for acl check
2025-10-27T11:21:02.769274Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:815: session v1 error cookie: 7 reason: access to topic 'Topic topic1 in dc dc1' denied for 'user_without_rights@builtin' due to 'no WriteTopic rights', Marker# PQ1125 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0
2025-10-27T11:21:02.769496Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 7 sessionId: 123|b2800e03-744245d9-172a15ac-9a218dcc_0 is DEAD
2025-10-27T11:21:02.769821Z :ERROR: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Got error. Status: UNAUTHORIZED, Description: <main>: Error: access to topic 'Topic topic1 in dc dc1' denied for 'user_without_rights@builtin' due to 'no WriteTopic rights', Marker# PQ1125, code: 500018 
2025-10-27T11:21:02.769871Z :ERROR: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session will not restart after a fatal error
2025-10-27T11:21:02.769908Z :INFO: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session will now close
2025-10-27T11:21:02.769966Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session: aborting
2025-10-27T11:21:02.769974Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2025-10-27T11:21:02.770016Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
SessionClosed { Status: UNAUTHORIZED Issues: "<main>: Error: access to topic 'Topic topic1 in dc dc1' denied for 'user_without_rights@builtin' due to 'no WriteTopic rights', Marker# PQ1125, code: 500018 " }
2025-10-27T11:21:02.770048Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.770115Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\000123' SeqNo: 2 partNo : 0 messageNo: 3 size 92 offset: -1
2025-10-27T11:21:02.770190Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2748: [PQ: 72075186224037892] server disconnected, pipe [8:7565860039104104329:2517] destroyed
2025-10-27T11:21:02.770218Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.770254Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.770285Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.770299Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.770406Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\000123' seqNo 2 partNo 0
2025-10-27T11:21:02.770573Z :DEBUG: [] MessageGroupId [123] SessionId [123|b2800e03-744245d9-172a15ac-9a218dcc_0] Write session: destroy
2025-10-27T11:21:02.771282Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\000123' seqNo 2 partNo 0 FormedBlobsCount 0 NewHead: Offset 5 PartNo 0 PackedSize 163 count 1 nextOffset 6 batches 1
2025-10-27T11:21:02.771329Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.771862Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 5,1 HeadOffset 5 endOffset 5 curOffset 6 d0000000001_00000000000000000005_00000_0000000001_00000? size 151 WTime 1761564062771
2025-10-27T11:21:02.772029Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][1][StateIdle] TPartition::DropOwner.
2025-10-27T11:21:02.772065Z node 8 :PERSQUEUE DEBUG: partition.cpp:2302: [72075186224037892][Partition][1][StateIdle] Writing. Can't process transactions and user actions
2025-10-27T11:21:02.772091Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.772219Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 5 partNo 0 count 1 size 151
2025-10-27T11:21:02.773181Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 5 count 1 size 151 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.773233Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.773283Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 96 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.773296Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 5 partno 0 count 1 parts 0 suffix '63' size 151
2025-10-27T11:21:02.773315Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.773346Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\000123', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 2, partNo: 0, Offset: 5 is stored on disk
2025-10-27T11:21:02.773524Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.773543Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.773555Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.773585Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.773629Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 3  requestId: <none> cookie: 2
2025-10-27T11:21:02.773690Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.773706Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.773718Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.773745Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.773756Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.773771Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
2025-10-27T11:21:02.780296Z :DEBUG: [] MessageGroupId [123] SessionId [] Write session: try to update token
2025-10-27T11:21:02.780637Z :INFO: [] MessageGroupId [123] SessionId [] Write session: Do CDS request
2025-10-27T11:21:02.780662Z :INFO: [] MessageGroupId [123] SessionId [] Start write session. Will connect to endpoint: localhost:23917
2025-10-27T11:21:02.788726Z :DEBUG: [] MessageGroupId [123] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "123" }
2025-10-27T11:21:02.789167Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:107: new grpc connection
2025-10-27T11:21:02.789200Z node 8 :PQ_WRITE_PROXY DEBUG: grpc_pq_write.h:141: new session created cookie 8
2025-10-27T11:21:02.789543Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 8 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "123" }
2025-10-27T11:21:02.789664Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:447: session request cookie: 8 topic: "topic1" message_group_id: "123" from ipv6:[::1]:47600
2025-10-27T11:21:02.789702Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1538: write session:  cookie=8 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47600 proto=v1  topic=topic1 durationSec=0
2025-10-27T11:21:02.789716Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:571: init check schema
2025-10-27T11:21:02.791234Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:632: session v1 cookie: 8 sessionId:  describe result for acl check
2025-10-27T11:21:02.791406Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:62: 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-27T11:21:02.791436Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:63: 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-27T11:21:02.791448Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__table_helper.h:64: 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-27T11:21:02.791466Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:111: TPartitionChooser [8:7565860039104104348:2530] (SourceId=123, PreferedPartition=(NULL)) StartKqpSession
2025-10-27T11:21:02.794692Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:142: TPartitionChooser [8:7565860039104104348:2530] (SourceId=123, PreferedPartition=(NULL)) Select from the table
2025-10-27T11:21:02.800646Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:174: TPartitionChooser [8:7565860039104104348:2530] (SourceId=123, PreferedPartition=(NULL)) Update the table
2025-10-27T11:21:02.807067Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:183: TPartitionChooser [8:7565860039104104348:2530] (SourceId=123, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2025-10-27T11:21:02.807109Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:305: TPartitionChooser [8:7565860039104104348:2530] (SourceId=123, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=0
2025-10-27T11:21:02.807129Z node 8 :PQ_PARTITION_CHOOSER DEBUG: partition_chooser_impl__abstract_chooser_actor.h:268: TPartitionChooser [8:7565860039104104348:2530] (SourceId=123, PreferedPartition=(NULL)) Start idle
2025-10-27T11:21:02.807161Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:694: ProceedPartition. session cookie: 8 sessionId:  partition: 1 expectedGeneration: (NULL)
2025-10-27T11:21:02.807672Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2723: [PQ: 72075186224037892] server connected, pipe [8:7565860039104104373:2530], now have 1 active actors on pipe
2025-10-27T11:21:02.807674Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:822: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 8, Generation: 1
2025-10-27T11:21:02.807716Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.807740Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.807822Z node 8 :PERSQUEUE INFO: ownerinfo.cpp:30: new Cookie 123|f53b84d8-6ca77129-e76d5325-c1b85d03_0 generated for partition 1 topic 'rt3.dc1--topic1' owner 123
2025-10-27T11:21:02.807860Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.807884Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.807899Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.807942Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.808005Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:35: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyOwnerOk. Partition: 1
2025-10-27T11:21:02.808070Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.808210Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.808239Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.808310Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2025-10-27T11:21:02.808467Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:871: session inited cookie: 8 partition: 1 MaxSeqNo: 2 sessionId: 123|f53b84d8-6ca77129-e76d5325-c1b85d03_0
2025-10-27T11:21:02.809077Z :INFO: [] MessageGroupId [123] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1761564062809 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2025-10-27T11:21:02.809212Z :INFO: [] MessageGroupId [123] SessionId [] Write session established. Init response: last_sequence_number: 2 session_id: "123|f53b84d8-6ca77129-e76d5325-c1b85d03_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
ReadyToAcceptEvent
2025-10-27T11:21:02.809406Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write 1 messages with Id from 1 to 1
ReadyToAcceptEvent
2025-10-27T11:21:02.809840Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session: try to update token
2025-10-27T11:21:02.809889Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Send 1 message(s) (0 left), first sequence number is 3
2025-10-27T11:21:02.810393Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 8 sessionId: 123|f53b84d8-6ca77129-e76d5325-c1b85d03_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.810685Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.810802Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.810829Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.810893Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2025-10-27T11:21:02.810964Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.811054Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.811072Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.811124Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2012: [PQ: 72075186224037892] got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\000123' SeqNo: 3 partNo : 0 messageNo: 1 size 92 offset: -1
2025-10-27T11:21:02.811156Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:637: [72075186224037892][Partition][1][StateIdle] Received TPartition::TEvWrite
2025-10-27T11:21:02.811190Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.811213Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.811228Z node 8 :PERSQUEUE DEBUG: partition.cpp:2336: [72075186224037892][Partition][1][StateIdle] Batch completed (1)
2025-10-27T11:21:02.811312Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1319: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\000123' seqNo 3 partNo 0
2025-10-27T11:21:02.812307Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1423: [72075186224037892][Partition][1][StateIdle] Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\000123' seqNo 3 partNo 0 FormedBlobsCount 0 NewHead: Offset 6 PartNo 0 PackedSize 163 count 1 nextOffset 7 batches 1
2025-10-27T11:21:02.812343Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.812944Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:1675: [72075186224037892][Partition][1][StateIdle] Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 6,1 HeadOffset 6 endOffset 6 curOffset 7 d0000000001_00000000000000000006_00000_0000000001_00000? size 151 WTime 1761564062812
2025-10-27T11:21:02.813109Z node 8 :PERSQUEUE DEBUG: read.h:275: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough write request to KV
2025-10-27T11:21:02.813258Z node 8 :PERSQUEUE DEBUG: read.h:313: [72075186224037892][PQCacheProxy]CacheProxy. Passthrough blob. Partition 1 offset 6 partNo 0 count 1 size 151
2025-10-27T11:21:02.814238Z node 8 :PERSQUEUE DEBUG: cache_eviction.h:321: Caching head blob in L1. Partition 1 offset 6 count 1 size 151 actorID [8:7565860030514169346:2435]
2025-10-27T11:21:02.814298Z node 8 :PERSQUEUE DEBUG: partition.cpp:2150: [72075186224037892][Partition][1][StateIdle] Received TEvKeyValue::TEvResponse
2025-10-27T11:21:02.814343Z node 8 :PERSQUEUE DEBUG: pq_l2_cache.cpp:129: PQ Cache (L2). Adding blob. Tablet '72075186224037892' partition 1 offset 6 partno 0 count 1 parts 0 suffix '63' size 151
2025-10-27T11:21:02.814350Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:574: [72075186224037892][Partition][1][StateIdle] TPartition::HandleWriteResponse writeNewSize# 96 WriteNewSizeFromSupportivePartitions# 0
2025-10-27T11:21:02.814382Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:58: [72075186224037892][Partition][1][StateIdle] TPartition::ReplyWrite. Partition: 1
2025-10-27T11:21:02.814422Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:361: [72075186224037892][Partition][1][StateIdle] Answering for message sourceid: '\000123', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 3, partNo: 0, Offset: 6 is stored on disk
2025-10-27T11:21:02.814624Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.814645Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.814659Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.814692Z node 8 :PERSQUEUE DEBUG: partition_compaction.cpp:193: [72075186224037892][Partition][1][StateIdle] No data for blobs compaction
2025-10-27T11:21:02.814739Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2025-10-27T11:21:02.814821Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::TEvPersQueue::TEvResponse
2025-10-27T11:21:02.815507Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session got write response: sequence_numbers: 3 offsets: 6 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 2 queued_in_partition_duration_ms: 1 }
2025-10-27T11:21:02.815559Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session: acknoledged message 1
AcksEvent: { seqNo : 1, State : EES_WRITTEN, offset : 6, partitionId : 1 } write stat: Write time 0.002000s total time in partition queue 0.001000s partition quoted time 0.000000s topic quoted time 0.000000s
Set token invalid_ticket
2025-10-27T11:21:02.815786Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write 1 messages with Id from 2 to 2
ReadyToAcceptEvent
2025-10-27T11:21:02.816204Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session: try to update token
2025-10-27T11:21:02.816247Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session: updating token
2025-10-27T11:21:02.816451Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Send 1 message(s) (0 left), first sequence number is 4
2025-10-27T11:21:02.816724Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 8 sessionId: 123|f53b84d8-6ca77129-e76d5325-c1b85d03_0 grpc read done: success: 1 data:  update_token_request [content omitted]
2025-10-27T11:21:02.816911Z node 8 :PQ_WRITE_PROXY DEBUG: write_session_actor.cpp:254: session v1 cookie: 8 sessionId: 123|f53b84d8-6ca77129-e76d5325-c1b85d03_0 grpc read done: success: 1 data:  write_request[data omitted]
2025-10-27T11:21:02.817091Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:1352: updating token
2025-10-27T11:21:02.817405Z node 8 :PQ_WRITE_PROXY INFO: write_session_actor.cpp:304: session v1 cookie: 8 sessionId: 123|f53b84d8-6ca77129-e76d5325-c1b85d03_0 is DEAD
2025-10-27T11:21:02.818085Z :ERROR: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Got error. Status: CLIENT_UNAUTHENTICATED, Description: <main>: Error: GRpc error: (16): unauthenticated, refreshed token is invalid 
2025-10-27T11:21:02.818054Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2025-10-27T11:21:02.818122Z node 8 :PQ_WRITE_PROXY DEBUG: writer.cpp:562: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2025-10-27T11:21:02.818141Z :ERROR: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session will not restart after a fatal error
2025-10-27T11:21:02.818183Z :INFO: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session will now close
2025-10-27T11:21:02.818249Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session: aborting
SessionClosed { Status: CLIENT_UNAUTHENTICATED Issues: "<main>: Error: GRpc error: (16): unauthenticated, refreshed token is invalid " }
2025-10-27T11:21:02.818276Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:146: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2025-10-27T11:21:02.818308Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2637: [PQ: 72075186224037892] got client message batch for topic 'rt3.dc1--topic1' partition 1
2025-10-27T11:21:02.818363Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:2748: [PQ: 72075186224037892] server disconnected, pipe [8:7565860039104104373:2530] destroyed
2025-10-27T11:21:02.818420Z node 8 :PERSQUEUE DEBUG: partition_write.cpp:138: [72075186224037892][Partition][1][StateIdle] TPartition::DropOwner.
2025-10-27T11:21:02.818456Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.818475Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.818486Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.818525Z node 8 :PERSQUEUE DEBUG: pq_impl.cpp:181: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 2  requestId: <none> cookie: 2
2025-10-27T11:21:02.818594Z :DEBUG: [] MessageGroupId [123] SessionId [123|f53b84d8-6ca77129-e76d5325-c1b85d03_0] Write session: destroy
2025-10-27T11:21:02.874008Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][1][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.874042Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][1][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.874056Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][1][StateIdle] Try persist
2025-10-27T11:21:02.874106Z node 8 :PERSQUEUE DEBUG: partition.cpp:2323: [72075186224037892][Partition][0][StateIdle] Batching state before ContinueProcessTxsAndUserActs: 0
2025-10-27T11:21:02.874116Z node 8 :PERSQUEUE DEBUG: partition.cpp:2332: [72075186224037892][Partition][0][StateIdle] Batching state after ContinueProcessTxsAndUserActs: 1
2025-10-27T11:21:02.874124Z node 8 :PERSQUEUE DEBUG: partition.cpp:2355: [72075186224037892][Partition][0][StateIdle] Try persist
