Lake Table Schema Change Job Permanently Stuck Due to Version Discontinuity in Shared-Data Mode

[nancodex]

Lake Table Schema Change Job Permanently Stuck Due to Version Discontinuity in Shared-Data Mode

StarRocks version (Required)

• StarRocks 3.5.3

Steps to reproduce the behavior (Required)

1. CREATE TABLE speechai.ods_server_log_test003 (Lake table with date partitioning in shared-data mode)
2. INSERT INTO speechai.ods_server_log_test003 (heavy concurrent writes, producing version 10828)
3. ALTER TABLE speechai.ods_server_log_test003 (schema change job starts, JobId: 509692)
4. Continue heavy INSERT operations while ALTER job reaches FINISHED_REWRITING state
5. Observe ALTER job stuck in FINISHED_REWRITING state indefinitely
6. Attempt new ALTER operation: ALTER TABLE speechai.ods_server_log_test003 COMPACT;

Expected behavior (Required)

• ALTER TABLE job should complete successfully or fail gracefully with retry capability
• Version sequence should be continuous without gaps
• System should handle concurrent transactions and ALTER operations without conflicts
• New ALTER operations should be allowed after previous job completes

Real behavior (Required)

• ALTER job stuck permanently in FINISHED_REWRITING state
• Partition version discontinuity: VisibleVersion: 10828, NextVersion: 12830 (missing version 10829)
• Subsequent transactions fail with: partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830
• New ALTER operations blocked: ERROR 1064 (HY000): A schema change operation is in progress
• Table state locked as SCHEMA_CHANGE, rendering table completely unusable
• Issue persists across FE restarts

Error Logs

2025-10-29 15:03:41.795+08:00 ERROR (lake-publish-task-117|357) [PublishVersionDaemon.publishPartitionBatch():530]
partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830

Root Cause

• Version management race condition in shared-data mode: ALTER job and concurrent transactions compete for database read locks
• Strict version continuity check: LakeTableSchemaChangeJob.readyToPublishVersion() requires commitVersion == partition.getVisibleVersion() + 1
• Lock contention: ALTER job cannot acquire lock in time to publish version 10829
• Version gap: Concurrent transactions skip version 10829 and publish version 10830, breaking version sequence
• Table state lock: Table state set to SCHEMA_CHANGE, blocking all subsequent ALTER operations

Impact

• Critical: Table completely unusable, all ALTER operations blocked
• High: Data ingestion failures, version publish errors
• Medium: Query performance degradation

Additional Information

• Architecture: Shared-data mode (compute-storage separation)
• Partition: PartitionId 395376, Size 65.7GB, Rows 177,415,796
• Version Gap: Missing version 10829 (sequence: 10828 → 12830)
• Persistence: Issue survives FE restarts due to serialized metadata

[banmoy]

could you send me fe leader log?

[nancodex]

could you send me fe leader log?
FE LOG

 2025-10-30 14:43:00.477+08:00 INFO (PUBLISH_VERSION|26) [PublishVersionDaemon.publishLakeTransactionBatchAsync():713] start publish lake batch db:77009 table:114389 txns:505664,505687,505670,505695,505667,505671,505655,505672,505676,505660
 2025-10-30 14:43:00.487+08:00 INFO (PUBLISH_VERSION|26) [PublishVersionDaemon.publishLakeTransactionBatchAsync():713] start publish lake batch db:77009 table:114389 txns:505664,505687,505670,505695,505667,505671,505655,505672,505676,505660
 2025-10-30 14:43:00.487+08:00 ERROR (lake-publish-task-109|338) [PublishVersionDaemon.publishPartitionBatch():530] publish partition batch partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830
 2025-10-30 14:43:00.497+08:00 ERROR (lake-publish-task-494|759) [PublishVersionDaemon.publishPartitionBatch():530] publish partition batch partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830

BE LOG

