libsnapshot: Add unit test to simulate merge-resume

Simulate merge interruption and merge restart and
validate the data once entire merge is completed.

Bug: 167409187
Test: cow_snapuserd_test
Signed-off-by: Akilesh Kailash <akailash@google.com>
Change-Id: Ia940d5fbd2426bdf13347ffb6637d753b2228de6
diff --git a/fs_mgr/libsnapshot/cow_snapuserd_test.cpp b/fs_mgr/libsnapshot/cow_snapuserd_test.cpp
index 0addba3..7fa23db 100644
--- a/fs_mgr/libsnapshot/cow_snapuserd_test.cpp
+++ b/fs_mgr/libsnapshot/cow_snapuserd_test.cpp
@@ -98,6 +98,7 @@
     void ValidateMerge();
     void ReadSnapshotDeviceAndValidate();
     void Shutdown();
+    void MergeInterrupt();
 
     std::string snapshot_dev() const { return snapshot_dev_->path(); }
 
@@ -105,7 +106,11 @@
 
   private:
     void SetupImpl();
+
     void MergeImpl();
+    void SimulateDaemonRestart();
+    void StartMerge();
+
     void CreateCowDevice();
     void CreateBaseDevice();
     void InitCowDevice();
@@ -130,7 +135,7 @@
     std::unique_ptr<uint8_t[]> merged_buffer_;
     bool setup_ok_ = false;
     bool merge_ok_ = false;
-    size_t size_ = 1_MiB;
+    size_t size_ = 50_MiB;
     int cow_num_sectors_;
     int total_base_size_;
 };
@@ -154,9 +159,13 @@
 }
 
 void CowSnapuserdTest::Shutdown() {
-    ASSERT_TRUE(client_->StopSnapuserd());
     ASSERT_TRUE(snapshot_dev_->Destroy());
     ASSERT_TRUE(dmuser_dev_->Destroy());
+
+    auto misc_device = "/dev/dm-user/" + system_device_ctrl_name_;
+    ASSERT_TRUE(client_->WaitForDeviceDelete(system_device_ctrl_name_));
+    ASSERT_TRUE(android::fs_mgr::WaitForFileDeleted(misc_device, 10s));
+    ASSERT_TRUE(client_->DetachSnapuserd());
 }
 
 bool CowSnapuserdTest::Setup() {
@@ -367,7 +376,7 @@
     return merge_ok_;
 }
 
