2025-11-14T08:30:19.174724Z node 10 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[10:7572495577496378810:2078];send_to=[0:7307199536658146131:7762515];
2025-11-14T08:30:19.174773Z node 10 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:69;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message;
test_client.cpp: SetPath # /home/runner/.ya/build/build_root/n9gb/00346e/r3tmp/tmpxj1soS/pdisk_1.dat
2025-11-14T08:30:19.381122Z node 10 :IMPORT WARN: Table profiles were not loaded
2025-11-14T08:30:19.399486Z node 10 :HIVE WARN: HIVE#72057594037968897 Node(10, (0,0,0,0)) VolatileState: Unknown -> Disconnected
2025-11-14T08:30:19.399573Z node 10 :HIVE WARN: HIVE#72057594037968897 Node(10, (0,0,0,0)) VolatileState: Disconnected -> Connecting
2025-11-14T08:30:19.406766Z node 10 :HIVE WARN: HIVE#72057594037968897 Node(10, (0,0,0,0)) VolatileState: Connecting -> Connected
TServer::EnableGrpc on GrpcPort 24610, node 10
2025-11-14T08:30:19.539727Z node 10 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: (empty maybe)
2025-11-14T08:30:19.539755Z node 10 :NET_CLASSIFIER WARN: will try to initialize from file: (empty maybe)
2025-11-14T08:30:19.539765Z node 10 :NET_CLASSIFIER WARN: failed to initialize from file: (empty maybe)
2025-11-14T08:30:19.539921Z node 10 :NET_CLASSIFIER ERROR: got bad distributable configuration
TClient is connected to server localhost:22276
WaitRootIsUp 'Root'...
TClient::Ls request: Root
TClient::Ls response: Status: 1
StatusCode: SUCCESS
SchemeStatus: 0
PathDescription {
  Self {
    Name: "Root"
    PathId: 1
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 1
    CreateStep: 0
    ParentPathId: 1
    PathState: EPathStateNoChanges
    Owner: "root@builtin"
    ACL: ""
    EffectiveACL: ""
    PathVersion: 2
    PathSubType: EPathSubTypeEmpty
    Version {
      GeneralVersion: 2
      ACLVersion: 0
      EffectiveACLVersion: 0
      UserAttrsVersion: 1
      ChildrenVersion: 1
      SubDomainVersion: 0
      SecurityStateVersion: 0
    }
    ChildrenExist: false
  }
  Children {
    Name: ".sys"
    PathId: 18446744073709551615
    SchemeshardId: 72057594046644480
    PathType: EPathTypeDir
    CreateFinished: true
    CreateTxId: 0
    CreateStep: 0
    ParentPathId: 18446744073709551615
  }
  DomainDescription {
    SchemeShardId_Depricated: 72057594046644480
    PathId_Depricated: 1
    ProcessingParams {
      Version: 0
      Pl...
(TRUNCATED)
WaitRootIsUp 'Root' success.
2025-11-14T08:30:19.837327Z node 10 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpAlterSubDomain, opId: 281474976710657:0, at schemeshard:  72057594046644480
waiting...
2025-11-14T08:30:20.189599Z node 10 :TX_CONVEYOR ERROR: fline=service.h:53;problem=unexpected event for task executor;ev_type=NActors::TEvents::TEvWakeup;
2025-11-14T08:30:22.477730Z node 10 :FLAT_TX_SCHEMESHARD WARN: Operation part proposed ok, but propose itself is undo unsafe, suboperation type: ESchemeOpCreateTable, opId: 281474976710658:0, at schemeshard:  72057594046644480
2025-11-14T08:30:22.502817Z node 10 :TX_DATASHARD INFO: TDataShard::OnActivateExecutor: tablet 72075186224037888 actor [10:7572495590381281724:2319]
2025-11-14T08:30:22.503125Z node 10 :TX_DATASHARD DEBUG: TxInitSchema.Execute
2025-11-14T08:30:22.515776Z node 10 :TX_DATASHARD DEBUG: TxInitSchema.Complete
2025-11-14T08:30:22.515857Z node 10 :TX_DATASHARD DEBUG: TDataShard::TTxInit::Execute
2025-11-14T08:30:22.517652Z node 10 :TX_DATASHARD DEBUG: LoadChangeRecords: QueueSize: 0, at tablet: 72075186224037888
2025-11-14T08:30:22.517725Z node 10 :TX_DATASHARD DEBUG: LoadLockChangeRecords at tablet: 72075186224037888
2025-11-14T08:30:22.517851Z node 10 :TX_DATASHARD DEBUG: LoadChangeRecordCommits at tablet: 72075186224037888
2025-11-14T08:30:22.518229Z node 10 :TX_DATASHARD DEBUG: TDataShard::TTxInit::Complete
2025-11-14T08:30:22.518284Z node 10 :TX_DATASHARD DEBUG: TDataShard::TTxInitRestored::Execute
2025-11-14T08:30:22.518321Z node 10 :TX_DATASHARD DEBUG: DataShard 72075186224037888 persisting started state actor id [10:7572495590381281748:2319] in generation 1
2025-11-14T08:30:22.521817Z node 10 :TX_DATASHARD DEBUG: TDataShard::TTxInitRestored::Complete
2025-11-14T08:30:22.521877Z node 10 :TX_DATASHARD INFO: Switched to work state WaitScheme tabletId 72075186224037888
2025-11-14T08:30:22.521946Z node 10 :TX_DATASHARD DEBUG: 72075186224037888 not sending time cast registration request in state WaitScheme: missing processing params
2025-11-14T08:30:22.521980Z node 10 :TX_DATASHARD DEBUG: Change sender created: at tablet: 72075186224037888, actorId: [10:7572495590381281751:2320]
2025-11-14T08:30:22.522007Z node 10 :TX_DATASHARD DEBUG: Trying to activate change sender: at tablet: 72075186224037888
2025-11-14T08:30:22.522025Z node 10 :TX_DATASHARD INFO: Cannot activate change sender: at tablet: 72075186224037888, state: WaitScheme
2025-11-14T08:30:22.522037Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
2025-11-14T08:30:22.522134Z node 10 :TX_DATASHARD DEBUG: TTxCheckInReadSets::Execute at 72075186224037888
2025-11-14T08:30:22.522233Z node 10 :TX_DATASHARD DEBUG: TTxCheckInReadSets::Complete found 0 read sets to remove in 72075186224037888
2025-11-14T08:30:22.522264Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Execute at 72075186224037888
2025-11-14T08:30:22.522284Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 active 0 active planned 0 immediate 0 planned 0
2025-11-14T08:30:22.522300Z node 10 :TX_DATASHARD INFO: No tx to execute at 72075186224037888 TxInFly 0
2025-11-14T08:30:22.522331Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Complete at 72075186224037888
2025-11-14T08:30:22.542988Z node 10 :TX_DATASHARD DEBUG: Server connected at leader tablet# 72075186224037888, clientId# [10:7572495590381281710:2654], serverId# [10:7572495590381281756:2685], sessionId# [0:0:0]
2025-11-14T08:30:22.543159Z node 10 :TX_DATASHARD DEBUG: TTxProposeTransactionBase::Execute at 72075186224037888
2025-11-14T08:30:22.543428Z node 10 :TX_DATASHARD DEBUG: Propose scheme transaction at tablet 72075186224037888 txId 281474976710658 ssId 72057594046644480 seqNo 2:1
2025-11-14T08:30:22.543516Z node 10 :TX_DATASHARD DEBUG: Prepared scheme transaction txId 281474976710658 at tablet 72075186224037888
2025-11-14T08:30:22.545100Z node 10 :TX_DATASHARD DEBUG: Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at datashard 72075186224037888
2025-11-14T08:30:22.547707Z node 10 :TX_DATASHARD DEBUG: TTxProposeTransactionBase::Complete at 72075186224037888
2025-11-14T08:30:22.547790Z node 10 :TX_DATASHARD DEBUG: 72075186224037888 not sending time cast registration request in state WaitScheme
2025-11-14T08:30:22.562984Z node 10 :TX_DATASHARD DEBUG: Server connected at leader tablet# 72075186224037888, clientId# [10:7572495590381281790:2699], serverId# [10:7572495590381281791:2700], sessionId# [0:0:0]
2025-11-14T08:30:22.568024Z node 10 :TX_DATASHARD DEBUG: Planned transaction txId 281474976710658 at step 1763109022605 at tablet 72075186224037888 { Transactions { TxId: 281474976710658 AckTo { RawX1: 0 RawX2: 0 } } Step: 1763109022605 MediatorID: 72057594046382081 TabletID: 72075186224037888 }
2025-11-14T08:30:22.568062Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
2025-11-14T08:30:22.568223Z node 10 :TX_DATASHARD DEBUG: Discovered subdomain [OwnerId: 72057594046644480, LocalPathId: 1] state, outOfSpace = 0 at datashard 72075186224037888
2025-11-14T08:30:22.568351Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Execute at 72075186224037888
2025-11-14T08:30:22.568383Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 active 0 active planned 0 immediate 0 planned 1
2025-11-14T08:30:22.568414Z node 10 :TX_DATASHARD DEBUG: Found ready operation [1763109022605:281474976710658] in PlanQueue unit at 72075186224037888
2025-11-14T08:30:22.568677Z node 10 :TX_DATASHARD DEBUG: LoadTxDetails at 72075186224037888 loaded tx from db 1763109022605:281474976710658 keys extracted: 0
2025-11-14T08:30:22.568797Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 (dry run) active 1 active planned 1 immediate 0 planned 1
2025-11-14T08:30:22.568877Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Execute at 72075186224037888
2025-11-14T08:30:22.568919Z node 10 :TX_DATASHARD INFO: Trying to CREATE TABLE at 72075186224037888 tableId# [OwnerId: 72057594046644480, LocalPathId: 2] schema version# 1
2025-11-14T08:30:22.569404Z node 10 :TX_DATASHARD INFO: Send registration request to time cast Ready tabletId 72075186224037888 mediators count is 1 coordinators count is 1 buckets per mediator 2
2025-11-14T08:30:22.569716Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 (dry run) active 0 active planned 0 immediate 0 planned 0
2025-11-14T08:30:22.571009Z node 10 :TX_DATASHARD DEBUG: Got TEvMediatorTimecast::TEvRegisterTabletResult at 72075186224037888 time 1763109022604
2025-11-14T08:30:22.571047Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
2025-11-14T08:30:22.571909Z node 10 :TX_DATASHARD DEBUG: Got TEvMediatorTimecast::TEvSubscribeReadStepResult at 72075186224037888 coordinator 72057594046316545 last step 0 next step 1763109022612
2025-11-14T08:30:22.571960Z node 10 :TX_DATASHARD DEBUG: Sending '{TEvPlanStepAccepted TabletId# 72075186224037888 step# 1763109022605}
2025-11-14T08:30:22.571998Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Complete at 72075186224037888
2025-11-14T08:30:22.572333Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Complete at 72075186224037888
2025-11-14T08:30:22.572361Z node 10 :TX_DATASHARD DEBUG: Trying to activate change sender: at tablet: 72075186224037888
2025-11-14T08:30:22.572388Z node 10 :TX_DATASHARD INFO: Change sender activated: at tablet: 72075186224037888
2025-11-14T08:30:22.572438Z node 10 :TX_DATASHARD DEBUG: Complete [1763109022605 : 281474976710658] from 72075186224037888 at tablet 72075186224037888 send result to client [10:7572495577496379122:2198], exec latency: 0 ms, propose latency: 3 ms
2025-11-14T08:30:22.572471Z node 10 :TX_DATASHARD INFO: 72075186224037888 Sending notify to schemeshard 72057594046644480 txId 281474976710658 state Ready TxInFly 0
2025-11-14T08:30:22.572528Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
2025-11-14T08:30:22.574488Z node 10 :TX_DATASHARD DEBUG: Handle TEvSchemaChangedResult 281474976710658  datashard 72075186224037888 state Ready
2025-11-14T08:30:22.574540Z node 10 :TX_DATASHARD DEBUG: 72075186224037888 Got TEvSchemaChangedResult from SS at 72075186224037888
FALLBACK_ACTOR_LOGGING;priority=DEBUG;component=2100;fline=native.cpp:110;event=serialize;size=10280;columns=12;
2025-11-14T08:30:22.598109Z node 10 :TX_DATASHARD DEBUG: Server connected at leader tablet# 72075186224037888, clientId# [10:7572495590381281842:2741], serverId# [10:7572495590381281843:2742], sessionId# [0:0:0]
2025-11-14T08:30:22.598208Z node 10 :TX_DATASHARD INFO: TTxDirectBase(36) Execute: at tablet# 72075186224037888
2025-11-14T08:30:22.604803Z node 10 :TX_DATASHARD INFO: TTxDirectBase(36) Complete: at tablet# 72075186224037888
2025-11-14T08:30:22.604842Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
SUCCESS
Upsert done: 0.023480s
2025-11-14T08:30:22.701257Z node 10 :TX_DATASHARD DEBUG: TTxProposeTransactionBase::Execute at 72075186224037888
2025-11-14T08:30:22.701369Z node 10 :TX_DATASHARD DEBUG: Prepared Snapshot transaction txId 281474976710659 at tablet 72075186224037888
2025-11-14T08:30:22.706174Z node 10 :TX_DATASHARD DEBUG: TTxProposeTransactionBase::Complete at 72075186224037888
2025-11-14T08:30:22.708672Z node 10 :TX_DATASHARD DEBUG: Planned transaction txId 281474976710659 at step 1763109022752 at tablet 72075186224037888 { Transactions { TxId: 281474976710659 AckTo { RawX1: 0 RawX2: 0 } } Step: 1763109022752 MediatorID: 72057594046382081 TabletID: 72075186224037888 }
2025-11-14T08:30:22.708698Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
2025-11-14T08:30:22.708822Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Execute at 72075186224037888
2025-11-14T08:30:22.708844Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 active 0 active planned 0 immediate 0 planned 1
2025-11-14T08:30:22.708864Z node 10 :TX_DATASHARD DEBUG: Found ready operation [1763109022752:281474976710659] in PlanQueue unit at 72075186224037888
2025-11-14T08:30:22.709040Z node 10 :TX_DATASHARD DEBUG: LoadTxDetails at 72075186224037888 loaded tx from db 1763109022752:281474976710659 keys extracted: 0
2025-11-14T08:30:22.709319Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 (dry run) active 0 active planned 0 immediate 0 planned 0
2025-11-14T08:30:22.710603Z node 10 :TX_DATASHARD DEBUG: Sending '{TEvPlanStepAccepted TabletId# 72075186224037888 step# 1763109022752}
2025-11-14T08:30:22.710644Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Complete at 72075186224037888
2025-11-14T08:30:22.710684Z node 10 :TX_DATASHARD DEBUG: Complete [1763109022752 : 281474976710659] from 72075186224037888 at tablet 72075186224037888 send result to client [10:7572495590381281860:2753], exec latency: 0 ms, propose latency: 1 ms
2025-11-14T08:30:22.710702Z node 10 :TX_DATASHARD DEBUG: [CdcStreamHeartbeat] Emit heartbeats: at tablet# 72075186224037888
2025-11-14T08:30:22.711661Z node 10 :KQP_EXECUTER ERROR: TxId: 281474976710660. Ctx: { TraceId: 01ka0qsawmdtvgk2gjw44a4x18, Database: , DatabaseId: /Root, SessionId: ydb://session/3?node_id=10&id=NWJhNjRkYTYtNWUyMDE1ZjgtYmJhNTViODAtYTJmMWMzODA=, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
2025-11-14T08:30:22.713414Z node 10 :TX_DATASHARD INFO: Start scan, at: [10:7572495590381281889:2128], tablet: [10:7572495590381281724:2319], scanId: 5, table: /Root/LogsX, gen: 1, deadline: 2025-11-14T08:40:22.712904Z
2025-11-14T08:30:22.713948Z node 10 :TX_DATASHARD DEBUG: Got ScanDataAck, at: [10:7572495590381281889:2128], scanId: 5, table: /Root/LogsX, gen: 1, tablet: [10:7572495590381281724:2319], freeSpace: 8388608;limits:(bytes=0;chunks=0);
2025-11-14T08:30:22.713976Z node 10 :TX_DATASHARD DEBUG: Wakeup driver at: [10:7572495590381281889:2128]
2025-11-14T08:30:22.715297Z node 10 :TX_DATASHARD DEBUG: Range 0 of 1 exhausted: try next one. table: /Root/LogsX range: [(Utf8 : NULL, Timestamp : NULL) ; ()) next range: <none>
2025-11-14T08:30:22.715321Z node 10 :TX_DATASHARD DEBUG: TableRanges is over, at: [10:7572495590381281889:2128], scanId: 5, table: /Root/LogsX
2025-11-14T08:30:22.715357Z node 10 :TX_DATASHARD DEBUG: Finish scan, at: [10:7572495590381281889:2128], scanId: 5, table: /Root/LogsX, reason: 0, abortEvent: <none>
2025-11-14T08:30:22.715384Z node 10 :TX_DATASHARD DEBUG: Send ScanData, from: [10:7572495590381281889:2128], to: [10:7572495590381281884:2330], scanId: 5, table: /Root/LogsX, bytes: 12600, rows: 100, page faults: 0, finished: 1, pageFault: 0
2025-11-14T08:30:22.715475Z node 10 :TX_DATASHARD DEBUG: FullScan complete at 72075186224037888
2025-11-14T08:30:22.715584Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Execute at 72075186224037888
2025-11-14T08:30:22.715607Z node 10 :TX_DATASHARD DEBUG: GetNextActiveOp at 72075186224037888 active 0 active planned 0 immediate 0 planned 0
2025-11-14T08:30:22.715627Z node 10 :TX_DATASHARD INFO: No tx to execute at 72075186224037888 TxInFly 0
2025-11-14T08:30:22.715671Z node 10 :TX_DATASHARD DEBUG: TTxProgressTransaction::Complete at 72075186224037888
2025-11-14T08:30:22.723787Z node 10 :KQP_RESOURCE_MANAGER WARN: KqpSnapshotManager: discarding snapshot; our snapshot: [step: 1763109022752, txId: 281474976710659] shutting down
2025-11-14T08:30:23.155010Z node 10 :KQP_EXECUTER ERROR: TxId: 281474976710661. Ctx: { TraceId: 01ka0qsb0fczajg41khz5x40y2, Database: , DatabaseId: /Root, SessionId: ydb://session/3?node_id=10&id=YjA1ZTNmMjUtNDI5M2E5MmEtZGEyNGJkNTMtZTcxYzdjYTU=, CurrentExecutionId: , CustomerSuppliedId: , PoolId: }. Database not set, use /Root
SUCCESS
count returned 100 rows
Negative (wrong format): BAD_REQUEST
Negative (wrong data): SCHEME_ERROR
FALLBACK_ACTOR_LOGGING;priority=DEBUG;component=2100;fline=native.cpp:110;event=serialize;size=9432;columns=11;
2025-11-14T08:30:23.186261Z node 10 :ARROW_HELPER ERROR: fline=arrow_helpers.cpp:146;event=cannot_parse;message=Invalid: Ran out of field metadata, likely malformed;schema_columns_count=12;schema_columns=timestamp,resource_type,resource_id,uid,level,message,json_payload,ingested_at,saved_at,request_id,flt,dbl;
Negative (less columns): BAD_REQUEST
FALLBACK_ACTOR_LOGGING;priority=DEBUG;component=2100;fline=native.cpp:110;event=serialize;size=10280;columns=12;
2025-11-14T08:30:23.194366Z node 10 :ARROW_HELPER ERROR: fline=arrow_helpers.cpp:146;event=cannot_parse;message=Serialization error: batch is not valid: Invalid: Offsets buffer size (bytes): 400 isn't large enough for length: 100;schema_columns_count=12;schema_columns=timestamp,resource_type,resource_id,uid,level,message,json_payload,ingested_at,saved_at,request_id,flt,dbl;
Negative (reordered columns): BAD_REQUEST
