2024-06-28T13:37:56.315819Z node 13 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction
2024-06-28T13:37:56.316116Z node 13 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction
2024-06-28T13:37:56.316309Z node 13 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction
2024-06-28T13:37:56.324419Z node 13 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[13:7385547920962672981:4117];send_to=[0:7307199536658146131:7762515];
2024-06-28T13:37:56.326549Z node 13 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2024-06-28T13:37:56.338810Z node 14 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction
2024-06-28T13:37:56.339508Z node 14 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[14:7385547923012034986:4098];send_to=[0:7307199536658146131:7762515];
2024-06-28T13:37:56.339552Z node 14 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction
2024-06-28T13:37:56.339861Z node 14 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction
2024-06-28T13:37:56.340707Z node 14 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
2024-06-28T13:37:56.374300Z node 13 :PQ_READ_PROXY DEBUG: Direct read cache created
2024-06-28T13:37:56.398443Z node 14 :PQ_READ_PROXY DEBUG: Direct read cache created
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/mls9/002b67/r3tmp/tmpSHduO3/pdisk_1.dat
2024-06-28T13:37:56.689910Z node 13 :IMPORT WARN: Table profiles were not loaded
2024-06-28T13:37:56.747055Z node 13 :HIVE WARN: HIVE#72057594037968897 Node(13, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2024-06-28T13:37:56.747182Z node 13 :HIVE WARN: HIVE#72057594037968897 Node(13, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2024-06-28T13:37:56.749149Z node 13 :HIVE WARN: HIVE#72057594037968897 Node(14, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2024-06-28T13:37:56.749255Z node 13 :HIVE WARN: HIVE#72057594037968897 Node(14, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2024-06-28T13:37:56.780204Z node 13 :HIVE WARN: HIVE#72057594037968897 Handle TEvInterconnect::TEvNodeConnected, NodeId 14 Cookie 14
2024-06-28T13:37:56.780394Z node 13 :HIVE WARN: HIVE#72057594037968897 Node(13, (0,0,0,0)) VolatileState: Connecting -> Connected
2024-06-28T13:37:56.789973Z node 13 :HIVE WARN: HIVE#72057594037968897 Node(14, (0,0,0,0)) VolatileState: Connecting -> Connected
TServer::EnableGrpc on GrpcPort 16697, node 13
2024-06-28T13:37:56.949170Z node 13 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: /home/runner/.ya/build/build_root/mls9/002b67/r3tmp/yandex5Va3Iw.tmp
2024-06-28T13:37:56.949206Z node 13 :NET_CLASSIFIER WARN: will try to initialize from file: /home/runner/.ya/build/build_root/mls9/002b67/r3tmp/yandex5Va3Iw.tmp
2024-06-28T13:37:56.949340Z node 13 :NET_CLASSIFIER WARN: successfully initialized from file: /home/runner/.ya/build/build_root/mls9/002b67/r3tmp/yandex5Va3Iw.tmp
2024-06-28T13:37:56.949487Z node 13 :NET_CLASSIFIER ERROR: got bad distributable configuration
2024-06-28T13:37:57.028486Z INFO: TTestServer started on Port 28742 GrpcPort 16697
TClient is connected to server localhost:28742
PQClient connected to localhost:16697
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      PlanResolution: 7
      Coo...
(TRUNCATED)
WaitRootIsUp 'Root' success.
waiting...
waiting...
2024-06-28T13:37:57.412574Z node 13 :FLAT_TX_SCHEMESHARD WARN: NotifyTxCompletion, unknown transaction, txId: 281474976715658, at schemeshard: 72057594046644480
waiting...
waiting...
waiting...
2024-06-28T13:38:01.320504Z node 13 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[13:7385547920962672981:4117];send_to=[0:7307199536658146131:7762515];
2024-06-28T13:38:01.320620Z node 13 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
2024-06-28T13:38:01.342571Z node 14 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[14:7385547923012034986:4098];send_to=[0:7307199536658146131:7762515];
2024-06-28T13:38:01.342665Z node 14 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout;
2024-06-28T13:38:01.608042Z node 13 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [13:7385547942437510468:4302], 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
2024-06-28T13:38:01.610476Z node 13 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=13&id=NGEzZjBhNDctNjI0YThhMmEtY2RjZWVhZTctYmQ3MTU0Njk=, ActorId: [13:7385547942437510466:4288], ActorState: ExecuteState, TraceId: 01j1fh2d67fpxj7tdhja8bpben, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2024-06-28T13:38:01.611353Z node 13 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 3 column: 16 } message: "At function: KiReadTable!" end_position { row: 3 column: 16 } severity: 1 issues { position { row: 3 column: 16 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Cluster]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 3 column: 16 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
2024-06-28T13:38:01.619980Z node 14 :KQP_COMPILE_ACTOR ERROR: Compilation failed, self: [14:7385547944486871791:4288], 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
2024-06-28T13:38:01.622442Z node 14 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=14&id=ZmRkOGE1YjYtOTc5Nzg1YTQtNjFhZjViNmUtZDdiODhhM2M=, ActorId: [14:7385547944486871789:4287], ActorState: ExecuteState, TraceId: 01j1fh2d7e82q238jsxc5nvy3q, ReplyQueryCompileError, status SCHEME_ERROR remove tx with tx_id: 
2024-06-28T13:38:01.623387Z node 14 :PERSQUEUE_CLUSTER_TRACKER ERROR: failed to list clusters: { Response { QueryIssues { message: "Type annotation" issue_code: 1030 severity: 1 issues { position { row: 3 column: 16 } message: "At function: KiReadTable!" end_position { row: 3 column: 16 } severity: 1 issues { position { row: 3 column: 16 } message: "Cannot find table \'db.[/Root/PQ/Config/V2/Cluster]\' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions." end_position { row: 3 column: 16 } issue_code: 2003 severity: 1 } } } TxMeta { } } YdbStatus: SCHEME_ERROR ConsumedRu: 1 }
=== 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);
2024-06-28T13:38:02.361043Z node 13 :KQP_EXECUTER ERROR: TxId: 281474976715665. Ctx: { TraceId: 01j1fh2dq96ey3x6qj7e7cd08c, Database: , SessionId: ydb://session/3?node_id=13&id=MWE1NTI2MmItYTY0NmQ1ZGUtMWVmMTA5YzYtMjcwMTE0NzQ=, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
=== CheckClustersList. Subcribe to ClusterTracker from [13:7385547946732478201:12347] 
=== CheckClustersList. Ok
PQ Client: create topic: rt3.dc1--topic1 with 2 partitions
CallPersQueueGRPC request to localhost:16697
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
CallPersQueueGRPC request to localhost:16697
2024-06-28T13:38:08.777123Z node 13 :PERSQUEUE INFO: proxy answer <none>
MetaRequest {
  CmdCreateTopic {
    Topic: "rt3.dc1--topic1"
    NumPartitions: 2
    Config {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxCounts: 6000000
      }
      LocalDC: true
      ReadRules: "user"
      ReadFromTimestampsMs: 0
      ConsumerFormatVersions: 0
      ConsumerCodecs {
      }
      Codecs {
        Ids: 0
        Ids: 1
        Ids: 2
        Codecs: "raw"
        Codecs: "gzip"
        Codecs: "lzop"
      }
      ReadRuleVersions: 0
    }
  }
}
CallPersQueueGRPC response:
Status: 129
ProxyErrorCode: 53
SchemeStatus: 1
FlatTxId {
  TxId: 281474976715679
  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
2024-06-28T13:38:08.829529Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic  pipe [13:7385547972502282577:8492] connected; active server actors: 1
2024-06-28T13:38:08.829791Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 updating configuration. Deleted partitions []. Added partitions [1, 0]
2024-06-28T13:38:08.830544Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at RB 72075186224037893
2024-06-28T13:38:08.834225Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: BALANCER INIT DONE for rt3.dc1--topic1: (0, 72075186224037892) (1, 72075186224037892) 
2024-06-28T13:38:08.835234Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892Registered with mediator time cast
2024-06-28T13:38:08.836049Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037893 topic rt3.dc1--topic1 TEvClientConnected TabletId 72057594046644480, NodeId 13, Generation 2
2024-06-28T13:38:08.843868Z node 14 :PERSQUEUE INFO: Tablet 72075186224037892 doesn't have tx info
2024-06-28T13:38:08.843910Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 LastStep 0 LastTxId 0
2024-06-28T13:38:08.843931Z node 14 :PERSQUEUE INFO: Tablet 72075186224037892 no config, start with empty partitions and default config
2024-06-28T13:38:08.843969Z node 14 :PERSQUEUE NOTICE: Tablet 72075186224037892 disable metering: reason# billing is not enabled in BillingMeteringConfig
2024-06-28T13:38:08.844009Z node 14 :PERSQUEUE INFO: Tablet 72075186224037892 doesn't have tx writes info
2024-06-28T13:38:08.844720Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547972502282610:2043], now have 1 active actors on pipe
2024-06-28T13:38:08.845110Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: tablet 72075186224037893 topic rt3.dc1--topic1 TEvClientConnected TabletId 72075186224037892, NodeId 14, Generation 1
2024-06-28T13:38:08.861823Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547972502282575:8511], now have 1 active actors on pipe
2024-06-28T13:38:08.862614Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 Config update version 0(current 0) received from actor [13:7385547920962673315:12346] txId 281474976715679 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
ReadRules: "user"
ReadFromTimestampsMs: 0
ConsumerFormatVersions: 0
ConsumerCodecs {
}
Codecs {
  Ids: 0
  Ids: 1
  Ids: 2
  Codecs: "raw"
  Codecs: "gzip"
  Codecs: "lzop"
}
ReadRuleVersions: 0
TopicPath: "/Root/PQ/rt3.dc1--topic1"
YcCloudId: ""
YcFolderId: ""
YdbDatabaseId: ""
YdbDatabasePath: "/Root"
Partitions {
  PartitionId: 1
  Status: Active
  CreateVersion: 1
  TabletId: 0
}
Partitions {
  PartitionId: 0
  Status: Active
  CreateVersion: 1
  TabletId: 0
}
ReadRuleGenerations: 0
AllPartitions {
  PartitionId: 1
  Status: Active
  CreateVersion: 1
  TabletId: 72075186224037892
}
AllPartitions {
  PartitionId: 0
  Status: Active
  CreateVersion: 1
  TabletId: 72075186224037892
}
Consumers {
  Name: "user"
  ReadFromTimestampsMs: 0
  FormatVersion: 0
  Codec {
  }
  Version: 0
  Generation: 0
  Important: false
}
2024-06-28T13:38:08.868539Z node 14 :PERSQUEUE NOTICE: Tablet 72075186224037892 disable metering: reason# billing is not enabled in BillingMeteringConfig
2024-06-28T13:38:08.869978Z node 14 :PERSQUEUE INFO: Tablet 72075186224037892 Config applied version 0 actor [13:7385547920962673315:12346] txId 281474976715679 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
ReadRules: "user"
ReadFromTimestampsMs: 0
ConsumerFormatVersions: 0
ConsumerCodecs {
}
Codecs {
  Ids: 0
  Ids: 1
  Ids: 2
  Codecs: "raw"
  Codecs: "gzip"
  Codecs: "lzop"
}
ReadRuleVersions: 0
TopicPath: "/Root/PQ/rt3.dc1--topic1"
YcCloudId: ""
YcFolderId: ""
YdbDatabaseId: ""
YdbDatabasePath: "/Root"
Partitions {
  PartitionId: 1
  Status: Active
  CreateVersion: 1
  TabletId: 0
}
Partitions {
  PartitionId: 0
  Status: Active
  CreateVersion: 1
  TabletId: 0
}
ReadRuleGenerations: 0
AllPartitions {
  PartitionId: 1
  Status: Active
  CreateVersion: 1
  TabletId: 72075186224037892
}
AllPartitions {
  PartitionId: 0
  Status: Active
  CreateVersion: 1
  TabletId: 72075186224037892
}
Consumers {
  Name: "user"
  ReadFromTimestampsMs: 0
  FormatVersion: 0
  Codec {
  }
  Version: 0
  Generation: 0
  Important: false
}
2024-06-28T13:38:08.870072Z node 14 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 1. Step TInitConfigStep
2024-06-28T13:38:08.870403Z node 14 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 0. Step TInitConfigStep
2024-06-28T13:38:08.870543Z node 14 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 1. Step TInitInternalFieldsStep
2024-06-28T13:38:08.870809Z node 14 :PERSQUEUE INFO: bootstrapping 1 [14:7385547974551643272:4321]
2024-06-28T13:38:08.874789Z node 14 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 1. Completed.
2024-06-28T13:38:08.874824Z node 14 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 1 generation 1 [14:7385547974551643272:4321]
2024-06-28T13:38:08.874852Z node 14 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 1 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2024-06-28T13:38:08.876927Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2024-06-28T13:38:08.877796Z node 14 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 0. Step TInitInternalFieldsStep
2024-06-28T13:38:08.878035Z node 14 :PERSQUEUE INFO: bootstrapping 0 [14:7385547974551643273:4330]
2024-06-28T13:38:08.880708Z node 14 :PERSQUEUE DEBUG: Initializing topic 'rt3.dc1--topic1' partition 0. Completed.
2024-06-28T13:38:08.880739Z node 14 :PERSQUEUE INFO: init complete for topic 'rt3.dc1--topic1' partition 0 generation 1 [14:7385547974551643273:4330]
2024-06-28T13:38:08.880764Z node 14 :PERSQUEUE DEBUG: SYNC INIT topic rt3.dc1--topic1 partitition 0 so 0 endOffset 0 Head Offset 0 PartNo 0 PackedSize 0 count 0 nextOffset 0 batches 0
2024-06-28T13:38:08.882090Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2024-06-28T13:38:08.998390Z node 13 :KQP_EXECUTER ERROR: TxId: 281474976715680. Ctx: { TraceId: 01j1fh2ma29txjkbytw7e0d84v, Database: , SessionId: ydb://session/3?node_id=13&id=ODIwMjJhNTItYWU2M2YzZDYtN2M2MjBiYy05YWIwY2VkMw==, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
===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: 281474976715679
    CreateStep: 1719581888920
    ParentPathId: 2
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 0
      PQVersion: 1
    }
    BalancerTabletID: 72075186224037893
  }
  PersQueueGroup {
    Name: "rt3.dc1--topic1"
    PathId: 9
    TotalGroupCount: 2
    PartitionPerTablet: 5
    PQTabletConfig {
      PartitionConfig {
        LifetimeSeconds: 86400
        LowWatermark: 8388608
        SourceIdLifetimeSeconds: 86400
        WriteSpeedInBytesPerSecond: 20000000
        BurstSize: 20000000
        SourceIdMaxC...
(TRUNCATED)
GetTopicVersionFromPath:  record Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "rt3.dc1--topic1"
    PathId: 9
    SchemeshardId: 72057594046644480
    PathType: EPathTypePersQueueGroup
    CreateFinished: true
    CreateTxId: 281474976715679
    CreateStep: 1719581888920
    ParentPathId: 2
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 0
      PQVersion: 1
    }
    BalancerTabletID: 72075186224037893
  }
  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
      ReadRules: "user"
      ReadFromTimestampsMs: 0
      ConsumerFormatVersions: 0
      ConsumerCodecs {
      }
      Codecs {
        Ids: 0
        Ids: 1
        Ids: 2
        Codecs: "raw"
        Codecs: "gzip"
        Codecs: "lzop"
      }
      ReadRuleVersions: 0
      YdbDatabasePath: "/Root"
    }
    Partitions {
      PartitionId: 0
      TabletId: 72075186224037892
      Status: Active
    }
    Partitions {
      PartitionId: 1
      TabletId: 72075186224037892
      Status: Active
    }
    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
  }
}
Path: "/Root/PQ/rt3.dc1--topic1"
 name rt3.dc1--topic1 version1