-void CowSnapuserdTest::MergeImpl() {
+void CowSnapuserdTest::StartMerge() {
     DmTable merge_table;
     ASSERT_TRUE(merge_table.AddTarget(std::make_unique<DmTargetSnapshot>(
             0, total_base_size_ / kSectorSize, base_loop_->device(), dmuser_dev_->path(),
@@ -377,6 +386,11 @@
 
     DeviceMapper& dm = DeviceMapper::Instance();
     ASSERT_TRUE(dm.LoadTableAndActivate("cowsnapuserd-test-dm-snapshot", merge_table));
+}
+
+void CowSnapuserdTest::MergeImpl() {
+    StartMerge();
+    DeviceMapper& dm = DeviceMapper::Instance();
 
     while (true) {
         vector<DeviceMapper::TargetInfo> status;
@@ -405,6 +419,44 @@
     ASSERT_EQ(memcmp(merged_buffer_.get(), orig_buffer_.get(), total_base_size_), 0);
 }
 
+void CowSnapuserdTest::SimulateDaemonRestart() {
+    Shutdown();
+    SetDeviceControlName();
+    StartSnapuserdDaemon();
+    InitCowDevice();
+    CreateDmUserDevice();
+    InitDaemon();
+    CreateSnapshotDevice();
+}
+
+void CowSnapuserdTest::MergeInterrupt() {
+    StartMerge();
+    std::this_thread::sleep_for(4s);
+    SimulateDaemonRestart();
+
+    StartMerge();
+    std::this_thread::sleep_for(3s);
+    SimulateDaemonRestart();
+
+    StartMerge();
+    std::this_thread::sleep_for(3s);
+    SimulateDaemonRestart();
+
+    StartMerge();
+    std::this_thread::sleep_for(1s);
+    SimulateDaemonRestart();
+
+    ASSERT_TRUE(Merge());
+}
+
+TEST(Snapuserd_Test, Snapshot_Merge_Resume) {
+    CowSnapuserdTest harness;
+    ASSERT_TRUE(harness.Setup());
+    harness.MergeInterrupt();
+    harness.ValidateMerge();
+    harness.Shutdown();
+}
+
 TEST(Snapuserd_Test, Snapshot) {
     CowSnapuserdTest harness;
     ASSERT_TRUE(harness.Setup());
diff --git a/fs_mgr/libsnapshot/snapuserd.cpp b/fs_mgr/libsnapshot/snapuserd.cpp
index 9ad4a1a..ceba8ab 100644
--- a/fs_mgr/libsnapshot/snapuserd.cpp
+++ b/fs_mgr/libsnapshot/snapuserd.cpp
@@ -96,7 +96,7 @@
 // it will be de-compressed.
 bool Snapuserd::ProcessReplaceOp(const CowOperation* cow_op) {
     if (!reader_->ReadData(*cow_op, &bufsink_)) {
-        SNAP_LOG(ERROR) << "ReadData failed for chunk: " << cow_op->new_block;
+        SNAP_LOG(ERROR) << "ProcessReplaceOp failed for block " << cow_op->new_block;
         return false;
     }
 
@@ -113,7 +113,8 @@
     // if the successive blocks are contiguous.
     if (!android::base::ReadFullyAtOffset(backing_store_fd_, buffer, BLOCK_SIZE,
                                           cow_op->source * BLOCK_SIZE)) {
-        SNAP_LOG(ERROR) << "Copy-op failed. Read from backing store at: " << cow_op->source;
+        SNAP_PLOG(ERROR) << "Copy-op failed. Read from backing store: " << backing_store_device_
+                         << "at block :" << cow_op->source;
         return false;
     }
 
@@ -160,7 +161,7 @@
                     << " Aligned sector: " << it->second;
 
     if (!ProcessCowOp(it->second)) {
-        SNAP_LOG(ERROR) << "ReadUnalignedSector: " << sector << " failed";
+        SNAP_LOG(ERROR) << "ReadUnalignedSector: " << sector << " failed of size: " << size;
         return -1;
     }
 
@@ -377,16 +378,21 @@
             CHECK(cow_de->new_chunk == 0);
             break;
         } else {
-            SNAP_LOG(ERROR) << "Error in merge operation. Found invalid metadata";
-            SNAP_LOG(ERROR) << "merged_de-old-chunk: " << merged_de->old_chunk;
-            SNAP_LOG(ERROR) << "merged_de-new-chunk: " << merged_de->new_chunk;
-            SNAP_LOG(ERROR) << "cow_de-old-chunk: " << cow_de->old_chunk;
-            SNAP_LOG(ERROR) << "cow_de-new-chunk: " << cow_de->new_chunk;
+            SNAP_LOG(ERROR) << "Error in merge operation. Found invalid metadata: "
+                            << " merged_de-old-chunk: " << merged_de->old_chunk
+                            << " merged_de-new-chunk: " << merged_de->new_chunk
+                            << " cow_de-old-chunk: " << cow_de->old_chunk
+                            << " cow_de-new-chunk: " << cow_de->new_chunk
+                            << " unmerged_exceptions: " << unmerged_exceptions
+                            << " merged_ops_cur_iter: " << merged_ops_cur_iter
+                            << " offset: " << offset;
             return -1;
         }
     }
 
     if (*copy_op) {
+        SNAP_LOG(ERROR) << "Invalid batch merge of copy ops: merged_ops_cur_iter: "
+                        << merged_ops_cur_iter;
         CHECK(merged_ops_cur_iter == 1);
     }
     return merged_ops_cur_iter;
@@ -446,7 +452,7 @@
     header.num_merge_ops += merged_ops_cur_iter;
     reader_->UpdateMergeProgress(merged_ops_cur_iter);
     if (!writer_->CommitMerge(merged_ops_cur_iter, copy_op)) {
-        SNAP_LOG(ERROR) << "CommitMerge failed...";
+        SNAP_LOG(ERROR) << "CommitMerge failed... merged_ops_cur_iter: " << merged_ops_cur_iter;
         return false;
     }
 
@@ -661,7 +667,7 @@
 bool Snapuserd::WriteDmUserPayload(size_t size) {
     if (!android::base::WriteFully(ctrl_fd_, bufsink_.GetBufPtr(),
                                    sizeof(struct dm_user_header) + size)) {
-        SNAP_PLOG(ERROR) << "Write to dm-user failed";
+        SNAP_PLOG(ERROR) << "Write to dm-user failed size: " << size;
         return false;
     }
 
@@ -670,7 +676,7 @@
 
 bool Snapuserd::ReadDmUserPayload(void* buffer, size_t size) {
     if (!android::base::ReadFully(ctrl_fd_, buffer, size)) {
-        SNAP_PLOG(ERROR) << "ReadDmUserPayload failed";
+        SNAP_PLOG(ERROR) << "ReadDmUserPayload failed size: " << size;
         return false;
     }
 
@@ -808,7 +814,8 @@
                 ret = ReadData(sector + num_sectors_read, read_size);
                 if (ret < 0) {
                     SNAP_LOG(ERROR) << "ReadData failed for chunk id: " << chunk
-                                    << "Sector: " << header->sector;
+                                    << " Sector: " << (sector + num_sectors_read)
+                                    << " size: " << read_size << " header-len: " << header->len;
                     header->type = DM_USER_RESP_ERROR;
                 } else {
                     SNAP_LOG(DEBUG) << "ReadData success for chunk id: " << chunk