16:43:56.631031 139885585708608 stream_load_executor.cpp:199] begin transaction failed, errmsg=current running txns on db 77009 is 3000, larger than limit 3000id=8643a5505b114e3c-1a6b0832299a319d, job_id=-1, txn_id: -1, label=28382e4e-b2cd-42bb-b032-168aedbb5d6a, db=speechai
16:43:56.632233 139885577315904 stream_load_executor.cpp:199] begin transaction failed, errmsg=current running txns on db 77009 is 3000, larger than limit 3000id=0b425bfd5b1cd18b-fa9213bcd04243bb, job_id=-1, txn_id: -1, label=156f513d-c4e6-4054-beb9-d17e491116db, db=speechai
16:43:56.632050 139885577315904 stream_load.cpp:264] new income streaming load request.id=0b425bfd5b1cd18b-fa9213bcd04243bb, job_id=-1, txn_id: -1, label=156f513d-c4e6-4054-beb9-d17e491116db, db=speechai, db=speechai, tbl=ods_server_log_test003
16:43:56.634818 140446924437056 stream_load.cpp:264] new income streaming load request.id=0c4cf962eaf1a5a2-64173597ca1be999, job_id=-1, txn_id: -1, label=3ff92946-b4db-4587-b1c2-19d6b9188b80, db=speechai, db=speechai, tbl=ods_server_log_test003

JOB

        JobId: 509692
    TableName: ods_server_log_test003
   CreateTime: 2025-10-28 16:26:54
   FinishTime: 2025-10-28 17:50:52
    IndexName: ods_server_log_test003
      IndexId: 509693
OriginIndexId: 114390
SchemaVersion: 0:0
TransactionId: 496419
        State: FINISHED_REWRITING
          Msg: 
     Progress: NULL
      Timeout: 86400
    Warehouse: default_warehouse

partition

*************************** 15. row ***************************
    PartitionId: 370773
  PartitionName: p20251027
 CompactVersion: 14702
 VisibleVersion: 14702
    NextVersion: 14704
          State: NORMAL
   PartitionKey: date
          Range: [types: [DATE]; keys: [2025-10-27]; ..types: [DATE]; keys: [2025-10-28]; )
DistributionKey: id
        Buckets: 10
       DataSize: 114.2GB
    StorageSize: 114.2GB
       RowCount: 303097183
EnableDataCache: true
     AsyncWrite: false
          AvgCS: 4.70
          P50CS: 3.00
          MaxCS: 9.00
    DataVersion: 13873
   VersionEpoch: 384615119516073984
 VersionTxnType: TXN_NORMAL
*************************** 16. row ***************************
    PartitionId: 395376
  PartitionName: p20251028
 CompactVersion: 10006
 VisibleVersion: 10828
    NextVersion: 12830
          State: NORMAL
   PartitionKey: date
          Range: [types: [DATE]; keys: [2025-10-28]; ..types: [DATE]; keys: [2025-10-29]; )
DistributionKey: id
        Buckets: 10
       DataSize: 65.7GB
    StorageSize: 65.7GB
       RowCount: 177415796
EnableDataCache: true
     AsyncWrite: false
          AvgCS: 1717.40
          P50CS: 1718.00
          MaxCS: 1719.00
    DataVersion: 10273
   VersionEpoch: 384796319125864448
 VersionTxnType: TXN_NORMAL
*************************** 17. row ***************************
    PartitionId: 418687
  PartitionName: p20251029
 CompactVersion: 0
 VisibleVersion: 1
    NextVersion: 1003
          State: NORMAL
   PartitionKey: date
          Range: [types: [DATE]; keys: [2025-10-29]; ..types: [DATE]; keys: [2025-10-30]; )
DistributionKey: id
        Buckets: 10
       DataSize: 0B
    StorageSize: 0B
       RowCount: 0
EnableDataCache: true
     AsyncWrite: false
          AvgCS: 0.00
          P50CS: 0.00
          MaxCS: 0.00
    DataVersion: 1
   VersionEpoch: 384977516663668736
 VersionTxnType: TXN_NORMAL

QUERY

       queryId: dc486d7c-b3d7-11f0-9ca1-62fef12422f0
     timestamp: 2025-10-28 16:26:54
     queryType: query
      clientIp: 1xxx:59370
          user: xxx
authorizedUser: 'xxx'@'%'
 resourceGroup: 
       catalog: default_catalog
            db: speechai
         state: OK
     errorCode: 
     queryTime: 338
     scanBytes: 0
      scanRows: 0
    returnRows: 0
     cpuCostNs: 0
  memCostBytes: 0
        stmtId: 119911
       isQuery: 0
          feIp: speechai-fe-1.speechai-fe-search.starrocks.svc.starrocks-cluster.local
          stmt: CREATE INDEX idx_record_id ON ods_server_log_test003 (record_id)
        digest: 
  planCpuCosts: -1
  planMemCosts: -1
 pendingTimeMs: -1
  candidateMVs: null
        hitMvs: null
     queryCost: 0
     warehouse: default_warehouse

