Check is blk alloced for normal volume write free blk. (#158)

In crash recovery case, volume write can write to index
and to disk and then crash. In this case index has stale
blk ids which are not alloced, but they can be freed next
time a write happens on same lba.

Author: sanebay

conanfile.py

@@ -9,7 +9,7 @@
 
 class HomeBlocksConan(ConanFile):
     name = "homeblocks"
-    version = "5.0.4"
+    version = "5.0.5"
 
     homepage = "https://github.com/eBay/HomeBlocks"
     description = "Block Store built on HomeStore"

src/lib/volume/tests/test_volume_io.cpp

@@ -767,6 +767,7 @@ TEST_F(VolumeIOTest, WriteCrash) {
     auto vol = volume_list().back();
     generate_write_io_single(vol, 1000 /* start_lba */, 100 /* nblks*/);
     restart(2);
+    LOGINFO("First restart done");
     // TODO read and verify zeros for no data.
 
     // Crash after journal write. After crash, index should be recovered.
@@ -775,15 +776,17 @@ TEST_F(VolumeIOTest, WriteCrash) {
     vol = volume_list().back();
     generate_write_io_single(vol, 2000 /* start_lba */, 100 /* nblks*/);
     restart(2);
+    LOGINFO("Second restart done");
 
     vol->verify_data(2000 /* start_lba */, 2100 /* max_lba */, 25 /* nlbas_per_io */);
-
+    LOGINFO("Verify data done");
     // remove the flip points
     for (auto& flip : flip_points) {
         g_helper->remove_flip(flip);
     }
 
     generate_write_io_single(vol, 1000 /* start_lba */, 100 /* nblks*/);
+    LOGINFO("Verify data done");
     LOGINFO("WriteCrash test done");
 }
 

src/lib/volume/volume.cpp

@@ -213,7 +213,7 @@ VolumeManager::NullAsyncResult Volume::write(const vol_interface_req_ptr& vol_re
     std::vector< homestore::MultiBlkId > new_blkids;
     auto result = rd()->alloc_blks(data_size, hints, new_blkids);
     if (result) {
-        LOGE("Failed to allocate blocks");
+        LOGE("Failed to allocate blocks data_size={}", data_size);
         return std::unexpected(VolumeError::NO_SPACE_LEFT);
     }
     COUNTER_INCREMENT(*metrics_, volume_write_count, 1);
@@ -239,7 +239,7 @@ VolumeManager::NullAsyncResult Volume::write(const vol_interface_req_ptr& vol_re
             lba_t start_lba = vol_req->lba;
             for (auto& blkid : new_blkids) {
                 DEBUG_ASSERT_EQ(blkid.num_pieces(), 1, "Multiple blkid pieces");
-                LOGT("volume write blkid={} lba={}", blkid.to_integer(), start_lba);
+                LOGT("volume write blkid={} start_lba={}", blkid.to_string(), start_lba);
 
                 // Split the large blkid to individual blkid having only one block because each LBA points
                 // to a blkid containing single blk which is stored in index value. Calculate the checksum for each
@@ -248,8 +248,8 @@ VolumeManager::NullAsyncResult Volume::write(const vol_interface_req_ptr& vol_re
                     auto new_bid = BlkId{blkid.blk_num() + i, 1 /* nblks */, blkid.chunk_num()};
                     auto csum = crc16_t10dif(init_crc_16, static_cast< unsigned char* >(data_buffer), blk_size);
                     blocks_info.emplace(start_lba + i, BlockInfo{new_bid, BlkId{}, csum});
-                    LOGT("volume write blkid={} csum={} lba={}", new_bid.to_string(),
-                         blocks_info[start_lba + i].new_checksum, start_lba + i);
+                    LOGT("volume write blkid={} csum={} start_lba={} lba={}", new_bid.to_string(),
+                         blocks_info[start_lba + i].new_checksum, start_lba, start_lba + i);
                     data_buffer += blk_size;
                 }
 
@@ -267,7 +267,10 @@ VolumeManager::NullAsyncResult Volume::write(const vol_interface_req_ptr& vol_re
             vol_req->journal_start_time = Clock::now();
             // Collect all old blocks to write to journal.
             for (auto& [_, info] : blocks_info) {
-                if (info.old_blkid.is_valid()) { old_blkids.emplace_back(info.old_blkid); }
+                if (info.old_blkid.is_valid()) {
+                    LOGT("volume write start_lba={} old blkids={}", vol_req->lba, info.old_blkid.to_string());
+                    old_blkids.emplace_back(info.old_blkid);
+                }
             }
 
             auto csum_size = sizeof(homestore::csum_t) * vol_req->nlbas;

src/lib/volume_mgr.cpp

@@ -370,12 +370,14 @@ void HomeBlocksImpl::on_write(int64_t lsn, const sisl::blob& header, const sisl:
         BlkId old_blkid = *r_cast< const BlkId* >(key_buffer);
         if (repl_ctx == nullptr) {
             if (homestore::hs()->data_service().is_blk_alloced(old_blkid)) {
-                LOGT("on_write free blk {} start_lba {}", old_blkid, journal_entry->start_lba);
+                LOGT("volume write on commit free blk {} start_lba {}", old_blkid, journal_entry->start_lba);
                 homestore::hs()->data_service().free_blk_now(old_blkid);
             }
         } else {
-            LOGT("on_write free blk {} start_lba {}", old_blkid, journal_entry->start_lba);
-            homestore::hs()->data_service().free_blk_now(old_blkid);
+            if (homestore::hs()->data_service().is_blk_alloced(old_blkid)) {
+                LOGT("volume write on commit free blk {} start_lba {}", old_blkid, journal_entry->start_lba);
+                vol_ptr->rd()->async_free_blks(lsn, old_blkid);
+            }
         }
         key_buffer += sizeof(BlkId);
     }