CallPersQueueGRPC request to localhost:16697
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2024-06-28T13:38:09.046302Z node 13 :PERSQUEUE INFO: proxy answer <none>
CallPersQueueGRPC response:
Status: 128
ErrorReason: "the following topics are not created: rt3.dc1--topic1, Marker# PQ95"
ErrorCode: UNKNOWN_TOPIC
CallPersQueueGRPC request to localhost:16697
MetaRequest {
  CmdGetTopicMetadata {
    Topic: "rt3.dc1--topic1"
  }
}
2024-06-28T13:38:09.551484Z node 13 :PERSQUEUE INFO: 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
        ReadRules: "user"
        ReadFromTimestampsMs: 0
        ConsumerFormatVersions: 0
        ConsumerCodecs {
        }
        Codecs {
          Ids: 0
          Ids: 1
          Ids: 2
          Codecs: "raw"
          Codecs: "gzip"
          Codecs: "lzop"
        }
        ReadRuleVersions: 0
        TopicPath: "/Root/PQ/rt3.dc1--topic1"
        YdbDatabasePath: "/Root"
        Consumers {
          Name: "user"
          ReadFromTimestampsMs: 0
          FormatVersion: 0
          Codec {
          }
          Version: 0
        ...
(TRUNCATED)
=== Topic created, have version: 1
2024-06-28T13:38:09.567220Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Starting read session
2024-06-28T13:38:09.567311Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Starting session to cluster null (localhost:16697)
2024-06-28T13:38:09.579171Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] In Reconnect, ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:09.579226Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] New values: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:09.579289Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] Reconnecting session to cluster null in 0.000000s
===== CreateReader =====
MessagesInflight: 0
BytesInflightUncompressed: 0
BytesInflightCompressed: 0
BytesInflightTotal: 0
============
2024-06-28T13:38:09.590987Z node 13 :PQ_READ_PROXY DEBUG: new grpc connection
2024-06-28T13:38:09.591019Z node 13 :PQ_READ_PROXY DEBUG: new session created cookie 1
2024-06-28T13:38:09.591516Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] Successfully connected. Initializing session
2024-06-28T13:38:09.592341Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer  session  grpc read done: success# 1, data# { init_request { topics_read_settings { topic: "topic1" } read_only_original: true consumer: "shared/user" read_params { max_read_size: 104857600 } } }
2024-06-28T13:38:09.592600Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read init: from# ipv6:[::1]:47846, request# { init_request { topics_read_settings { topic: "topic1" } read_only_original: true consumer: "shared/user" read_params { max_read_size: 104857600 } } }
2024-06-28T13:38:09.592938Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 auth for : user
2024-06-28T13:38:09.593740Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Handle describe topics response
2024-06-28T13:38:09.593918Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 auth is DEAD
2024-06-28T13:38:09.594014Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 auth ok: topics# 1, initDone# 0
2024-06-28T13:38:09.595142Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 register session: topic# rt3.dc1--topic1
2024-06-28T13:38:09.595910Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] Server session id: shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:09.596271Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:09.596679Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:09.596792Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# 4cd9d817-b5ce7220-ea03f697-aa36de6f
2024-06-28T13:38:09.597250Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547976797250062:4326] connected; active server actors: 1
2024-06-28T13:38:09.597390Z node 13 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer "user" register session for pipe [13:7385547976797250062:4326] session shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:09.597445Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user register readable partition 0
2024-06-28T13:38:09.597511Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user family created family=1 (Status=Free, Partitions=[0])
2024-06-28T13:38:09.597530Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user register readable partition 1
2024-06-28T13:38:09.597562Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user family created family=2 (Status=Free, Partitions=[1])
2024-06-28T13:38:09.597607Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user register reading session ReadingSession "shared/user_13_1_2041620033203687009_v1" (Sender=[13:7385547976797250059:4326], Pipe=[13:7385547976797250062:4326], Partitions=[], ActiveFamilyCount=0)
2024-06-28T13:38:09.597642Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user rebalancing was scheduled
2024-06-28T13:38:09.597702Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user balancing. Sessions=1, Families=2, UnradableFamilies=2 [2 (1), 1 (0), ], RequireBalancing=0 []
2024-06-28T13:38:09.597762Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user balancing family=2 (Status=Free, Partitions=[1]) for ReadingSession "shared/user_13_1_2041620033203687009_v1" (Sender=[13:7385547976797250059:4326], Pipe=[13:7385547976797250062:4326], Partitions=[], ActiveFamilyCount=0)
2024-06-28T13:38:09.597826Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user family 2 status Active partitions [1] session "shared/user_13_1_2041620033203687009_v1" sender [13:7385547976797250059:4326] lock partition 1 for ReadingSession "shared/user_13_1_2041620033203687009_v1" (Sender=[13:7385547976797250059:4326], Pipe=[13:7385547976797250062:4326], Partitions=[], ActiveFamilyCount=1) generation 1 step 1
2024-06-28T13:38:09.597887Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user balancing family=1 (Status=Free, Partitions=[0]) for ReadingSession "shared/user_13_1_2041620033203687009_v1" (Sender=[13:7385547976797250059:4326], Pipe=[13:7385547976797250062:4326], Partitions=[], ActiveFamilyCount=1)
2024-06-28T13:38:09.597922Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user family 1 status Active partitions [0] session "shared/user_13_1_2041620033203687009_v1" sender [13:7385547976797250059:4326] lock partition 0 for ReadingSession "shared/user_13_1_2041620033203687009_v1" (Sender=[13:7385547976797250059:4326], Pipe=[13:7385547976797250062:4326], Partitions=[], ActiveFamilyCount=2) generation 1 step 2
2024-06-28T13:38:09.597964Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user start rebalancing. familyCount=2, sessionCount=1, desiredFamilyCount=2, allowPlusOne=0
2024-06-28T13:38:09.597992Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user balancing duration: 0.000268s
2024-06-28T13:38:09.598834Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 assign: record# { Partition: 1 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 1 Session: "shared/user_13_1_2041620033203687009_v1" ClientId: "user" PipeClient { RawX1: 7385547976797250062 RawX2: 4503655461949670 } Path: "/Root/PQ/rt3.dc1--topic1" }
2024-06-28T13:38:09.598958Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 assign: record# { Partition: 0 TabletId: 72075186224037892 Topic: "rt3.dc1--topic1" Generation: 1 Step: 2 Session: "shared/user_13_1_2041620033203687009_v1" ClientId: "user" PipeClient { RawX1: 7385547976797250062 RawX2: 4503655461949670 } Path: "/Root/PQ/rt3.dc1--topic1" }
2024-06-28T13:38:09.599036Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1)
2024-06-28T13:38:09.599118Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 INITING TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2)
2024-06-28T13:38:09.600350Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547976797250066:4330], now have 1 active actors on pipe
2024-06-28T13:38:09.600384Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547976797250067:4325], now have 1 active actors on pipe
2024-06-28T13:38:09.600693Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2024-06-28T13:38:09.600760Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) pipe restart attempt 0 pipe creation result: OK TabletId: 72075186224037892 Generation: 1
2024-06-28T13:38:09.601159Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:09.601188Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:09.601231Z node 14 :PERSQUEUE DEBUG: Created session shared/user_13_1_2041620033203687009_v1 on pipe: [13:7385547976797250066:4330]
2024-06-28T13:38:09.601304Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:09.601318Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:09.601334Z node 14 :PERSQUEUE DEBUG: Created session shared/user_13_1_2041620033203687009_v1 on pipe: [13:7385547976797250067:4325]
2024-06-28T13:38:09.601442Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user session is set to 0 (startOffset 0) session shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:09.601497Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user session is set to 0 (startOffset 0) session shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:09.601600Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:09.601699Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:09.602488Z node 14 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_13_1_2041620033203687009_v1:1 with generation 1
2024-06-28T13:38:09.602530Z node 14 :PQ_READ_PROXY DEBUG: Direct read cache: registered server session: shared/user_13_1_2041620033203687009_v1:2 with generation 1
2024-06-28T13:38:09.611635Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 0
2024-06-28T13:38:09.611635Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 0
2024-06-28T13:38:09.611746Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2024-06-28T13:38:09.611789Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 18446744073709551615
2024-06-28T13:38:09.612239Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1719581888874 CreateTimestampMS: 1719581888874 SizeLag: 0 WriteTimestampEstimateMS: 1719581889590 } Cookie: 18446744073709551615 }
CreatePartitionStream { PartitionStreamId: 1 TopicPath: topic1 Cluster: dc1 PartitionId: 1 CommittedOffset: 0 EndOffset: 0 }
2024-06-28T13:38:09.612305Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 0 readOffset 0 committedOffset 0
2024-06-28T13:38:09.612399Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) initDone 0 event { CmdGetClientOffsetResult { Offset: 0 EndOffset: 0 WriteTimestampMS: 1719581888880 CreateTimestampMS: 1719581888880 SizeLag: 0 WriteTimestampEstimateMS: 1719581889590 } Cookie: 18446744073709551615 }
2024-06-28T13:38:09.613781Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] Confirm partition stream create. Partition stream id: 1. Cluster: "dc1". Topic: "topic1". Partition: 1. Read offset: (empty maybe)
2024-06-28T13:38:09.612418Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 INIT DONE TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 0 readOffset 0 committedOffset 0
2024-06-28T13:38:09.612485Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 sending to client partition status
2024-06-28T13:38:09.612841Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 sending to client partition status
CreatePartitionStream { PartitionStreamId: 2 TopicPath: topic1 Cluster: dc1 PartitionId: 0 CommittedOffset: 0 EndOffset: 0 }
2024-06-28T13:38:09.614001Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] Confirm partition stream create. Partition stream id: 2. Cluster: "dc1". Topic: "topic1". Partition: 0. Read offset: (empty maybe)
2024-06-28T13:38:09.614481Z :DEBUG: [] MessageGroupId [source0] SessionId [] Write session: try to update token
2024-06-28T13:38:09.614976Z :INFO: [] MessageGroupId [source0] SessionId [] Write session: Do CDS request
2024-06-28T13:38:09.615019Z :INFO: [] MessageGroupId [source0] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:09.615954Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { start_read { topic { path: "topic1" } cluster: "dc1" partition: 1 assign_id: 1 } }
2024-06-28T13:38:09.616177Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 0, commitOffset# 0
2024-06-28T13:38:09.616276Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { start_read { topic { path: "topic1" } cluster: "dc1" assign_id: 2 } }
2024-06-28T13:38:09.616384Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got StartRead from client: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 0, commitOffset# 0
2024-06-28T13:38:09.616466Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset 0 clientReadOffset 0
2024-06-28T13:38:09.616555Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 1
2024-06-28T13:38:09.616733Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Start reading TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 0 readOffset 0 committedOffset 0 clientCommitOffset 0 clientReadOffset 0
2024-06-28T13:38:09.616757Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 1
2024-06-28T13:38:09.621690Z :DEBUG: [] MessageGroupId [source0] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source0" }
2024-06-28T13:38:09.622675Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:09.622714Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 1
2024-06-28T13:38:09.623102Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source0" }
2024-06-28T13:38:09.623260Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 1 topic: "topic1" message_group_id: "source0" from ipv6:[::1]:47846
2024-06-28T13:38:09.623290Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=1 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:09.623303Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:09.625295Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId:  describe result for acl check
2024-06-28T13:38:09.625470Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:09.625490Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:09.625503Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:09.625523Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:09.628564Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:09.846107Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:09.846464Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547976797250118:4323] connected; active server actors: 1
2024-06-28T13:38:09.846548Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=source0
2024-06-28T13:38:09.846576Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:09.846858Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547976797250118:4323] disconnected; active server actors: 1
2024-06-28T13:38:09.846891Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547976797250118:4323] disconnected no session
2024-06-28T13:38:10.013368Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:10.013425Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2024-06-28T13:38:10.013452Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547976797250074:4323] (SourceId=source0, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:10.013492Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 1 sessionId:  partition: 0 expectedGeneration: (NULL)
2024-06-28T13:38:10.016570Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547981092217436:4323], now have 1 active actors on pipe
2024-06-28T13:38:10.016871Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:10.017411Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.017446Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.017561Z node 14 :PERSQUEUE INFO: new Cookie source0|249628b4-c9ec1799-380c1857-4c1f1d16_0 generated for partition 0 topic 'rt3.dc1--topic1' owner source0
2024-06-28T13:38:10.017686Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2024-06-28T13:38:10.017764Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.024049Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.024090Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.024206Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.024770Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 1 partition: 0 MaxSeqNo: 0 sessionId: source0|249628b4-c9ec1799-380c1857-4c1f1d16_0
2024-06-28T13:38:10.025660Z :INFO: [] MessageGroupId [source0] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581890025 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:10.025800Z :INFO: [] MessageGroupId [source0] SessionId [] Write session established. Init response: session_id: "source0|249628b4-c9ec1799-380c1857-4c1f1d16_0" topic: "topic1" cluster: "dc1" supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:10.026061Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:10.026159Z :INFO: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:10.028091Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session: try to update token
2024-06-28T13:38:10.028151Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:10.035916Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: source0|249628b4-c9ec1799-380c1857-4c1f1d16_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:10.036238Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:10.038374Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.038414Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.038528Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.039806Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:10.044893Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.044928Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.045200Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 0 SourceId: '\0source0' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:10.045390Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob processing sourceId '\0source0' seqNo 1 partNo 0
2024-06-28T13:38:10.046572Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob complete sourceId '\0source0' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 173 count 1 nextOffset 1 batches 1
2024-06-28T13:38:10.047190Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 0 compactOffset 0,1 HeadOffset 0 endOffset 0 curOffset 1 d0000000000_00000000000000000000_00000_0000000001_00000| size 161 WTime 1719581890047
2024-06-28T13:38:10.047418Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:10.052689Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:10.052763Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2024-06-28T13:38:10.052808Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source0', Topic: 'rt3.dc1--topic1', Partition: 0, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2024-06-28T13:38:10.054006Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2024-06-28T13:38:10.054032Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2024-06-28T13:38:10.054218Z node 14 :PERSQUEUE DEBUG: read cookie 0 Topic 'rt3.dc1--topic1' partition 0 user user offset 0 count 1 size 1024000 endOffset 1 max time lag 0ms effective offset 0
2024-06-28T13:38:10.054247Z node 14 :PERSQUEUE DEBUG: read cookie 0 added 0 blobs, size 0 count 0 last offset 0
2024-06-28T13:38:10.054288Z node 14 :PERSQUEUE DEBUG: Reading cookie 0. All data is from uncompacted head.
2024-06-28T13:38:10.054316Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.054411Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 user user readTimeStamp done, result 1719581890045 queuesize 0 startOffset 0
2024-06-28T13:38:10.054490Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:10.055834Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait for data done:  readOffset 0 EndOffset 0 newEndOffset 1 commitOffset 0 clientCommitOffset 0 cookie 1
2024-06-28T13:38:10.055894Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) ready for read with readOffset 0 endOffset 1
2024-06-28T13:38:10.055991Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:10.056574Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 0, endOffset# 1, WTime# 1719581888880, sizeLag# 161
2024-06-28T13:38:10.056627Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:10.056700Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# 4cd9d817-b5ce7220-ea03f697-aa36de6f, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:10.057369Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.057403Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.057545Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session got write response: sequence_numbers: 1 offsets: 0 already_written: false write_statistics { persist_duration_ms: 6 queued_in_partition_duration_ms: 1 }
2024-06-28T13:38:10.057617Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session: acknoledged message 1
2024-06-28T13:38:10.056818Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 1 ClientCommitOffset 0 committedOffset 0 Guid 4cd9d817-b5ce7220-ea03f697-aa36de6f
2024-06-28T13:38:10.057048Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user Reading of the partition 0 was started by user.
2024-06-28T13:38:10.058402Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) initDone 1 event { CmdReadResult { MaxOffset: 1 Result { Offset: 0 Data: "... 98 bytes ..." SourceId: "\000source0" SeqNo: 1 WriteTimestampMS: 1719581890045 CreateTimestampMS: 1719581890026 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 0 WaitQuotaTimeMs: 0 } Cookie: 0 }
2024-06-28T13:38:10.057499Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:10.057580Z node 14 :PERSQUEUE DEBUG: read cookie 1 Topic 'rt3.dc1--topic1' partition 0 user user offset 0 count 1 size 193 endOffset 1 max time lag 0ms effective offset 0
2024-06-28T13:38:10.057600Z node 14 :PERSQUEUE DEBUG: read cookie 1 added 0 blobs, size 0 count 0 last offset 0
2024-06-28T13:38:10.057634Z node 14 :PERSQUEUE DEBUG: Reading cookie 1. All data is from uncompacted head.
2024-06-28T13:38:10.057656Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.057802Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.058656Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 2
2024-06-28T13:38:10.058729Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 1 ReadOffset 1 ReadGuid 4cd9d817-b5ce7220-ea03f697-aa36de6f has messages 1
2024-06-28T13:38:10.058905Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# 4cd9d817-b5ce7220-ea03f697-aa36de6f, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), size# 195
2024-06-28T13:38:10.058961Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# 4cd9d817-b5ce7220-ea03f697-aa36de6f
2024-06-28T13:38:10.059219Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:10.060118Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:10.067973Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:10.068179Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# 5ec11a61-4e8534-d1254de3-263d5c4a
2024-06-28T13:38:10.127867Z :INFO: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session will now close
2024-06-28T13:38:10.127927Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session: aborting
2024-06-28T13:38:10.128470Z :INFO: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:10.128517Z :DEBUG: [] MessageGroupId [source0] SessionId [source0|249628b4-c9ec1799-380c1857-4c1f1d16_0] Write session: destroy
2024-06-28T13:38:10.133283Z :DEBUG: [] MessageGroupId [source1] SessionId [] Write session: try to update token
2024-06-28T13:38:10.133561Z :INFO: [] MessageGroupId [source1] SessionId [] Write session: Do CDS request
2024-06-28T13:38:10.133584Z :INFO: [] MessageGroupId [source1] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:10.131868Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 1 sessionId: source0|249628b4-c9ec1799-380c1857-4c1f1d16_0 grpc read done: success: 0 data: 
2024-06-28T13:38:10.131898Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: source0|249628b4-c9ec1799-380c1857-4c1f1d16_0 grpc read failed
2024-06-28T13:38:10.131932Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: source0|249628b4-c9ec1799-380c1857-4c1f1d16_0 grpc closed
2024-06-28T13:38:10.131954Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 1 sessionId: source0|249628b4-c9ec1799-380c1857-4c1f1d16_0 is DEAD
2024-06-28T13:38:10.132816Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:10.134723Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547981092217436:4323] destroyed
2024-06-28T13:38:10.134783Z node 14 :PERSQUEUE DEBUG: [Partition:0, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:10.139744Z :DEBUG: [] MessageGroupId [source1] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source1" }
2024-06-28T13:38:10.143781Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:10.143823Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 2
2024-06-28T13:38:10.144276Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source1" }
2024-06-28T13:38:10.144417Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 2 topic: "topic1" message_group_id: "source1" from ipv6:[::1]:47846
2024-06-28T13:38:10.144445Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=2 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:10.144460Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:10.146207Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId:  describe result for acl check
2024-06-28T13:38:10.146368Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:10.146381Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:10.146395Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:10.146417Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:10.149672Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:10.160984Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:10.161488Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217463:4338] connected; active server actors: 1
2024-06-28T13:38:10.161638Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=source1
2024-06-28T13:38:10.161662Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:10.162322Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217463:4338] disconnected; active server actors: 1
2024-06-28T13:38:10.162347Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217463:4338] disconnected no session
2024-06-28T13:38:10.188711Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:10.188781Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2024-06-28T13:38:10.188806Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217443:4338] (SourceId=source1, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:10.188839Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 2 sessionId:  partition: 1 expectedGeneration: (NULL)
2024-06-28T13:38:10.189790Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547981092217473:4338], now have 1 active actors on pipe
2024-06-28T13:38:10.190736Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.190768Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.190909Z node 14 :PERSQUEUE INFO: new Cookie source1|8c65de08-4521e899-7eb19465-d1cd7fc_0 generated for partition 1 topic 'rt3.dc1--topic1' owner source1
2024-06-28T13:38:10.191008Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 1
2024-06-28T13:38:10.191078Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.191644Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.191673Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.191790Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.189960Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:10.192360Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 2 partition: 1 MaxSeqNo: 0 sessionId: source1|8c65de08-4521e899-7eb19465-d1cd7fc_0
2024-06-28T13:38:10.199250Z :INFO: [] MessageGroupId [source1] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581890199 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:10.199367Z :INFO: [] MessageGroupId [source1] SessionId [] Write session established. Init response: session_id: "source1|8c65de08-4521e899-7eb19465-d1cd7fc_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:10.199747Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:10.199818Z :INFO: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:10.200264Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session: try to update token
2024-06-28T13:38:10.200314Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:10.203779Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|8c65de08-4521e899-7eb19465-d1cd7fc_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:10.204137Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:10.204732Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.204770Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.204883Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.208543Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:10.209121Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.209157Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.209435Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source1' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:10.209651Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source1' seqNo 1 partNo 0
2024-06-28T13:38:10.210660Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\0source1' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 0 PartNo 0 PackedSize 173 count 1 nextOffset 1 batches 1
2024-06-28T13:38:10.211265Z node 14 :PERSQUEUE DEBUG: 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 161 WTime 1719581890208
2024-06-28T13:38:10.211455Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:10.222557Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:10.222605Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 1
2024-06-28T13:38:10.222646Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source1', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 1, partNo: 0, Offset: 0 is stored on disk
2024-06-28T13:38:10.298125Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 0 rrg 0
2024-06-28T13:38:10.298158Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user send read request for offset 0 initiated  queuesize 0 startOffset 0 ReadingTimestamp 1 rrg 0
2024-06-28T13:38:10.298328Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:10.298463Z node 14 :PERSQUEUE DEBUG: read cookie 0 Topic 'rt3.dc1--topic1' partition 1 user user offset 0 count 1 size 1024000 endOffset 1 max time lag 0ms effective offset 0
2024-06-28T13:38:10.298483Z node 14 :PERSQUEUE DEBUG: read cookie 0 added 0 blobs, size 0 count 0 last offset 0
2024-06-28T13:38:10.298515Z node 14 :PERSQUEUE DEBUG: Reading cookie 0. All data is from uncompacted head.
2024-06-28T13:38:10.298537Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.298616Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 user user readTimeStamp done, result 1719581890208 queuesize 0 startOffset 0
2024-06-28T13:38:10.299895Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session got write response: sequence_numbers: 1 offsets: 0 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 14 }
2024-06-28T13:38:10.299954Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session: acknoledged message 1
2024-06-28T13:38:10.300228Z :INFO: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session will now close
2024-06-28T13:38:10.300267Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session: aborting
2024-06-28T13:38:10.300263Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.300302Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.300370Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:10.300447Z node 14 :PERSQUEUE DEBUG: read cookie 1 Topic 'rt3.dc1--topic1' partition 1 user user offset 0 count 1 size 193 endOffset 1 max time lag 0ms effective offset 0
2024-06-28T13:38:10.300465Z node 14 :PERSQUEUE DEBUG: read cookie 1 added 0 blobs, size 0 count 0 last offset 0
2024-06-28T13:38:10.300494Z node 14 :PERSQUEUE DEBUG: Reading cookie 1. All data is from uncompacted head.
2024-06-28T13:38:10.300516Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.300659Z :INFO: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:10.300688Z :DEBUG: [] MessageGroupId [source1] SessionId [source1|8c65de08-4521e899-7eb19465-d1cd7fc_0] Write session: destroy
2024-06-28T13:38:10.300649Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.299028Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait for data done:  readOffset 0 EndOffset 0 newEndOffset 1 commitOffset 0 clientCommitOffset 0 cookie 1
2024-06-28T13:38:10.301543Z :DEBUG: [] MessageGroupId [source2] SessionId [] Write session: try to update token
2024-06-28T13:38:10.299064Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) ready for read with readOffset 0 endOffset 1
2024-06-28T13:38:10.299147Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:10.299601Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 0, endOffset# 1, WTime# 1719581888874, sizeLag# 161
2024-06-28T13:38:10.299617Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:10.299651Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# 5ec11a61-4e8534-d1254de3-263d5c4a, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:10.299736Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 0 EndOffset 1 ClientCommitOffset 0 committedOffset 0 Guid 5ec11a61-4e8534-d1254de3-263d5c4a
2024-06-28T13:38:10.300192Z node 13 :PERSQUEUE_READ_BALANCER DEBUG: balancer: [72075186224037893] topic rt3.dc1--topic1 consumer user Reading of the partition 1 was started by user.
2024-06-28T13:38:10.301221Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 1 Result { Offset: 0 Data: "... 98 bytes ..." SourceId: "\000source1" SeqNo: 1 WriteTimestampMS: 1719581890208 CreateTimestampMS: 1719581890199 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 0 WaitQuotaTimeMs: 0 } Cookie: 0 }
2024-06-28T13:38:10.301324Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 2
2024-06-28T13:38:10.301360Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 1 ReadOffset 1 ReadGuid 5ec11a61-4e8534-d1254de3-263d5c4a has messages 1
2024-06-28T13:38:10.301430Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# 5ec11a61-4e8534-d1254de3-263d5c4a, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), size# 197
2024-06-28T13:38:10.301460Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# 5ec11a61-4e8534-d1254de3-263d5c4a
2024-06-28T13:38:10.301675Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:10.302934Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 2 sessionId: source1|8c65de08-4521e899-7eb19465-d1cd7fc_0 grpc read done: success: 0 data: 
2024-06-28T13:38:10.302950Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source1|8c65de08-4521e899-7eb19465-d1cd7fc_0 grpc read failed
2024-06-28T13:38:10.302984Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source1|8c65de08-4521e899-7eb19465-d1cd7fc_0 grpc closed
2024-06-28T13:38:10.303007Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 2 sessionId: source1|8c65de08-4521e899-7eb19465-d1cd7fc_0 is DEAD
2024-06-28T13:38:10.304730Z :INFO: [] MessageGroupId [source2] SessionId [] Write session: Do CDS request
2024-06-28T13:38:10.304762Z :INFO: [] MessageGroupId [source2] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:10.303723Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:10.309451Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:10.309269Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547981092217473:4338] destroyed
2024-06-28T13:38:10.309329Z node 14 :PERSQUEUE DEBUG: [Partition:1, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:10.309854Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:10.309957Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# d8c84e8c-bd80ae28-4248bef8-a6179035
2024-06-28T13:38:10.313621Z :DEBUG: [] MessageGroupId [source2] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source2" }
2024-06-28T13:38:10.314130Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:10.314152Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 3
2024-06-28T13:38:10.314469Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source2" }
2024-06-28T13:38:10.314613Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 3 topic: "topic1" message_group_id: "source2" from ipv6:[::1]:47846
2024-06-28T13:38:10.314636Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=3 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:10.314648Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:10.316295Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId:  describe result for acl check
2024-06-28T13:38:10.316440Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:10.316455Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:10.316470Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:10.316491Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:10.319908Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:10.330616Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:10.331014Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217518:4315] connected; active server actors: 1
2024-06-28T13:38:10.331111Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=source2
2024-06-28T13:38:10.331128Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:10.331535Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217518:4315] disconnected; active server actors: 1
2024-06-28T13:38:10.331561Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217518:4315] disconnected no session
2024-06-28T13:38:10.339925Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:10.339980Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2024-06-28T13:38:10.340007Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217496:4315] (SourceId=source2, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:10.340050Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 3 sessionId:  partition: 0 expectedGeneration: (NULL)
2024-06-28T13:38:10.341717Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:10.343334Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 3 partition: 0 MaxSeqNo: 0 sessionId: source2|5e86d439-d2dd2608-b63f0773-73e95195_0
2024-06-28T13:38:10.341530Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547981092217529:4315], now have 1 active actors on pipe
2024-06-28T13:38:10.342082Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.342107Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.342192Z node 14 :PERSQUEUE INFO: new Cookie source2|5e86d439-d2dd2608-b63f0773-73e95195_0 generated for partition 0 topic 'rt3.dc1--topic1' owner source2
2024-06-28T13:38:10.342274Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2024-06-28T13:38:10.342343Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.342899Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.342919Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.343011Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.345600Z :INFO: [] MessageGroupId [source2] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581890345 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:10.345741Z :INFO: [] MessageGroupId [source2] SessionId [] Write session established. Init response: session_id: "source2|5e86d439-d2dd2608-b63f0773-73e95195_0" topic: "topic1" cluster: "dc1" supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:10.346103Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:10.346164Z :INFO: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:10.346577Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session: try to update token
2024-06-28T13:38:10.346620Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:10.347877Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source2|5e86d439-d2dd2608-b63f0773-73e95195_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:10.348160Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:10.349468Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.349510Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.349654Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.349888Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:10.350354Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.350382Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.350435Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 0 SourceId: '\0source2' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:10.350618Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob processing sourceId '\0source2' seqNo 1 partNo 0
2024-06-28T13:38:10.351617Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob complete sourceId '\0source2' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 173 count 1 nextOffset 2 batches 1
2024-06-28T13:38:10.352236Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 0 compactOffset 1,1 HeadOffset 0 endOffset 1 curOffset 2 d0000000000_00000000000000000001_00000_0000000001_00000| size 161 WTime 1719581890352
2024-06-28T13:38:10.352442Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:10.360609Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:10.360659Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2024-06-28T13:38:10.360708Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source2', Topic: 'rt3.dc1--topic1', Partition: 0, SeqNo: 1, partNo: 0, Offset: 1 is stored on disk
2024-06-28T13:38:10.361726Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:10.365387Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.365421Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.365522Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:10.365609Z node 14 :PERSQUEUE DEBUG: read cookie 2 Topic 'rt3.dc1--topic1' partition 0 user user offset 1 count 1 size 193 endOffset 2 max time lag 0ms effective offset 1
2024-06-28T13:38:10.365628Z node 14 :PERSQUEUE DEBUG: read cookie 2 added 0 blobs, size 0 count 0 last offset 1
2024-06-28T13:38:10.365665Z node 14 :PERSQUEUE DEBUG: Reading cookie 2. All data is from uncompacted head.
2024-06-28T13:38:10.365689Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.365809Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.363482Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait for data done:  readOffset 1 EndOffset 1 newEndOffset 2 commitOffset 0 clientCommitOffset 0 cookie 2
2024-06-28T13:38:10.363526Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) ready for read with readOffset 1 endOffset 2
2024-06-28T13:38:10.363606Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:10.363775Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 1, endOffset# 2, WTime# 1719581890045, sizeLag# 161
2024-06-28T13:38:10.363792Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:10.363833Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# d8c84e8c-bd80ae28-4248bef8-a6179035, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:10.363888Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 1 EndOffset 2 ClientCommitOffset 0 committedOffset 0 Guid d8c84e8c-bd80ae28-4248bef8-a6179035
2024-06-28T13:38:10.366510Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) initDone 1 event { CmdReadResult { MaxOffset: 2 Result { Offset: 1 Data: "... 98 bytes ..." SourceId: "\000source2" SeqNo: 1 WriteTimestampMS: 1719581890350 CreateTimestampMS: 1719581890346 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 1 WaitQuotaTimeMs: 0 } Cookie: 1 }
2024-06-28T13:38:10.366620Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 3
2024-06-28T13:38:10.366657Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 2 ReadOffset 2 ReadGuid d8c84e8c-bd80ae28-4248bef8-a6179035 has messages 1
2024-06-28T13:38:10.366840Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# d8c84e8c-bd80ae28-4248bef8-a6179035, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), size# 197
2024-06-28T13:38:10.366878Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# d8c84e8c-bd80ae28-4248bef8-a6179035
2024-06-28T13:38:10.367049Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:10.371638Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session got write response: sequence_numbers: 1 offsets: 1 already_written: false write_statistics { persist_duration_ms: 9 queued_in_partition_duration_ms: 1 }
2024-06-28T13:38:10.371712Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session: acknoledged message 1
2024-06-28T13:38:10.372225Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:10.372738Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:10.372940Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# 72b97457-1b522fdb-fd34c0c1-5cfa8aa4
2024-06-28T13:38:10.447757Z :INFO: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session will now close
2024-06-28T13:38:10.447805Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session: aborting
2024-06-28T13:38:10.448899Z :INFO: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:10.449490Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session is aborting and will not restart
2024-06-28T13:38:10.451429Z :DEBUG: [] MessageGroupId [source2] SessionId [source2|5e86d439-d2dd2608-b63f0773-73e95195_0] Write session: destroy
2024-06-28T13:38:10.452496Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 3 sessionId: source2|5e86d439-d2dd2608-b63f0773-73e95195_0 grpc read done: success: 0 data: 
2024-06-28T13:38:10.452554Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: source2|5e86d439-d2dd2608-b63f0773-73e95195_0 grpc read failed
2024-06-28T13:38:10.452596Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: source2|5e86d439-d2dd2608-b63f0773-73e95195_0 grpc closed
2024-06-28T13:38:10.452624Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 3 sessionId: source2|5e86d439-d2dd2608-b63f0773-73e95195_0 is DEAD
2024-06-28T13:38:10.453623Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:10.455393Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547981092217529:4315] destroyed
2024-06-28T13:38:10.455457Z node 14 :PERSQUEUE DEBUG: [Partition:0, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:10.463130Z :DEBUG: [] MessageGroupId [source3] SessionId [] Write session: try to update token
2024-06-28T13:38:10.467187Z :INFO: [] MessageGroupId [source3] SessionId [] Write session: Do CDS request
2024-06-28T13:38:10.467219Z :INFO: [] MessageGroupId [source3] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:10.479989Z :DEBUG: [] MessageGroupId [source3] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source3" }
2024-06-28T13:38:10.488262Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:10.488319Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 4
2024-06-28T13:38:10.491910Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source3" }
2024-06-28T13:38:10.492092Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 4 topic: "topic1" message_group_id: "source3" from ipv6:[::1]:47846
2024-06-28T13:38:10.492122Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=4 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:10.492136Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:10.496031Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId:  describe result for acl check
2024-06-28T13:38:10.496202Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:10.496220Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:10.496233Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:10.496256Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:10.499941Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:10.510025Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:10.510418Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217579:4324] connected; active server actors: 1
2024-06-28T13:38:10.510605Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=source3
2024-06-28T13:38:10.510631Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:10.511288Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217579:4324] disconnected; active server actors: 1
2024-06-28T13:38:10.511314Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217579:4324] disconnected no session
2024-06-28T13:38:10.525380Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:10.525439Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2024-06-28T13:38:10.525467Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217562:4324] (SourceId=source3, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:10.525507Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 4 sessionId:  partition: 1 expectedGeneration: (NULL)
2024-06-28T13:38:10.527623Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:10.527277Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547981092217589:4324], now have 1 active actors on pipe
2024-06-28T13:38:10.527822Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.527856Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.528034Z node 14 :PERSQUEUE INFO: new Cookie source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0 generated for partition 1 topic 'rt3.dc1--topic1' owner source3
2024-06-28T13:38:10.528133Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 1
2024-06-28T13:38:10.528211Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.529423Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.529445Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.529564Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.531526Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 4 partition: 1 MaxSeqNo: 0 sessionId: source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0
2024-06-28T13:38:10.533886Z :INFO: [] MessageGroupId [source3] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581890533 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:10.534049Z :INFO: [] MessageGroupId [source3] SessionId [] Write session established. Init response: session_id: "source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:10.534314Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:10.534385Z :INFO: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:10.534803Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session: try to update token
2024-06-28T13:38:10.534869Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:10.536821Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:10.537095Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:10.538978Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:10.538065Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.538115Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.538773Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.539338Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.539359Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.539408Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source3' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:10.539595Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source3' seqNo 1 partNo 0
2024-06-28T13:38:10.540555Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\0source3' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 1 PartNo 0 PackedSize 173 count 1 nextOffset 2 batches 1
2024-06-28T13:38:10.541113Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 1,1 HeadOffset 0 endOffset 1 curOffset 2 d0000000001_00000000000000000001_00000_0000000001_00000| size 161 WTime 1719581890540
2024-06-28T13:38:10.541293Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:10.544500Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:10.544567Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 1
2024-06-28T13:38:10.544614Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source3', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 1, partNo: 0, Offset: 1 is stored on disk
2024-06-28T13:38:10.545497Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:10.546857Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.546893Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.546965Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:10.547046Z node 14 :PERSQUEUE DEBUG: read cookie 2 Topic 'rt3.dc1--topic1' partition 1 user user offset 1 count 1 size 193 endOffset 2 max time lag 0ms effective offset 1
2024-06-28T13:38:10.547065Z node 14 :PERSQUEUE DEBUG: read cookie 2 added 0 blobs, size 0 count 0 last offset 1
2024-06-28T13:38:10.547103Z node 14 :PERSQUEUE DEBUG: Reading cookie 2. All data is from uncompacted head.
2024-06-28T13:38:10.547136Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.547263Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.545719Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait for data done:  readOffset 1 EndOffset 1 newEndOffset 2 commitOffset 0 clientCommitOffset 0 cookie 2
2024-06-28T13:38:10.545759Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) ready for read with readOffset 1 endOffset 2
2024-06-28T13:38:10.545850Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:10.546297Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 1, endOffset# 2, WTime# 1719581890208, sizeLag# 161
2024-06-28T13:38:10.546316Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:10.546371Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# 72b97457-1b522fdb-fd34c0c1-5cfa8aa4, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:10.546421Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 1 EndOffset 2 ClientCommitOffset 0 committedOffset 0 Guid 72b97457-1b522fdb-fd34c0c1-5cfa8aa4
2024-06-28T13:38:10.547900Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 2 Result { Offset: 1 Data: "... 98 bytes ..." SourceId: "\000source3" SeqNo: 1 WriteTimestampMS: 1719581890539 CreateTimestampMS: 1719581890534 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 1 WaitQuotaTimeMs: 0 } Cookie: 1 }
2024-06-28T13:38:10.548542Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session got write response: sequence_numbers: 1 offsets: 1 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 2 queued_in_partition_duration_ms: 1 }
2024-06-28T13:38:10.548594Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session: acknoledged message 1
2024-06-28T13:38:10.548020Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 3
2024-06-28T13:38:10.548075Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 2 ReadOffset 2 ReadGuid 72b97457-1b522fdb-fd34c0c1-5cfa8aa4 has messages 1
2024-06-28T13:38:10.548213Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# 72b97457-1b522fdb-fd34c0c1-5cfa8aa4, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), size# 199
2024-06-28T13:38:10.548240Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# 72b97457-1b522fdb-fd34c0c1-5cfa8aa4
2024-06-28T13:38:10.548510Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:10.549320Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:10.551993Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:10.552191Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# efde7003-f5b73d33-a2876c35-b5b02966
2024-06-28T13:38:10.569978Z :INFO: [] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): null:topic1:1:1:1:0 null:topic1:0:2:1:0
2024-06-28T13:38:10.570069Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1002 BytesRead: 0 MessagesRead: 0 BytesReadCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 108 BytesInflightTotal: 108 MessagesInflight: 4 }
2024-06-28T13:38:10.639770Z :INFO: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session will now close
2024-06-28T13:38:10.639826Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session: aborting
2024-06-28T13:38:10.640237Z :INFO: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:10.640270Z :DEBUG: [] MessageGroupId [source3] SessionId [source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0] Write session: destroy
2024-06-28T13:38:10.641122Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 4 sessionId: source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0 grpc read done: success: 0 data: 
2024-06-28T13:38:10.641156Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0 grpc read failed
2024-06-28T13:38:10.641185Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0 grpc closed
2024-06-28T13:38:10.641209Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 4 sessionId: source3|d9b71951-a8eb1c3e-de38ebdc-54c3400b_0 is DEAD
2024-06-28T13:38:10.648136Z :DEBUG: [] MessageGroupId [source4] SessionId [] Write session: try to update token
2024-06-28T13:38:10.654778Z :INFO: [] MessageGroupId [source4] SessionId [] Write session: Do CDS request
2024-06-28T13:38:10.654824Z :INFO: [] MessageGroupId [source4] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:10.662719Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:10.663485Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547981092217589:4324] destroyed
2024-06-28T13:38:10.663586Z node 14 :PERSQUEUE DEBUG: [Partition:1, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:10.674481Z :DEBUG: [] MessageGroupId [source4] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source4" }
2024-06-28T13:38:10.679774Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:10.679821Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 5
2024-06-28T13:38:10.682175Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source4" }
2024-06-28T13:38:10.682340Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 5 topic: "topic1" message_group_id: "source4" from ipv6:[::1]:47846
2024-06-28T13:38:10.682363Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=5 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:10.682376Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:10.684197Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId:  describe result for acl check
2024-06-28T13:38:10.684369Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:10.684383Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:10.684397Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:10.684423Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:10.687670Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:10.697924Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:10.698423Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217619:4311] connected; active server actors: 1
2024-06-28T13:38:10.698572Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=source4
2024-06-28T13:38:10.698597Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:10.699200Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217619:4311] disconnected; active server actors: 1
2024-06-28T13:38:10.699225Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217619:4311] disconnected no session
2024-06-28T13:38:10.711297Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:10.711350Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2024-06-28T13:38:10.711374Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217601:4311] (SourceId=source4, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:10.711409Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 5 sessionId:  partition: 0 expectedGeneration: (NULL)
2024-06-28T13:38:10.713560Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:10.713926Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547981092217630:4311], now have 1 active actors on pipe
2024-06-28T13:38:10.713980Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.713999Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.714087Z node 14 :PERSQUEUE INFO: new Cookie source4|fe23a773-e89a52a1-f0f81307-c517b447_0 generated for partition 0 topic 'rt3.dc1--topic1' owner source4
2024-06-28T13:38:10.714169Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2024-06-28T13:38:10.714243Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.716109Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 5 partition: 0 MaxSeqNo: 0 sessionId: source4|fe23a773-e89a52a1-f0f81307-c517b447_0
2024-06-28T13:38:10.717415Z :INFO: [] MessageGroupId [source4] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581890717 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:10.717554Z :INFO: [] MessageGroupId [source4] SessionId [] Write session established. Init response: session_id: "source4|fe23a773-e89a52a1-f0f81307-c517b447_0" topic: "topic1" cluster: "dc1" supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:10.717834Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:10.717900Z :INFO: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:10.714877Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.714902Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.715003Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.720186Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session: try to update token
2024-06-28T13:38:10.720244Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:10.721014Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source4|fe23a773-e89a52a1-f0f81307-c517b447_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:10.721318Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:10.722520Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:10.722148Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.722186Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.722296Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.722972Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.722989Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.723048Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 0 SourceId: '\0source4' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:10.723244Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob processing sourceId '\0source4' seqNo 1 partNo 0
2024-06-28T13:38:10.724355Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob complete sourceId '\0source4' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 2 PartNo 0 PackedSize 173 count 1 nextOffset 3 batches 1
2024-06-28T13:38:10.725015Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 0 compactOffset 2,1 HeadOffset 0 endOffset 2 curOffset 3 d0000000000_00000000000000000002_00000_0000000001_00000| size 161 WTime 1719581890723
2024-06-28T13:38:10.725263Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:10.729232Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:10.729275Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2024-06-28T13:38:10.729320Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source4', Topic: 'rt3.dc1--topic1', Partition: 0, SeqNo: 1, partNo: 0, Offset: 2 is stored on disk
2024-06-28T13:38:10.730300Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:10.730917Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait for data done:  readOffset 2 EndOffset 2 newEndOffset 3 commitOffset 0 clientCommitOffset 0 cookie 3
2024-06-28T13:38:10.730951Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) ready for read with readOffset 2 endOffset 3
2024-06-28T13:38:10.731016Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:10.731202Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 2, endOffset# 3, WTime# 1719581890350, sizeLag# 161
2024-06-28T13:38:10.731234Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:10.731273Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# efde7003-f5b73d33-a2876c35-b5b02966, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:10.731339Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 2 EndOffset 3 ClientCommitOffset 0 committedOffset 0 Guid efde7003-f5b73d33-a2876c35-b5b02966
2024-06-28T13:38:10.731957Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session got write response: sequence_numbers: 1 offsets: 2 already_written: false write_statistics { persist_duration_ms: 3 }
2024-06-28T13:38:10.732031Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session: acknoledged message 1
2024-06-28T13:38:10.732203Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.732234Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:10.732301Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:10.732379Z node 14 :PERSQUEUE DEBUG: read cookie 3 Topic 'rt3.dc1--topic1' partition 0 user user offset 2 count 1 size 193 endOffset 3 max time lag 0ms effective offset 2
2024-06-28T13:38:10.732397Z node 14 :PERSQUEUE DEBUG: read cookie 3 added 0 blobs, size 0 count 0 last offset 2
2024-06-28T13:38:10.732430Z node 14 :PERSQUEUE DEBUG: Reading cookie 3. All data is from uncompacted head.
2024-06-28T13:38:10.732454Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.732578Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 2
2024-06-28T13:38:10.733359Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) initDone 1 event { CmdReadResult { MaxOffset: 3 Result { Offset: 2 Data: "... 98 bytes ..." SourceId: "\000source4" SeqNo: 1 WriteTimestampMS: 1719581890722 CreateTimestampMS: 1719581890717 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 2 WaitQuotaTimeMs: 0 } Cookie: 2 }
2024-06-28T13:38:10.733469Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 4
2024-06-28T13:38:10.733506Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 3 ReadOffset 3 ReadGuid efde7003-f5b73d33-a2876c35-b5b02966 has messages 1
2024-06-28T13:38:10.733616Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# efde7003-f5b73d33-a2876c35-b5b02966, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), size# 197
2024-06-28T13:38:10.733643Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# efde7003-f5b73d33-a2876c35-b5b02966
2024-06-28T13:38:10.733857Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:10.736200Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:10.736685Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:10.736817Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# 8cb0cf5d-31c4739d-af9cef91-4a8323c8
2024-06-28T13:38:10.819123Z :INFO: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session will now close
2024-06-28T13:38:10.819171Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session: aborting
2024-06-28T13:38:10.819644Z :INFO: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:10.819675Z :DEBUG: [] MessageGroupId [source4] SessionId [source4|fe23a773-e89a52a1-f0f81307-c517b447_0] Write session: destroy
2024-06-28T13:38:10.824298Z :DEBUG: [] MessageGroupId [source5] SessionId [] Write session: try to update token
2024-06-28T13:38:10.820429Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 5 sessionId: source4|fe23a773-e89a52a1-f0f81307-c517b447_0 grpc read done: success: 0 data: 
2024-06-28T13:38:10.820457Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: source4|fe23a773-e89a52a1-f0f81307-c517b447_0 grpc read failed
2024-06-28T13:38:10.826359Z :INFO: [] MessageGroupId [source5] SessionId [] Write session: Do CDS request
2024-06-28T13:38:10.826391Z :INFO: [] MessageGroupId [source5] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:10.820539Z node 13 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 5 sessionId: source4|fe23a773-e89a52a1-f0f81307-c517b447_0
2024-06-28T13:38:10.820564Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 5 sessionId: source4|fe23a773-e89a52a1-f0f81307-c517b447_0 is DEAD
2024-06-28T13:38:10.833073Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547981092217630:4311] destroyed
2024-06-28T13:38:10.833143Z node 14 :PERSQUEUE DEBUG: [Partition:0, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:10.820985Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:10.856555Z :DEBUG: [] MessageGroupId [source5] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source5" }
2024-06-28T13:38:10.856343Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:10.856391Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 6
2024-06-28T13:38:10.857239Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source5" }
2024-06-28T13:38:10.857413Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 6 topic: "topic1" message_group_id: "source5" from ipv6:[::1]:47846
2024-06-28T13:38:10.857435Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=6 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:10.857450Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:10.859379Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId:  describe result for acl check
2024-06-28T13:38:10.859545Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:10.859568Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:10.859584Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:10.859608Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:10.863406Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:10.880432Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:10.881791Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217659:4304] connected; active server actors: 1
2024-06-28T13:38:10.881927Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=source5
2024-06-28T13:38:10.881957Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:10.882695Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217659:4304] disconnected; active server actors: 1
2024-06-28T13:38:10.882719Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547981092217659:4304] disconnected no session
2024-06-28T13:38:10.901099Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:10.901153Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2024-06-28T13:38:10.901177Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547981092217637:4304] (SourceId=source5, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:10.901214Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 6 sessionId:  partition: 1 expectedGeneration: (NULL)
2024-06-28T13:38:10.902473Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547981092217671:4304], now have 1 active actors on pipe
2024-06-28T13:38:10.904635Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:10.905543Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.905582Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.905685Z node 14 :PERSQUEUE INFO: new Cookie source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0 generated for partition 1 topic 'rt3.dc1--topic1' owner source5
2024-06-28T13:38:10.905768Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 1
2024-06-28T13:38:10.905838Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.913076Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 6 partition: 1 MaxSeqNo: 0 sessionId: source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0
2024-06-28T13:38:10.912473Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.912512Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.912661Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:10.916390Z :INFO: [] MessageGroupId [source5] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581890916 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:10.916589Z :INFO: [] MessageGroupId [source5] SessionId [] Write session established. Init response: session_id: "source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:10.916979Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:10.917058Z :INFO: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:10.920112Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session: try to update token
2024-06-28T13:38:10.920167Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:10.921036Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId: source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:10.921327Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:10.922036Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.922070Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.922181Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:10.922560Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:10.923053Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.923080Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.923136Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source5' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:10.923332Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source5' seqNo 1 partNo 0
2024-06-28T13:38:10.924462Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\0source5' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 2 PartNo 0 PackedSize 173 count 1 nextOffset 3 batches 1
2024-06-28T13:38:10.925099Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 2,1 HeadOffset 0 endOffset 2 curOffset 3 d0000000001_00000000000000000002_00000_0000000001_00000| size 161 WTime 1719581890924
2024-06-28T13:38:10.925299Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:10.936766Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:10.936811Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 1
2024-06-28T13:38:10.936853Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source5', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 1, partNo: 0, Offset: 2 is stored on disk
2024-06-28T13:38:10.937874Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:10.938791Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait for data done:  readOffset 2 EndOffset 2 newEndOffset 3 commitOffset 0 clientCommitOffset 0 cookie 3
2024-06-28T13:38:10.938844Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) ready for read with readOffset 2 endOffset 3
2024-06-28T13:38:10.938954Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:10.939507Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 2, endOffset# 3, WTime# 1719581890539, sizeLag# 161
2024-06-28T13:38:10.939535Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:10.939595Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# 8cb0cf5d-31c4739d-af9cef91-4a8323c8, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:10.939678Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 2 EndOffset 3 ClientCommitOffset 0 committedOffset 0 Guid 8cb0cf5d-31c4739d-af9cef91-4a8323c8
2024-06-28T13:38:10.940975Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session got write response: sequence_numbers: 1 offsets: 2 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 11 queued_in_partition_duration_ms: 1 }
2024-06-28T13:38:10.941036Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session: acknoledged message 1
2024-06-28T13:38:10.941714Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:10.941745Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:10.941812Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:10.941895Z node 14 :PERSQUEUE DEBUG: read cookie 3 Topic 'rt3.dc1--topic1' partition 1 user user offset 2 count 1 size 193 endOffset 3 max time lag 0ms effective offset 2
2024-06-28T13:38:10.941914Z node 14 :PERSQUEUE DEBUG: read cookie 3 added 0 blobs, size 0 count 0 last offset 2
2024-06-28T13:38:10.941947Z node 14 :PERSQUEUE DEBUG: Reading cookie 3. All data is from uncompacted head.
2024-06-28T13:38:10.941968Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:10.942079Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 2
2024-06-28T13:38:10.942854Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 3 Result { Offset: 2 Data: "... 98 bytes ..." SourceId: "\000source5" SeqNo: 1 WriteTimestampMS: 1719581890922 CreateTimestampMS: 1719581890916 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 2 WaitQuotaTimeMs: 0 } Cookie: 2 }
2024-06-28T13:38:10.942963Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 4
2024-06-28T13:38:10.942999Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 3 ReadOffset 3 ReadGuid 8cb0cf5d-31c4739d-af9cef91-4a8323c8 has messages 1
2024-06-28T13:38:10.943133Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# 8cb0cf5d-31c4739d-af9cef91-4a8323c8, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), size# 199
2024-06-28T13:38:10.943157Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# 8cb0cf5d-31c4739d-af9cef91-4a8323c8
2024-06-28T13:38:10.943341Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:10.944095Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:10.944439Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:10.944554Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# 105c4308-d9458eca-1280b860-484bc550
2024-06-28T13:38:11.020151Z :INFO: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session will now close
2024-06-28T13:38:11.020206Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session: aborting
2024-06-28T13:38:11.020684Z :INFO: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:11.020716Z :DEBUG: [] MessageGroupId [source5] SessionId [source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0] Write session: destroy
2024-06-28T13:38:11.025998Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 6 sessionId: source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0 grpc read done: success: 0 data: 
2024-06-28T13:38:11.026028Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0 grpc read failed
2024-06-28T13:38:11.026059Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0 grpc closed
2024-06-28T13:38:11.028253Z :DEBUG: [] MessageGroupId [source6] SessionId [] Write session: try to update token
2024-06-28T13:38:11.028549Z :INFO: [] MessageGroupId [source6] SessionId [] Write session: Do CDS request
2024-06-28T13:38:11.028575Z :INFO: [] MessageGroupId [source6] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:11.026081Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 6 sessionId: source5|71f04ea6-b599a448-ca684a16-b3acd7a6_0 is DEAD
2024-06-28T13:38:11.026902Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:11.033087Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547981092217671:4304] destroyed
2024-06-28T13:38:11.033146Z node 14 :PERSQUEUE DEBUG: [Partition:1, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:11.040447Z :DEBUG: [] MessageGroupId [source6] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source6" }
2024-06-28T13:38:11.041956Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:11.041993Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 7
2024-06-28T13:38:11.042587Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source6" }
2024-06-28T13:38:11.042737Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 7 topic: "topic1" message_group_id: "source6" from ipv6:[::1]:47846
2024-06-28T13:38:11.042757Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=7 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:11.042770Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:11.045621Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId:  describe result for acl check
2024-06-28T13:38:11.045793Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:11.045808Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:11.045823Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:11.045849Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:11.050108Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:11.067610Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:11.068153Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387184996:4323] connected; active server actors: 1
2024-06-28T13:38:11.068220Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=source6
2024-06-28T13:38:11.068242Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:11.069052Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387184996:4323] disconnected; active server actors: 1
2024-06-28T13:38:11.069079Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387184996:4323] disconnected no session
2024-06-28T13:38:11.079313Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:11.079366Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2024-06-28T13:38:11.079390Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387184978:4323] (SourceId=source6, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:11.079432Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 7 sessionId:  partition: 1 expectedGeneration: (NULL)
2024-06-28T13:38:11.081158Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:11.085327Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547985387185005:4323], now have 1 active actors on pipe
2024-06-28T13:38:11.085411Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.085436Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.085538Z node 14 :PERSQUEUE INFO: new Cookie source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0 generated for partition 1 topic 'rt3.dc1--topic1' owner source6
2024-06-28T13:38:11.085637Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 1
2024-06-28T13:38:11.085713Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.086394Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.086420Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.086520Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.086916Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 7 partition: 1 MaxSeqNo: 0 sessionId: source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0
2024-06-28T13:38:11.087737Z :INFO: [] MessageGroupId [source6] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581891087 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:11.087896Z :INFO: [] MessageGroupId [source6] SessionId [] Write session established. Init response: session_id: "source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:11.088145Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:11.088219Z :INFO: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:11.088619Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session: try to update token
2024-06-28T13:38:11.088666Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:11.090883Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId: source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:11.091212Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:11.092374Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.092407Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.092519Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:11.092847Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:11.093340Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.093366Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.093424Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source6' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:11.093627Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source6' seqNo 1 partNo 0
2024-06-28T13:38:11.094677Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\0source6' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 3 PartNo 0 PackedSize 173 count 1 nextOffset 4 batches 1
2024-06-28T13:38:11.095302Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 3,1 HeadOffset 0 endOffset 3 curOffset 4 d0000000001_00000000000000000003_00000_0000000001_00000| size 161 WTime 1719581891089
2024-06-28T13:38:11.095507Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:11.104147Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:11.104201Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 1
2024-06-28T13:38:11.104249Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source6', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 1, partNo: 0, Offset: 3 is stored on disk
2024-06-28T13:38:11.104281Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:11.105403Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:11.106483Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session got write response: sequence_numbers: 1 offsets: 3 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 12 }
2024-06-28T13:38:11.106535Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session: acknoledged message 1
2024-06-28T13:38:11.107952Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait for data done:  readOffset 3 EndOffset 3 newEndOffset 4 commitOffset 0 clientCommitOffset 0 cookie 4
2024-06-28T13:38:11.107987Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) ready for read with readOffset 3 endOffset 4
2024-06-28T13:38:11.108043Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 3, endOffset# 4, WTime# 1719581890922, sizeLag# 161
2024-06-28T13:38:11.108057Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:11.108096Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# 105c4308-d9458eca-1280b860-484bc550, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:11.108142Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 3 EndOffset 4 ClientCommitOffset 0 committedOffset 0 Guid 105c4308-d9458eca-1280b860-484bc550
2024-06-28T13:38:11.110534Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.110570Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.110640Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:11.110721Z node 14 :PERSQUEUE DEBUG: read cookie 4 Topic 'rt3.dc1--topic1' partition 1 user user offset 3 count 1 size 193 endOffset 4 max time lag 0ms effective offset 3
2024-06-28T13:38:11.110740Z node 14 :PERSQUEUE DEBUG: read cookie 4 added 0 blobs, size 0 count 0 last offset 3
2024-06-28T13:38:11.110776Z node 14 :PERSQUEUE DEBUG: Reading cookie 4. All data is from uncompacted head.
2024-06-28T13:38:11.110802Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:11.110917Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 3
2024-06-28T13:38:11.111894Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 4 Result { Offset: 3 Data: "... 98 bytes ..." SourceId: "\000source6" SeqNo: 1 WriteTimestampMS: 1719581891089 CreateTimestampMS: 1719581891088 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 3 WaitQuotaTimeMs: 0 } Cookie: 3 }
2024-06-28T13:38:11.112020Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 5
2024-06-28T13:38:11.112057Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 4 ReadOffset 4 ReadGuid 105c4308-d9458eca-1280b860-484bc550 has messages 1
2024-06-28T13:38:11.112184Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# 105c4308-d9458eca-1280b860-484bc550, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), size# 199
2024-06-28T13:38:11.112208Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# 105c4308-d9458eca-1280b860-484bc550
2024-06-28T13:38:11.112486Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:11.113384Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:11.114097Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:11.114199Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# a1539cca-2ff5f435-4c86cf6d-f9eca1ea
2024-06-28T13:38:11.191752Z :INFO: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session will now close
2024-06-28T13:38:11.191809Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session: aborting
2024-06-28T13:38:11.192273Z :INFO: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:11.192303Z :DEBUG: [] MessageGroupId [source6] SessionId [source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0] Write session: destroy
2024-06-28T13:38:11.199200Z :DEBUG: [] MessageGroupId [source7] SessionId [] Write session: try to update token
2024-06-28T13:38:11.199781Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 7 sessionId: source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0 grpc read done: success: 0 data: 
2024-06-28T13:38:11.199813Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId: source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0 grpc read failed
2024-06-28T13:38:11.199880Z node 13 :PQ_WRITE_PROXY INFO: session v1 closed cookie: 7 sessionId: source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0
2024-06-28T13:38:11.199905Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 7 sessionId: source6|2c964e99-b6231f2e-ef5d205c-732bd6bc_0 is DEAD
2024-06-28T13:38:11.213214Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547985387185005:4323] destroyed
2024-06-28T13:38:11.200316Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:11.213320Z node 14 :PERSQUEUE DEBUG: [Partition:1, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:11.234812Z :INFO: [] MessageGroupId [source7] SessionId [] Write session: Do CDS request
2024-06-28T13:38:11.234855Z :INFO: [] MessageGroupId [source7] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:11.250776Z :DEBUG: [] MessageGroupId [source7] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source7" }
2024-06-28T13:38:11.256188Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:11.256224Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 8
2024-06-28T13:38:11.256796Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 8 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source7" }
2024-06-28T13:38:11.256944Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 8 topic: "topic1" message_group_id: "source7" from ipv6:[::1]:47846
2024-06-28T13:38:11.256965Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=8 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:11.256977Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:11.258862Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 8 sessionId:  describe result for acl check
2024-06-28T13:38:11.259023Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:11.259038Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:11.259053Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:11.259075Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:11.262310Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:11.273727Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:11.278592Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185042:4310] connected; active server actors: 1
2024-06-28T13:38:11.278668Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=source7
2024-06-28T13:38:11.278691Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:11.279269Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185042:4310] disconnected; active server actors: 1
2024-06-28T13:38:11.279296Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185042:4310] disconnected no session
2024-06-28T13:38:11.313433Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:11.313495Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2024-06-28T13:38:11.313521Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185020:4310] (SourceId=source7, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:11.313558Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 8 sessionId:  partition: 0 expectedGeneration: (NULL)
2024-06-28T13:38:11.314885Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547985387185051:4310], now have 1 active actors on pipe
2024-06-28T13:38:11.319933Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:11.320278Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.320315Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.320422Z node 14 :PERSQUEUE INFO: new Cookie source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0 generated for partition 0 topic 'rt3.dc1--topic1' owner source7
2024-06-28T13:38:11.320514Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2024-06-28T13:38:11.320611Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.327540Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.327589Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.327733Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.329548Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 8 partition: 0 MaxSeqNo: 0 sessionId: source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0
2024-06-28T13:38:11.332262Z :INFO: [] MessageGroupId [source7] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581891332 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:11.332397Z :INFO: [] MessageGroupId [source7] SessionId [] Write session established. Init response: session_id: "source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0" topic: "topic1" cluster: "dc1" supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:11.333947Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:11.334037Z :INFO: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:11.334446Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session: try to update token
2024-06-28T13:38:11.334483Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:11.338883Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.338927Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.339038Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:11.337080Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 8 sessionId: source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:11.337412Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:11.339376Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:11.339903Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.339934Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.340003Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 0 SourceId: '\0source7' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:11.340220Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob processing sourceId '\0source7' seqNo 1 partNo 0
2024-06-28T13:38:11.341268Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob complete sourceId '\0source7' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 3 PartNo 0 PackedSize 173 count 1 nextOffset 4 batches 1
2024-06-28T13:38:11.341930Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 0 compactOffset 3,1 HeadOffset 0 endOffset 3 curOffset 4 d0000000000_00000000000000000003_00000_0000000001_00000| size 161 WTime 1719581891341
2024-06-28T13:38:11.342144Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:11.349664Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:11.349706Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2024-06-28T13:38:11.349753Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source7', Topic: 'rt3.dc1--topic1', Partition: 0, SeqNo: 1, partNo: 0, Offset: 3 is stored on disk
2024-06-28T13:38:11.349775Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:11.350892Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session got write response: sequence_numbers: 1 offsets: 3 already_written: false write_statistics { persist_duration_ms: 8 queued_in_partition_duration_ms: 3 }
2024-06-28T13:38:11.350955Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session: acknoledged message 1
2024-06-28T13:38:11.350086Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:11.417659Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.417702Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.417785Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:11.417878Z node 14 :PERSQUEUE DEBUG: read cookie 4 Topic 'rt3.dc1--topic1' partition 0 user user offset 3 count 1 size 193 endOffset 4 max time lag 0ms effective offset 3
2024-06-28T13:38:11.417897Z node 14 :PERSQUEUE DEBUG: read cookie 4 added 0 blobs, size 0 count 0 last offset 3
2024-06-28T13:38:11.417931Z node 14 :PERSQUEUE DEBUG: Reading cookie 4. All data is from uncompacted head.
2024-06-28T13:38:11.417953Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:11.418081Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 3
2024-06-28T13:38:11.416098Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait for data done:  readOffset 3 EndOffset 3 newEndOffset 4 commitOffset 0 clientCommitOffset 0 cookie 4
2024-06-28T13:38:11.416137Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) ready for read with readOffset 3 endOffset 4
2024-06-28T13:38:11.416201Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 3, endOffset# 4, WTime# 1719581890722, sizeLag# 161
2024-06-28T13:38:11.416217Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:11.416268Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# a1539cca-2ff5f435-4c86cf6d-f9eca1ea, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:11.416318Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 3 EndOffset 4 ClientCommitOffset 0 committedOffset 0 Guid a1539cca-2ff5f435-4c86cf6d-f9eca1ea
2024-06-28T13:38:11.418669Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) initDone 1 event { CmdReadResult { MaxOffset: 4 Result { Offset: 3 Data: "... 98 bytes ..." SourceId: "\000source7" SeqNo: 1 WriteTimestampMS: 1719581891336 CreateTimestampMS: 1719581891333 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 3 WaitQuotaTimeMs: 0 } Cookie: 3 }
2024-06-28T13:38:11.418790Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 5
2024-06-28T13:38:11.418825Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 4 ReadOffset 4 ReadGuid a1539cca-2ff5f435-4c86cf6d-f9eca1ea has messages 1
2024-06-28T13:38:11.418942Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# a1539cca-2ff5f435-4c86cf6d-f9eca1ea, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), size# 197
2024-06-28T13:38:11.418976Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# a1539cca-2ff5f435-4c86cf6d-f9eca1ea
2024-06-28T13:38:11.419280Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:11.424253Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:11.425003Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:11.425132Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# 8967e069-dae1cbcd-d4495dc-8d0af734
2024-06-28T13:38:11.438339Z :INFO: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session will now close
2024-06-28T13:38:11.438393Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session: aborting
2024-06-28T13:38:11.438808Z :INFO: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:11.438845Z :DEBUG: [] MessageGroupId [source7] SessionId [source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0] Write session: destroy
2024-06-28T13:38:11.439683Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 8 sessionId: source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0 grpc read done: success: 0 data: 
2024-06-28T13:38:11.439735Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 8 sessionId: source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0 grpc read failed
2024-06-28T13:38:11.439787Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 8 sessionId: source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0 grpc closed
2024-06-28T13:38:11.439811Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 8 sessionId: source7|77e4e2e-eb9aaa3c-b91a7ad7-53e60606_0 is DEAD
2024-06-28T13:38:11.440894Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:11.442181Z :DEBUG: [] MessageGroupId [source8] SessionId [] Write session: try to update token
2024-06-28T13:38:11.444628Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547985387185051:4310] destroyed
2024-06-28T13:38:11.444694Z node 14 :PERSQUEUE DEBUG: [Partition:0, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:11.447857Z :INFO: [] MessageGroupId [source8] SessionId [] Write session: Do CDS request
2024-06-28T13:38:11.447896Z :INFO: [] MessageGroupId [source8] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:11.460280Z :DEBUG: [] MessageGroupId [source8] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source8" }
2024-06-28T13:38:11.464035Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:11.464074Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 9
2024-06-28T13:38:11.464634Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 9 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source8" }
2024-06-28T13:38:11.464822Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 9 topic: "topic1" message_group_id: "source8" from ipv6:[::1]:47846
2024-06-28T13:38:11.464848Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=9 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:11.464861Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:11.469859Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 9 sessionId:  describe result for acl check
2024-06-28T13:38:11.469984Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:11.469994Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:11.470003Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:11.470020Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:11.473039Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:11.482847Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:11.483342Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185089:4335] connected; active server actors: 1
2024-06-28T13:38:11.483662Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) Received partition 1 from PQRB for SourceId=source8
2024-06-28T13:38:11.483708Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:11.484236Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185089:4335] disconnected; active server actors: 1
2024-06-28T13:38:11.484257Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185089:4335] disconnected no session
2024-06-28T13:38:11.502742Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:11.502800Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) ReplyResult: Partition=1, SeqNo=(NULL)
2024-06-28T13:38:11.502825Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185069:4335] (SourceId=source8, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:11.502861Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 9 sessionId:  partition: 1 expectedGeneration: (NULL)
2024-06-28T13:38:11.504057Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547985387185107:4335], now have 1 active actors on pipe
2024-06-28T13:38:11.504332Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:11.504717Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.504748Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.504832Z node 14 :PERSQUEUE INFO: new Cookie source8|672ea7cc-e78070c6-e1309150-58d57c97_0 generated for partition 1 topic 'rt3.dc1--topic1' owner source8
2024-06-28T13:38:11.504918Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 1
2024-06-28T13:38:11.504981Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.505655Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.505682Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.505780Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.506075Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 9 partition: 1 MaxSeqNo: 0 sessionId: source8|672ea7cc-e78070c6-e1309150-58d57c97_0
2024-06-28T13:38:11.511903Z :INFO: [] MessageGroupId [source8] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581891511 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:11.512066Z :INFO: [] MessageGroupId [source8] SessionId [] Write session established. Init response: session_id: "source8|672ea7cc-e78070c6-e1309150-58d57c97_0" topic: "topic1" cluster: "dc1" partition_id: 1 supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:11.515804Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:11.515896Z :INFO: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:11.517292Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session: try to update token
2024-06-28T13:38:11.517339Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:11.520447Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 9 sessionId: source8|672ea7cc-e78070c6-e1309150-58d57c97_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:11.520871Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:11.521676Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.521717Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.521823Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:11.522111Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:11.522444Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.522467Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.522520Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 1 SourceId: '\0source8' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:11.522698Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob processing sourceId '\0source8' seqNo 1 partNo 0
2024-06-28T13:38:11.523796Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 1 part blob complete sourceId '\0source8' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 4 PartNo 0 PackedSize 173 count 1 nextOffset 5 batches 1
2024-06-28T13:38:11.524361Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 1 compactOffset 4,1 HeadOffset 0 endOffset 4 curOffset 5 d0000000001_00000000000000000004_00000_0000000001_00000| size 161 WTime 1719581891523
2024-06-28T13:38:11.524574Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:11.527835Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:11.527877Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 1
2024-06-28T13:38:11.527913Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source8', Topic: 'rt3.dc1--topic1', Partition: 1, SeqNo: 1, partNo: 0, Offset: 4 is stored on disk
2024-06-28T13:38:11.569295Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:11.572754Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session got write response: sequence_numbers: 1 offsets: 4 already_written: false partition_id: 1 write_statistics { persist_duration_ms: 4 queued_in_partition_duration_ms: 1 }
2024-06-28T13:38:11.572803Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session: acknoledged message 1
2024-06-28T13:38:11.571918Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait for data done:  readOffset 4 EndOffset 4 newEndOffset 5 commitOffset 0 clientCommitOffset 0 cookie 5
2024-06-28T13:38:11.571957Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) ready for read with readOffset 4 endOffset 5
2024-06-28T13:38:11.572030Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::IEventHandle
2024-06-28T13:38:11.572462Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), readOffset# 4, endOffset# 5, WTime# 1719581891089, sizeLag# 161
2024-06-28T13:38:11.572480Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:11.572516Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# 8967e069-dae1cbcd-d4495dc-8d0af734, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:11.572580Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 4 EndOffset 5 ClientCommitOffset 0 committedOffset 0 Guid 8967e069-dae1cbcd-d4495dc-8d0af734
2024-06-28T13:38:11.574148Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.574186Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 1
2024-06-28T13:38:11.574315Z node 14 :PERSQUEUE DEBUG: read cookie 5 Topic 'rt3.dc1--topic1' partition 1 user user offset 4 count 1 size 193 endOffset 5 max time lag 0ms effective offset 4
2024-06-28T13:38:11.574342Z node 14 :PERSQUEUE DEBUG: read cookie 5 added 0 blobs, size 0 count 0 last offset 4
2024-06-28T13:38:11.574389Z node 14 :PERSQUEUE DEBUG: Reading cookie 5. All data is from uncompacted head.
2024-06-28T13:38:11.574416Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:11.574515Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:11.574567Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 1 messageNo: 0  requestId: <none> cookie: 4
2024-06-28T13:38:11.576048Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) initDone 1 event { CmdReadResult { MaxOffset: 5 Result { Offset: 4 Data: "... 98 bytes ..." SourceId: "\000source8" SeqNo: 1 WriteTimestampMS: 1719581891522 CreateTimestampMS: 1719581891515 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 4 WaitQuotaTimeMs: 0 } Cookie: 4 }
2024-06-28T13:38:11.576176Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) wait data in partition inited, cookie 6
2024-06-28T13:38:11.576213Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1) EndOffset 5 ReadOffset 5 ReadGuid 8967e069-dae1cbcd-d4495dc-8d0af734 has messages 1
2024-06-28T13:38:11.576373Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# 8967e069-dae1cbcd-d4495dc-8d0af734, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 1(assignId:1), size# 199
2024-06-28T13:38:11.576400Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# 8967e069-dae1cbcd-d4495dc-8d0af734
2024-06-28T13:38:11.576683Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:11.577671Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:11.580051Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:11.580198Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# acc0d41a-21b7c5c4-95d5dd5e-f6479e68
2024-06-28T13:38:11.619812Z :INFO: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session will now close
2024-06-28T13:38:11.619866Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session: aborting
2024-06-28T13:38:11.620323Z :INFO: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:11.620354Z :DEBUG: [] MessageGroupId [source8] SessionId [source8|672ea7cc-e78070c6-e1309150-58d57c97_0] Write session: destroy
2024-06-28T13:38:11.623372Z node 13 :FLAT_TX_SCHEMESHARD WARN: Cannot get console configs
2024-06-28T13:38:11.623405Z node 13 :IMPORT WARN: Table profiles were not loaded
2024-06-28T13:38:11.626023Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547985387185107:4335] destroyed
2024-06-28T13:38:11.626088Z node 14 :PERSQUEUE DEBUG: [Partition:1, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:11.624467Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 9 sessionId: source8|672ea7cc-e78070c6-e1309150-58d57c97_0 grpc read done: success: 0 data: 
2024-06-28T13:38:11.624490Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 9 sessionId: source8|672ea7cc-e78070c6-e1309150-58d57c97_0 grpc read failed
2024-06-28T13:38:11.624538Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 9 sessionId: source8|672ea7cc-e78070c6-e1309150-58d57c97_0 grpc closed
2024-06-28T13:38:11.624560Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 9 sessionId: source8|672ea7cc-e78070c6-e1309150-58d57c97_0 is DEAD
2024-06-28T13:38:11.625415Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=1) Received event: NActors::TEvents::TEvPoison
2024-06-28T13:38:11.628451Z :DEBUG: [] MessageGroupId [source9] SessionId [] Write session: try to update token
2024-06-28T13:38:11.628734Z :INFO: [] MessageGroupId [source9] SessionId [] Write session: Do CDS request
2024-06-28T13:38:11.628758Z :INFO: [] MessageGroupId [source9] SessionId [] Start write session. Will connect to endpoint: localhost:16697
2024-06-28T13:38:11.647939Z :DEBUG: [] MessageGroupId [source9] SessionId [] Write session: send init request: init_request { topic: "topic1" message_group_id: "source9" }
2024-06-28T13:38:11.651779Z node 13 :PQ_WRITE_PROXY DEBUG: new grpc connection
2024-06-28T13:38:11.651822Z node 13 :PQ_WRITE_PROXY DEBUG: new session created cookie 10
2024-06-28T13:38:11.652452Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 10 sessionId:  grpc read done: success: 1 data: init_request { topic: "topic1" message_group_id: "source9" }
2024-06-28T13:38:11.652624Z node 13 :PQ_WRITE_PROXY INFO: session request cookie: 10 topic: "topic1" message_group_id: "source9" from ipv6:[::1]:47846
2024-06-28T13:38:11.652658Z node 13 :PQ_WRITE_PROXY INFO: write session:  cookie=10 sessionId= userAgent="pqv1 server" ip=ipv6:[::1]:47846 proto=v1  topic=topic1 durationSec=0
2024-06-28T13:38:11.652673Z node 13 :PQ_WRITE_PROXY INFO: init check schema
2024-06-28T13:38:11.661127Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 10 sessionId:  describe result for acl check
2024-06-28T13:38:11.661314Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper SelectQuery: --!syntax_v1
DECLARE $Hash AS Uint32; DECLARE $Topic AS Utf8; DECLARE $SourceId AS Utf8;
SELECT Partition, CreateTime, AccessTime, SeqNo FROM `/Root/PQ/SourceIdMeta2` WHERE Hash == $Hash AND Topic == $Topic AND SourceId == $SourceId;
2024-06-28T13:38:11.661336Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;DECLARE $SeqNo AS Uint64;
UPSERT INTO `/Root/PQ/SourceIdMeta2` (Hash, Topic, SourceId, CreateTime, AccessTime, Partition, SeqNo) VALUES ($Hash, $Topic, $SourceId, $CreateTime, $AccessTime, $Partition, $SeqNo);
2024-06-28T13:38:11.661349Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TTableHelper UpdateAccessTimeQuery: --!syntax_v1
DECLARE $SourceId AS Utf8; DECLARE $Topic AS Utf8; DECLARE $Hash AS Uint32; DECLARE $Partition AS Uint32; DECLARE $CreateTime AS Uint64; DECLARE $AccessTime AS Uint64;
UPDATE `/Root/PQ/SourceIdMeta2` SET AccessTime = $AccessTime WHERE Hash = $Hash AND Topic = $Topic AND SourceId = $SourceId AND Partition = $Partition;
2024-06-28T13:38:11.661371Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) StartKqpSession
2024-06-28T13:38:11.666381Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) Select from the table
2024-06-28T13:38:11.680399Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) RequestPQRB
2024-06-28T13:38:11.680948Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185136:4316] connected; active server actors: 1
2024-06-28T13:38:11.681069Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) Received partition 0 from PQRB for SourceId=source9
2024-06-28T13:38:11.681101Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) Update the table
2024-06-28T13:38:11.681899Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185136:4316] disconnected; active server actors: 1
2024-06-28T13:38:11.681931Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547985387185136:4316] disconnected no session
2024-06-28T13:38:11.705692Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) HandleUpdate PartitionPersisted=0 Status=SUCCESS
2024-06-28T13:38:11.705747Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) ReplyResult: Partition=0, SeqNo=(NULL)
2024-06-28T13:38:11.705770Z node 13 :PQ_PARTITION_CHOOSER DEBUG: TPartitionChooser [13:7385547985387185116:4316] (SourceId=source9, PreferedPartition=(NULL)) Start idle
2024-06-28T13:38:11.705802Z node 13 :PQ_WRITE_PROXY DEBUG: ProceedPartition. session cookie: 10 sessionId:  partition: 0 expectedGeneration: (NULL)
2024-06-28T13:38:11.711133Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server connected, pipe [13:7385547985387185166:4316], now have 1 active actors on pipe
2024-06-28T13:38:11.711980Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) TEvClientConnected Status OK, TabletId: 72075186224037892, NodeId 14, Generation: 1
2024-06-28T13:38:11.715384Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.715420Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.715510Z node 14 :PERSQUEUE INFO: new Cookie source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0 generated for partition 0 topic 'rt3.dc1--topic1' owner source9
2024-06-28T13:38:11.715586Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyOwnerOk. Partition: 0
2024-06-28T13:38:11.715648Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.720023Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.720070Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.720189Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 0
2024-06-28T13:38:11.722648Z :INFO: [] MessageGroupId [source9] SessionId [] Counters: { Errors: 0 CurrentSessionLifetimeMs: 1719581891722 BytesWritten: 0 MessagesWritten: 0 BytesWrittenCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 0 BytesInflightTotal: 0 MessagesInflight: 0 }
2024-06-28T13:38:11.722787Z :INFO: [] MessageGroupId [source9] SessionId [] Write session established. Init response: session_id: "source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0" topic: "topic1" cluster: "dc1" supported_codecs: CODEC_RAW supported_codecs: CODEC_GZIP supported_codecs: CODEC_LZOP
2024-06-28T13:38:11.723087Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write 1 messages with Id from 1 to 1
2024-06-28T13:38:11.723165Z :INFO: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session: close. Timeout = 10000 ms
2024-06-28T13:38:11.720638Z node 13 :PQ_WRITE_PROXY INFO: session inited cookie: 10 partition: 0 MaxSeqNo: 0 sessionId: source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0
2024-06-28T13:38:11.724183Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session: try to update token
2024-06-28T13:38:11.724229Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Send 1 message(s) (0 left), first sequence number is 1
2024-06-28T13:38:11.725761Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.725798Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.725902Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 1
2024-06-28T13:38:11.726669Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.726696Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.726756Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message topic: rt3.dc1--topic1 partition: 0 SourceId: '\0source9' SeqNo: 1 partNo : 0 messageNo: 1 size 98 offset: -1
2024-06-28T13:38:11.726939Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob processing sourceId '\0source9' seqNo 1 partNo 0
2024-06-28T13:38:11.724951Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 10 sessionId: source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0 grpc read done: success: 1 data:  write_request[data omitted]
2024-06-28T13:38:11.725234Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NKikimr::NPQ::TEvPartitionWriter::TEvWriteRequest
2024-06-28T13:38:11.726283Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:11.727916Z node 14 :PERSQUEUE DEBUG: Topic 'rt3.dc1--topic1' partition 0 part blob complete sourceId '\0source9' seqNo 1 partNo 0 FormedBlobsCount 0 NewHead: Offset 4 PartNo 0 PackedSize 173 count 1 nextOffset 5 batches 1
2024-06-28T13:38:11.728520Z node 14 :PERSQUEUE DEBUG: Add new write blob: topic 'rt3.dc1--topic1' partition 0 compactOffset 4,1 HeadOffset 0 endOffset 4 curOffset 5 d0000000000_00000000000000000004_00000_0000000001_00000| size 161 WTime 1719581891728
2024-06-28T13:38:11.728743Z node 14 :PERSQUEUE DEBUG: CacheProxy. Passthrough write request to KV
2024-06-28T13:38:11.731996Z node 14 :PERSQUEUE DEBUG: TPartition::HandleWriteResponse writeNewSize# 106
2024-06-28T13:38:11.732036Z node 14 :PERSQUEUE DEBUG: TPartition::ReplyWrite. Partition: 0
2024-06-28T13:38:11.732079Z node 14 :PERSQUEUE DEBUG: Answering for message sourceid: '\0source9', Topic: 'rt3.dc1--topic1', Partition: 0, SeqNo: 1, partNo: 0, Offset: 4 is stored on disk
2024-06-28T13:38:11.745504Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 1  requestId: <none> cookie: 1
2024-06-28T13:38:11.746959Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::IEventHandle
2024-06-28T13:38:11.747987Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session got write response: sequence_numbers: 1 offsets: 4 already_written: false write_statistics { persist_duration_ms: 4 queued_in_partition_duration_ms: 1 }
2024-06-28T13:38:11.748035Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session: acknoledged message 1
2024-06-28T13:38:11.827763Z :INFO: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session will now close
2024-06-28T13:38:11.827814Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session: aborting
2024-06-28T13:38:11.828217Z :INFO: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session: gracefully shut down, all writes complete
2024-06-28T13:38:11.828248Z :DEBUG: [] MessageGroupId [source9] SessionId [source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0] Write session: destroy
2024-06-28T13:38:11.832446Z node 13 :PQ_WRITE_PROXY DEBUG: session v1 cookie: 10 sessionId: source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0 grpc read done: success: 0 data: 
2024-06-28T13:38:11.832474Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 10 sessionId: source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0 grpc read failed
2024-06-28T13:38:11.832508Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 10 sessionId: source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0 grpc closed
2024-06-28T13:38:11.832550Z node 13 :PQ_WRITE_PROXY INFO: session v1 cookie: 10 sessionId: source9|8661e074-5dfdce7a-d5094fb6-7bfec86_0 is DEAD
2024-06-28T13:38:11.833411Z node 13 :PQ_WRITE_PROXY DEBUG: TPartitionWriter 72075186224037892 (partition=0) Received event: NActors::TEvents::TEvPoison
===== Write =====
MessagesInflight: 9
BytesInflightUncompressed: 0
BytesInflightCompressed: 243
BytesInflightTotal: 243
============
2024-06-28T13:38:11.835853Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait for data done:  readOffset 4 EndOffset 4 newEndOffset 5 commitOffset 0 clientCommitOffset 0 cookie 5
2024-06-28T13:38:11.835886Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) ready for read with readOffset 4 endOffset 5
2024-06-28T13:38:11.835937Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 partition ready for read: partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), readOffset# 4, endOffset# 5, WTime# 1719581891336, sizeLag# 161
2024-06-28T13:38:11.835951Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1TEvPartitionReady. Aval parts: 1
2024-06-28T13:38:11.835981Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 performing read request: guid# acc0d41a-21b7c5c4-95d5dd5e-f6479e68, from# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), count# 1, size# 193, partitionsAsked# 1, maxTimeLag# 0ms
2024-06-28T13:38:11.836018Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 READ FROM TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2)maxCount 1 maxSize 193 maxTimeLagMs 0 readTimestampMs 0 readOffset 4 EndOffset 5 ClientCommitOffset 0 committedOffset 0 Guid acc0d41a-21b7c5c4-95d5dd5e-f6479e68
2024-06-28T13:38:11.837676Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) initDone 1 event { CmdReadResult { MaxOffset: 5 Result { Offset: 4 Data: "... 98 bytes ..." SourceId: "\000source9" SeqNo: 1 WriteTimestampMS: 1719581891726 CreateTimestampMS: 1719581891723 UncompressedSize: 15 PartitionKey: "" ExplicitHash: "" } BlobsFromDisk: 0 BlobsFromCache: 0 SizeLag: 20 RealReadOffset: 4 WaitQuotaTimeMs: 0 } Cookie: 4 }
2024-06-28T13:38:11.837786Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) wait data in partition inited, cookie 6
2024-06-28T13:38:11.837824Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 after read state TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2) EndOffset 5 ReadOffset 5 ReadGuid acc0d41a-21b7c5c4-95d5dd5e-f6479e68 has messages 1
2024-06-28T13:38:11.837932Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 read done: guid# acc0d41a-21b7c5c4-95d5dd5e-f6479e68, partition# TopicId: Topic rt3.dc1--topic1 in dc dc1 in database: Root, partition 0(assignId:2), size# 197
2024-06-28T13:38:11.837963Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 response to read: guid# acc0d41a-21b7c5c4-95d5dd5e-f6479e68
2024-06-28T13:38:11.838259Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 Process answer. Aval parts: 0
2024-06-28T13:38:11.835835Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547985387185166:4316] destroyed
2024-06-28T13:38:11.835907Z node 14 :PERSQUEUE DEBUG: [Partition:0, State:StateIdle] TPartition::DropOwner.
2024-06-28T13:38:11.836697Z node 14 :PERSQUEUE DEBUG: Handle TEvRequest topic: 'rt3.dc1--topic1' requestId: <none>
2024-06-28T13:38:11.836724Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 got client message batch for topic 'rt3.dc1--topic1' partition 0
2024-06-28T13:38:11.836794Z node 14 :PERSQUEUE DEBUG: Read proxy: bootstrap for direct read id: 0
2024-06-28T13:38:11.836874Z node 14 :PERSQUEUE DEBUG: read cookie 5 Topic 'rt3.dc1--topic1' partition 0 user user offset 4 count 1 size 193 endOffset 5 max time lag 0ms effective offset 4
2024-06-28T13:38:11.836894Z node 14 :PERSQUEUE DEBUG: read cookie 5 added 0 blobs, size 0 count 0 last offset 4
2024-06-28T13:38:11.836928Z node 14 :PERSQUEUE DEBUG: Reading cookie 5. All data is from uncompacted head.
2024-06-28T13:38:11.836953Z node 14 :PERSQUEUE DEBUG: FormAnswer 0
2024-06-28T13:38:11.853840Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] After sending read request: ReadSizeBudget = 52428800, ReadSizeServerDelta = 0
2024-06-28T13:38:11.837070Z node 14 :PERSQUEUE DEBUG: Answer ok topic: 'rt3.dc1--topic1' partition: 0 messageNo: 0  requestId: <none> cookie: 4
2024-06-28T13:38:11.856199Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 1, data# { read { } }
2024-06-28T13:38:11.856375Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 got read request: guid# fdc6b6ba-7f9604ca-dbcd4eee-48886a11
2024-06-28T13:38:12.734239Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Closing read session. Close timeout: 0.000000s
2024-06-28T13:38:12.734313Z :INFO: [] Read/commit by partition streams (cluster:topic:partition:stream-id:read-offset:committed-offset): null:topic1:1:1:4:0 null:topic1:0:2:4:0
2024-06-28T13:38:12.734362Z :INFO: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Counters: { Errors: 0 CurrentSessionLifetimeMs: 3167 BytesRead: 0 MessagesRead: 0 BytesReadCompressed: 0 BytesInflightUncompressed: 0 BytesInflightCompressed: 270 BytesInflightTotal: 270 MessagesInflight: 10 }
2024-06-28T13:38:12.734559Z :NOTICE: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Close with zero timeout " }
2024-06-28T13:38:12.734620Z :DEBUG: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] [null] Abort session to cluster
2024-06-28T13:38:12.735377Z :NOTICE: [] [] [5804a87b-8e29e15f-b9bf4f27-f2f7d60b] Aborting read session. Description: SessionClosed { Status: ABORTED Issues: "<main>: Error: Aborted " }
2024-06-28T13:38:12.736030Z node 13 :PQ_READ_PROXY DEBUG: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read done: success# 0, data# {  }
2024-06-28T13:38:12.736063Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 grpc read failed
2024-06-28T13:38:12.739961Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 closed
2024-06-28T13:38:12.772055Z node 13 :PQ_READ_PROXY INFO: session cookie 1 consumer shared/user session shared/user_13_1_2041620033203687009_v1 is DEAD
2024-06-28T13:38:12.772722Z node 13 :PERSQUEUE_READ_BALANCER INFO: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547976797250062:4326] disconnected; active server actors: 1
2024-06-28T13:38:12.772759Z node 13 :PERSQUEUE_READ_BALANCER NOTICE: balancer: [72075186224037893] topic rt3.dc1--topic1 pipe [13:7385547976797250062:4326] client user disconnected session shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:12.777087Z node 14 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:12.777144Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547976797250067:4325] destroyed
2024-06-28T13:38:12.777168Z node 14 :PERSQUEUE DEBUG: PQ: Destroy direct read session shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:12.777185Z node 14 :PERSQUEUE DEBUG: Tablet 72075186224037892 server disconnected, pipe [13:7385547976797250066:4330] destroyed
2024-06-28T13:38:12.787601Z node 14 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_13_1_2041620033203687009_v1
2024-06-28T13:38:12.795407Z node 14 :PQ_READ_PROXY DEBUG: Direct read cache: server session deregistered: shared/user_13_1_2041620033203687009_v1
[[bad]]assertion failed at ydb/services/persqueue_v1/persqueue_ut.cpp:3154, virtual void NKikimr::NPersQueueTests::NTestSuiteTPersQueueTest::TTestCaseCheckKillBalancer::Execute_(NUnitTest::TTestContext &): (counters->MessagesInflight->Val() == 10) failed: (9 != 10) [[rst]]
[[alt1]]NUnitTest::NPrivate::RaiseError(char const*, TBasicString<char, std::__y1::char_traits<char>> const&, bool)+636 (0x18AFE5BC)
NKikimr::NPersQueueTests::NTestSuiteTPersQueueTest::TTestCaseCheckKillBalancer::Execute_(NUnitTest::TTestContext&)+25742 (0x17FC01AE)
std::__y1::__function::__func<NKikimr::NPersQueueTests::NTestSuiteTPersQueueTest::TCurrentTest::Execute()::'lambda'(), std::__y1::allocator<NKikimr::NPersQueueTests::NTestSuiteTPersQueueTest::TCurrentTest::Execute()::'lambda'()>, void ()>::operator()()+537 (0x181DAE89)
TColoredProcessor::Run(std::__y1::function<void ()>, TBasicString<char, std::__y1::char_traits<char>> const&, char const*, bool)+539 (0x18B45FFB)
NUnitTest::TTestBase::Run(std::__y1::function<void ()>, TBasicString<char, std::__y1::char_traits<char>> const&, char const*, bool)+550 (0x18B062A6)
NKikimr::NPersQueueTests::NTestSuiteTPersQueueTest::TCurrentTest::Execute()+1588 (0x181D99B4)
NUnitTest::TTestFactory::Execute()+2794 (0x18B07FEA)
NUnitTest::RunMain(int, char**)+7405 (0x18B3E46D)
??+0 (0x7FE4E8EFCD90)
__libc_start_main+128 (0x7FE4E8EFCE40)
??+0 (0x1580D029)
[[rst]]