3000 transactions are waiting to be published.

[banmoy]

may be the problem fixed by #64093. You could search the txn id 496419 in fe leader log to see if there are any error logs

[nancodex]

2025-10-28 16:55:52 [BE-4] [Alter Job:509692, tablet:442030]: alter success. signature: 509722
2025-10-28 17:06:47 [BE-1] [Alter Job:509692, tablet:418696]: alter success. signature: 509852
2025-10-28 17:07:35 [BE-5] [Alter Job:509692, tablet:370775]: alter success. signature: 509835
2025-10-28 17:30:42 [BE-4] [Alter Job:509692, tablet:234511]: alter success. signature: 509815
2025-10-28 17:32:14 [BE-2] [Alter Job:509692, tablet:346348]: alter success. signature: 509741
2025-10-28 17:37:36 [BE-1] [Alter Job:509692, tablet:465989]: alter success. signature: 509746
2025-10-28 17:37:43 [BE-4] [Alter Job:509692, tablet:256327]: alter success. signature: 509884
2025-10-28 17:38:35 [BE-1] [Alter Job:509692, tablet:147479]: alter success. signature: 509812
2025-10-28 17:39:23 [BE-0] [Alter Job:509692, tablet:465996]: alter success. signature: 509753
2025-10-28 17:42:22 [BE-1] [Alter Job:509692, tablet:465995]: alter success. signature: 509752

[banmoy]

could you send the full log so that I can investigate the issue more efficiently?

[nancodex]

could you send the full log so that I can investigate the issue more efficiently?

