GC conflict with shard creating

[Besroy]

The issue happen in my local build SM 0.5.5 image, lets put here to see if it is a real bug for GC

Environment

Parameter	Value
Cluster	908
Namespace	nuobject2sh-dev
Deployment	sm-long-running2-1013
HomeObjVer	homeobject/4.1.0@oss/v4
HomeStoreVer	homestore/7.4.4@oss/master

Issue Description

The storage manager instance sm2 became stuck because no space left and was unable to synchronize with other cluster members. And the gc task failed due to data verification failure. The data was not migrated successfully by the previous gc task.

Test Scenario

1. Initial Test Cycle: write_blobs → delete_blobs → upgrade_version → gc → write_blobs → seal_shards → truncate_logs → read_verify (PASSED)
2. Follow-up Test: Write 10,000 additional blobs
   • blob_size: 4M
   • replica_count: 3
   • write:delete:read ratio: 6:4
3. Failure Point: During the write phase, sm2 stuck .

Symptoms

1. Space Full Error trigger EGC

[03/07/26 01:17:40.715] [storage_mgr] [warning] block allocation failure, repl_key=[...], status=[SPACE_FULL]
[03/07/26 01:17:40.715] [storage_mgr] [error] Allocate blk for rreq failed error=NO_SPACE_LEFT

2. GC Task Failure with Blob Verification Errors

randomly selected one task log; all blobs on pg=0, shard=0x19 failed verification, and the PBA mismatch:

[03/07/26 01:11:51.753] [storage_mgr] [error] [18] [gc_manager.cpp:872:operator()] [gc_task_id=112, pg_id=0, shard_id=0x19] blob verification fails for move_from_chunk=66, blob_id=10488, pba=[{blk#=52278 count=1025 chunk=55},]	
[03/07/26 01:11:51.767] [storage_mgr] [error] [18] [hs_blob_manager.cpp:702:do_verify_blob] Invalid header found: [header=magic=0xdbcc00880a6daea8 version=47 shard=0xd7ed5efeee4f468 blob_size=1930654802 user_size=4123788523 ...
...
[03/07/26 01:11:52.694] [storage_mgr] [error] [18] [hs_blob_manager.cpp:702:do_verify_blob] Invalid header found: [header=magic=0x5812e3650743c043 version=223 shard=0xddbf494dcb517fd7 blob_size=3020033140 user_size=2718524605 ...
[03/07/26 01:11:52.694] [storage_mgr] [error] [18] [gc_manager.cpp:872:operator()] [gc_task_id=112, pg_id=0, shard_id=0x19] blob verification fails for move_from_chunk=66, blob_id=10699, pba=[{blk#=95328 count=1025 chunk=55},]
[03/07/26 01:11:52.694] [storage_mgr] [error] [251] [gc_manager.cpp:986:copy_valid_data] [gc_task_id=112, pg_id=0, shard_id=0x19] Failed to copy all blobs from move_from_chunk=66 to move_to_chunk=51
[03/07/26 01:11:52.694] [storage_mgr] [error] [251] [gc_manager.cpp:1168:handle_error_before_persisting_gc_metablk] [gc_task_id=112, pg_id=0, shard_id=0xffffffffffffffff] move_from_chunk=66 to move_to_chunk=51 with priority=1 failed before persisting gc metablk

3. Previous GC Task for the Shard Could Not Complete

[03/07/26 00:59:34.119] [storage_mgr] [debug] [250] [gc_manager.cpp:388:operator()] start gc task : move_from_chunk_id=55, priority=1
[03/07/26 00:59:34.119] [storage_mgr] [debug] [250] [gc_manager.cpp:1191:process_gc_task] [gc_task_id=71, pg_id=0, shard_id=0xffffffffffffffff] start process gc task for move_from_chunk=55 with priority=1 
[03/07/26 00:59:34.119] [storage_mgr] [debug] [250] [gc_manager.cpp:1210:process_gc_task] [gc_task_id=71, pg_id=0, shard_id=0xffffffffffffffff] task for move_from_chunk=55 to move_to_chunk=66 with priority=1 start copying data
[03/07/26 00:59:34.119] [storage_mgr] [debug] [250] [gc_manager.cpp:1059:purge_reserved_chunk] [gc_task_id=71, pg_id=0, shard_id=0xffffffffffffffff] reset chunk=66 before using it for gc
[03/07/26 00:59:34.120] [storage_mgr] [warning] [250] [gc_manager.cpp:694:copy_valid_data] [gc_task_id=71, pg_id=0, shard_id=0x19] last shard in move_from_chunk=55 has a state of OPEN!
[03/07/26 00:59:34.227] [storage_mgr] [debug] [250] [gc_manager.cpp:762:copy_valid_data] [gc_task_id=71, pg_id=0, shard_id=0x19] empty shard found in move_from_chunk=55
[03/07/26 00:59:34.227] [storage_mgr] [debug] [250] [gc_manager.cpp:990:copy_valid_data] [gc_task_id=71, pg_id=0, shard_id=0x19] successfully copy blobs from move_from_chunk=55 to move_to_chunk=66
...
[03/07/26 00:59:34.244] [storage_mgr] [info] [250] [gc_manager.cpp:1291:process_gc_task] [gc_task_id=71, pg_id=0, shard_id=0xffffffffffffffff] task for move_from_chunk=55 to move_to_chunk=66 with priority=1 is completed!

4. shard 0x19 creation and GC overlap

[03/07/26 00:59:04.905] [storage_mgr] [debug] [74] [raft_repl_dev.cpp:1694:handle_commit] [traceID=13542536828225921791] [rdev0:c5f48809-45d9-4b88-b843-73ef1661a1ad] Raft channel: Commit rreq=[dsn=18752 term=3 lsn=18757 op=HS_DATA_LINKED local_blkid=[[{blk#=42027 count=1 chunk=55},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | DATA_WRITTEN | LOG_RECEIVED | LOG_FLUSHED]]

[03/07/26 00:59:34.910] [storage_mgr] [debug] [74] [hs_shard_manager.cpp:470:local_create_shard] [trace_id=13542536828225921791,shardID=0x19,pg=0,shard=0x19] local_create_shard 25, vchunk_id=17, p_chunk_id=55, pg_id=0
[03/07/26 00:59:34.910] [storage_mgr] [debug] [74] [hs_shard_manager.cpp:525:on_shard_message_commit] [trace_id=13542536828225921791,shardID=0x19,pg=0,shard=0x19] Commit done for creating shard

Phenomenon Analysis

Primary Issue: Race Condition Between GC and Shard Operations?

The logs reveal a critical race condition between garbage collection and shard lifecycle operations:

1. Shard in OPEN State During GC: At 00:59:34.120, a warning was logged indicating that the last shard in chunk=55 was still in OPEN state when GC started moving data to chunk=66.

2. Concurrent Operations: While GC was copying data from chunk 55 to chunk 66, the shard was still writing data to the original chunk 55.

3. Data Corruption: The PBA references in the GC metadata point to chunk=55, but the actual data content after GC points to invalid blob headers. This indicates that:

   • GC metadata was not updated to reflect new locations
   • The data has been corrupted

[Besroy]

SH test found a new racing case:
T1: Follower receives a create_shard log entry and allocates space (vchunk_id=18, pchunk_id=274) for it.

[04/27/26 03:54:15.994] [storage_mgr] [trace] [32] [raft_state_machine.cpp:62:localize_journal_entry_prepare] [traceID=1611437756867722868] [rdev1:bd717553-da8b-48a0-81b7-299ded6800df] Raft Channel: Localizing Raft log_entry: server_id=896390092, term=3, journal_entry=[version=1.1, code=HS_DATA_LINKED, server_id=896390092, dsn=18590, header_size=1170, key_size=0, value_size=8]
[04/27/26 03:54:15.994] [storage_mgr] [debug] [32] [replication_state_machine.cpp:234:get_blk_alloc_hints] tid=1611437756867722868, get_blk_alloc_hint for creating shard, select vchunk_id=18 for pg=1, shardID=281474976710680
...
[04/27/26 03:54:16.189] [storage_mgr] [trace] [18] [raft_repl_dev.cpp:1644:handle_fetch_data_response] [traceID=1611437756867722868] [rdev1:bd717553-da8b-48a0-81b7-299ded6800df] Data Channel: Data fetched from remote: rreq=[dsn=18590 term=3 lsn=-1 op=HS_DATA_LINKED local_blkid=[[{blk#=28702 count=1 chunk=274},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | ]], data_size: 4096, total_size: 4096, local_blkid: [{blk#=28702 count=1 chunk=274},]
[04/27/26 03:54:16.198] [storage_mgr] [debug] [18] [raft_repl_dev.cpp:1638:operator()] [traceID=1611437756867722868] [rdev1:bd717553-da8b-48a0-81b7-299ded6800df] Data Channel: Data Write completed rreq=[dsn=18590 term=3 lsn=-1 op=HS_DATA_LINKED local_blkid=[[{blk#=28702 count=1 chunk=274},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | DATA_WRITTEN | ]], data_write_latency_us=8613, total_write_latency_us=149512, write_num_pieces=1

T2: GC runs on chunk 274, moves its data to chunk 282, reclaims 22551 blocks, updates the vchunk_id=18 → pchunk mapping from 274 to 282, and marks pchunk 274 as AVAILABLE.

[04/27/26 03:54:16.475] [storage_mgr] [debug] [241] [gc_manager.cpp:1199:process_gc_task] [gc_task_id=70, pg_id=1, shard_id=0xffffffffffffffff] start process gc task for move_from_chunk=274 with priority=1
[04/27/26 03:54:16.475] [storage_mgr] [debug] [241] [gc_manager.cpp:1218:process_gc_task] [gc_task_id=70, pg_id=1, shard_id=0xffffffffffffffff] task for move_from_chunk=274 to move_to_chunk=282 with priority=1 start copying data
[...
[04/27/26 03:54:19.890] [storage_mgr] [debug] [241] [gc_manager.cpp:1367:process_after_gc_metablk_persisted] [gc_task_id=70, pg_id=1, shard_id=0xffffffffffffffff] vchunk_id=18 has been update from move_from_chunk=274 to move_to_chunk=282, 22551 blks are reclaimed, final state is updated to AVAILABLE
[04/27/26 03:54:19.890] [storage_mgr] [info] [241] [gc_manager.cpp:1299:process_gc_task] [gc_task_id=70, pg_id=1, shard_id=0xffffffffffffffff] task for move_from_chunk=274 to move_to_chunk=282 with priority=1 is completed!

T3: The create_shard log is committed. local_create_shard calls select_specific_chunk with vchunk_id 18, but the mapping vhunk_id->pchunk_id has been change, so the old pchunk 274 is still in AVAILABLE, while the new pchunk changed to IN_USE.

[04/27/26 03:54:20.736] [storage_mgr] [debug] [74] [hs_shard_manager.cpp:475:local_create_shard] [trace_id=1611437756867722868,shardID=0x1000000000018,pg=1,shard=0x18] local_create_shard 281474976710680, vchunk_id=18, p_chunk_id=274, pg_id=1

T4: put blobs on the shard, use pchunk_id in shard as hint, so all blobs are written to the now-AVAILABLE pchunk 274
[04/27/26 03:54:32.092] [storage_mgr] [trace] [74] [hs_blob_manager.cpp:222:local_add_blob_info] [traceID=5298027153442811482,shardID=0x1000000000018,pg=1,shard=0x18,blob=10132] blob put commit, exist_already=false, status=success, pbas=[{blk#=31778 count=1025 chunk=274},]

T5: pchunk 274, still marked AVAILABLE, is allocated to other shards, causing data corruption.