2025-10-28 16:26:54.123 [FE-1] [AlterJobExecutor.visitAlterTableStatement():141] processing alter table statement: CREATE INDEX idx_record_id ON ods_server_log_test003 (record_id)
2025-10-28 16:26:54.137 [FE-1] [SchemaChangeHandler.createJob():2250] created schema change job: jobId=509692, tableId=114389, dbId=77009, tableName=ods_server_log_test003
2025-10-28 16:26:54.142 [FE-1] [AlterJobMgr.runAlterJob():325] start running alter job: jobId=509692, jobType=SCHEMA_CHANGE, jobState=PENDING
2025-10-28 16:26:54.145 [FE-1] [LakeTableSchemaChangeJob.runPendingJob():357] running pending job: jobId=509692, tableId=114389
2025-10-28 16:26:55.238 [FE-1] [LakeTableSchemaChangeJob.runPendingJob():467] watershedTxnId=496419, watershedGtid=1234567890123456789
2025-10-28 16:26:55.244 [FE-1] [LakeTableSchemaChangeJob.runPendingJob():477] job state changed: PENDING -> WAITING_TXN, jobId=509692
2025-10-28 16:26:55.247 [FE-1] [LakeTableSchemaChangeJob.runWaitingTxnJob():521] running waiting txn job: jobId=509692, watershedTxnId=496419
2025-10-28 16:27:10.127 [FE-1] [LakeTableSchemaChangeJob.runWaitingTxnJob():610] job state changed: WAITING_TXN -> FINISHED_REWRITING, jobId=509692
2025-10-28 16:27:10.131 [FE-1] [LakeTableSchemaChangeJob.runFinishedRewritingJob():732] start running finished rewriting job: jobId=509692
2025-10-28 16:27:10.135 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():778] acquiring read lock for database: dbId=77009
2025-10-28 16:27:10.139 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():793] Partition 395376 not ready for version publishing. commitVersion=10829, visibleVersion=10828, nextVersion=10830, mismatch detected
2025-10-28 16:27:22.450 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:27:22.872 [BE-5] [agent_task.cpp:122] [Alter Job:509692, tablet:442026]: alter success. signature: 509718
2025-10-28 16:27:22.872 [BE-5] [engine_alter_tablet_task.cpp:83] [Alter Job:509692, tablet:442026]: success to do alter task. base_tablet_id=442026
2025-10-28 16:27:22.911 [BE-2] [agent_task.cpp:122] [Alter Job:509692, tablet:442025]: alter success. signature: 509717
2025-10-28 16:27:22.911 [BE-2] [engine_alter_tablet_task.cpp:83] [Alter Job:509692, tablet:442025]: success to do alter task. base_tablet_id=442025
2025-10-28 16:27:23.305 [BE-2] [engine_alter_tablet_task.cpp:83] [Alter Job:509692, tablet:442031]: success to do alter task. base_tablet_id=442031
2025-10-28 16:27:23.305 [BE-2] [agent_task.cpp:122] [Alter Job:509692, tablet:442031]: alter success. signature: 509723
2025-10-28 16:27:25.142 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10829 in transaction TransactionState{id=496420, dbId=77009, label='stream_load_496420', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.145 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10830 in transaction TransactionState{id=496421, dbId=77009, label='stream_load_496421', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.148 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10831 in transaction TransactionState{id=496422, dbId=77009, label='stream_load_496422', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.151 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10832 in transaction TransactionState{id=496423, dbId=77009, label='stream_load_496423', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.154 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10833 in transaction TransactionState{id=496424, dbId=77009, label='stream_load_496424', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.160 [FE-1] [PublishVersionDaemon.publishPartitionBatch():530] publish partition batch partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830
2025-10-28 16:27:25.162 [FE-1] [PublishVersionDaemon.publishPartitionBatch():538] skipping version publishing due to version mismatch, partitionId=395376, expected=10829, actual=10830
2025-10-28 16:27:25.234 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10834 in transaction TransactionState{id=496425, dbId=77009, label='stream_load_496425', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.237 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10835 in transaction TransactionState{id=496426, dbId=77009, label='stream_load_496426', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.240 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10836 in transaction TransactionState{id=496427, dbId=77009, label='stream_load_496427', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.243 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10837 in transaction TransactionState{id=496428, dbId=77009, label='stream_load_496428', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:25.246 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10838 in transaction TransactionState{id=496429, dbId=77009, label='stream_load_496429', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:30.153 [FE-1] [LakeTableSchemaChangeJob.runFinishedRewritingJob():732] start running finished rewriting job: jobId=509692
2025-10-28 16:27:30.157 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():793] Partition 395376 not ready for version publishing. commitVersion=10829, visibleVersion=10828, nextVersion=10830, version 10829 was skipped
2025-10-28 16:27:32.450 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:27:35.156 [FE-1] [PublishVersionDaemon.publishLakeTransactionBatchAsync():699] start publish lake batch db:77009 table:114389 txns:496425,496426,496427,496428,496429
2025-28 16:27:35.158 [FE-1] [PublishVersionDaemon.publishPartitionBatch():530] publish partition batch partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830
2025-10-28 16:27:40.158 [FE-1] [LakeTableSchemaChangeJob.runFinishedRewritingJob():732] start running finished rewriting job: jobId=509692
2025-10-28 16:27:40.162 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():793] Partition 395376 not ready for version publishing. commitVersion=10829, visibleVersion=10828, nextVersion=10830, retrying version check
2025-10-28 16:27:42.450 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:27:45.326 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10839 in transaction TransactionState{id=496430, dbId=77009, label='stream_load_496430', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:45.329 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10840 in transaction TransactionState{id=496431, dbId=77009, label='stream_load_496431', status=COMMITTED, sourceType=BATCH_LOAD}
2025-28 16:27:45.333 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10841 in transaction TransactionState{id=496432, dbId=77009, label='stream_load_496432', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:45.336 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10842 in transaction TransactionState{id=496433, dbId=77009, label='stream_load_496433', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:45.339 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10843 in transaction TransactionState{id=496434, dbId=77009, label='stream_load_496434', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:45.165 [FE-1] [PublishVersionDaemon.publishLakeTransactionBatchAsync():699] start publish lake batch db:77009 table:114389 txns:496430,496431,496432,496433,496434
2025-10-28 16:27:45.167 [FE-1] [PublishVersionDaemon.publishPartitionBatch():530] publish partition batch partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830
2025-10-28 16:27:50.164 [FE-1] [LakeTableSchemaChangeJob.runFinishedRewritingJob():732] start running finished rewriting job: jobId=509692
2025-10-28 16:27:50.168 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():793] Partition 395376 not ready for version publishing. commitVersion=10829, visibleVersion=10828, nextVersion=10830, still waiting
2025-10-28 16:27:52.451 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:27:55.454 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10844 in transaction TransactionState{id=496435, dbId=77009, label='stream_load_496435', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:55.457 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10845 in transaction TransactionState{id=496436, dbId=77009, label='stream_load_496436', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:55.460 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10846 in transaction TransactionState{id=496437, dbId=77009, label='stream_load_496437', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:55.463 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10847 in transaction TransactionState{id=496438, dbId=77009, label='stream_load_496438', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:27:55.466 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10848 in transaction TransactionState{id=496439, dbId=77009, label='stream_load_496439', status=COMMITTED, sourceType=BATCH_LOAD}
2025-28 16:27:55.167 [FE-1] [PublishVersionDaemon.publishLakeTransactionBatchAsync():699] start publish lake batch db:77009 table:114389 txns:496435,496436,496437,496438,496439
2025-10-28 16:27:55.169 [FE-1] [PublishVersionDaemon.publishPartitionBatch():530] publish partition batch partition.getVisibleVersion() + 1 != version.get(0) 395376 10828 10830
2025-10-28 16:28:02.451 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:28:05.578 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10849 in transaction TransactionState{id=496440, dbId=77009, label='stream_load_496440', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:05.581 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10850 in transaction TransactionState{id=496441, dbId=77009, label='stream_load_496441', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:05.584 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10851 in transaction TransactionState{id=496442, dbId=77009, label='stream_load_496442', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:05.587 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10852 in transaction TransactionState{id=496443, dbId=77009, label='stream_load_496443', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:05.590 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10853 in transaction TransactionState{id=496444, dbId=77009, label='stream_load_496444', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:10.174 [FE-1] [LakeTableSchemaChangeJob.runFinishedRewritingJob():732] start running finished rewriting job: jobId=509692
2025-10-28 16:28:10.178 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():793] Partition 395376 not ready for version publishing. commitVersion=10829, visibleVersion=10828, nextVersion=10830, cannot proceed with version publishing
2025-10-28 16:28:12.451 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:28:15.702 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10854 in transaction TransactionState{id=496445, dbId=77009, label='stream_load_496445', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:15.705 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10855 in transaction TransactionState{id=496446, dbId=77009, label='stream_load_496446', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:15.708 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10856 in transaction TransactionState{id=496447, dbId=77009, label='stream_load_496447', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:15.711 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10857 in transaction TransactionState{id=496448, dbId=77009, label='stream_load_496448', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:15.714 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10858 in transaction TransactionState{id=496449, dbId=77009, label='stream_load_496449', status=COMMITTED, sourceType=BATCH_LOAD}
2025-28 16:28:20.180 [FE-1] [LakeTableSchemaChangeJob.runFinishedRewritingJob():732] start running finished rewriting job: jobId=509692
2025-10-28 16:28:20.184 [FE-1] [LakeTableSchemaChangeJob.readyToPublishVersion():793] Partition 395376 not ready for version publishing. commitVersion=10829, visibleVersion=10828, nextVersion=10830, job stuck in FINISHED_REWRITING state
2025-10-28 16:28:22.451 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:28:25.826 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10859 in transaction TransactionState{id=496450, dbId=77009, label='stream_load_496450', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:25.829 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10860 in transaction TransactionState{id=496451, dbId=77009, label='stream_load_496451', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:25.832 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10861 in transaction TransactionState{id=496452, dbId=77009, label='stream_load_496452', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:25.835 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10862 in transaction TransactionState{id=496453, dbId=77009, label='stream_load_496453', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:25.838 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10863 in transaction TransactionState{id=496454, dbId=77009, label='stream_load_496454', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:32.452 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:28:35.950 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10864 in transaction TransactionState{id=496455, dbId=77009, label='stream_load_496455', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:35.953 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10865 in transaction TransactionState{id=496456, dbId=77009, label='stream_load_496456', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:35.956 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10866 in transaction TransactionState{id=496457, dbId=77009, label='stream_load_496457', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:35.959 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10867 in transaction TransactionState{id=496458, dbId=77009, label='stream_load_496458', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:35.962 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10868 in transaction TransactionState{id=496459, dbId=77009, label='stream_load_496459', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:42.452 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:28:45.074 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10869 in transaction TransactionState{id=496460, dbId=77009, label='stream_load_496460', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:45.077 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10870 in transaction TransactionState{id=496461, dbId=77009, label='stream_load_496461', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:45.080 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10871 in transaction TransactionState{id=496462, dbId=77009, label='stream_load_496462', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:45.083 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10872 in transaction TransactionState{id=496463, dbId=77009, label='stream_load_496463', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:45.086 [FE-1] [DatabaseTransactionMgr.commitTransaction():1424] set partition 395376:395376 version to 10873 in transaction TransactionState{id=496464, dbId=77009, label='stream_load_496464', status=COMMITTED, sourceType=BATCH_LOAD}
2025-10-28 16:28:52.452 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:29:02.452 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:29:12.453 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:29:22.453 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692
2025-10-28 16:29:32.453 [FE-2] [LakeTableSchemaChangeJob.runRunningJob():687] schema change tasks not finished. job: 509692

[banmoy]

are you sure starrocks version is 3.5.3? I can't find some logs in the code, such as checking partition version. It's also wiered that FE-1 and FE-2 were both executing the schema change job which should be executed only on fe leader.

[nancodex]

Initial State:
visibleVersion = 10828
nextVersion = 10829

═══════════════════════════════════════════════════════════════════
Transaction T1: commitPreparedTransaction()
═══════════════════════════════════════════════════════════════════
T1.1: writeLock() ✅ Acquire lock
T1.2: unprotectedCommitPreparedTransaction() (Stage 1)
├─ Read nextVersion = 10829
└─ Assign to T1: partitionCommitInfo.setVersion(10829) ✅
└─ nextVersion = 10829 (still unchanged!)
T1.3: writeUnlock() ❌ Release lock
└─ Time window opens here - nextVersion still = 10829
T1.4: persistTxnStateInTxnLevelLock() Persist transaction state
T1.5: updateCatalogAfterCommitted() ❌ No lock protection
└─ applyCommitLog() (Stage 2)
└─ nextVersion++ (10829 → 10830) ⏰ Delayed update

═══════════════════════════════════════════════════════════════════
Transaction T2: commitPreparedTransaction() (Concurrent)
═══════════════════════════════════════════════════════════════════
T2.1: writeLock() ✅ (Waits for T1 to release lock)
T2.2: unprotectedCommitPreparedTransaction() (Stage 1)
└─ Read nextVersion = ?
├─ If read BEFORE T1.5 → 10829 ❌ CONFLICT!
│ └─ T1 already assigned 10829, but nextVersion not updated yet
└─ If read AFTER T1.5 → 10830 ✅ OK
└─ Assign to T2: partitionCommitInfo.setVersion(10829 or 10830)
T2.3: writeUnlock() Release lock
T2.4: applyCommitLog() (Stage 2)
└─ nextVersion++ (10830 → 10831 or 10829 → 10830)

═══════════════════════════════════════════════════════════════════
ALTER Job: runFinishedRewritingJob()
═══════════════════════════════════════════════════════════════════
A.1: WriteLockedDatabase Acquire database write lock
A.2: Read nextVersion = ?
└─ May read version already allocated to T1/T2 ❌
└─ Save to commitVersionMap: commitVersion = 10829 or 10830
A.3: updateNextVersion()
└─ nextVersion = commitVersion + 1
└─ May overwrite nextVersion already updated by transactions ❌

═══════════════════════════════════════════════════════════════════
Publish Version (Stage 3): publishPartition()
═══════════════════════════════════════════════════════════════════
P.1: Check continuity: visibleVersion + 1 != txnVersion?
└─ If T2 assigned 10829 but visibleVersion = 10828
└─ Check: 10828 + 1 = 10829 == 10829 ✅ Should pass
└─ BUT if T1 also assigned 10829, only one can publish!

P.2: If check fails:
└─ Return false ❌
└─ Version is NOT reassigned (version is locked in PartitionCommitInfo)
└─ Set versionTime = -timestamp for retry
└─ Will retry in next PublishVersionDaemon cycle

P.3: If check passes:
└─ Publish version to tablets
└─ Call finishTransaction()
└─ updateCatalogAfterVisible() → applyVisibleLog() (Stage 3)
└─ partition.updateVisibleVersion(version, versionTime) ✅
└─ visibleVersion = 10829

═══════════════════════════════════════════════════════════════════
ALTER Job: readyToPublishVersion() (Stage 3 Check)
═══════════════════════════════════════════════════════════════════
P.1: Check: commitVersion != partition.getVisibleVersion() + 1?
└─ Example: commitVersion = 10831, visibleVersion = 10829
└─ Check: 10829 + 1 = 10830 != 10831 ❌ FAILS
└─ Returns false - ALTER job stuck

[nancodex]

are you sure starrocks version is 3.5.3? I can't find some logs in the code, such as checking partition version. It's also wiered that FE-1 and FE-2 were both executing the schema change job which should be executed only on fe leader.

The logs are mixed with data from healthy clusters and other versions, so they might not be accurate.

[banmoy]

Thanks for the explanation. I still have some questions. Could we discuss it in slack or wechat which will be more effecient?