Snap for 7744445 from 1d9e35c5bf74bc91b37b72e769d6d9563c94fe72 to sc-qpr1-release

Change-Id: I24ebd135614e0d3bfe4503eaa8474901b1b89726

4 files changed, 274 insertions, 17 deletions

diff --git a/fs_mgr/libsnapshot/cow_snapuserd_test.cpp b/fs_mgr/libsnapshot/cow_snapuserd_test.cpp
index d09c6e9c9..bd432bbdf 100644
--- a/fs_mgr/libsnapshot/cow_snapuserd_test.cpp
+++ b/fs_mgr/libsnapshot/cow_snapuserd_test.cpp
@@ -108,6 +108,7 @@ class CowSnapuserdTest final {
     void MergeInterruptFixed(int duration);
     void MergeInterruptRandomly(int max_duration);
     void ReadDmUserBlockWithoutDaemon();
+    void ReadLastBlock();
 
     std::string snapshot_dev() const { return snapshot_dev_->path(); }
 
@@ -256,6 +257,73 @@ void CowSnapuserdTest::StartSnapuserdDaemon() {
     }
 }
 
+void CowSnapuserdTest::ReadLastBlock() {
+    unique_fd rnd_fd;
+    total_base_size_ = BLOCK_SZ * 2;
+
+    base_fd_ = CreateTempFile("base_device", total_base_size_);
+    ASSERT_GE(base_fd_, 0);
+
+    rnd_fd.reset(open("/dev/random", O_RDONLY));
+    ASSERT_TRUE(rnd_fd > 0);
+
+    std::unique_ptr<uint8_t[]> random_buffer = std::make_unique<uint8_t[]>(BLOCK_SZ);
+
+    for (size_t j = 0; j < ((total_base_size_) / BLOCK_SZ); j++) {
+        ASSERT_EQ(ReadFullyAtOffset(rnd_fd, (char*)random_buffer.get(), BLOCK_SZ, 0), true);
+        ASSERT_EQ(android::base::WriteFully(base_fd_, random_buffer.get(), BLOCK_SZ), true);
+    }
+
+    ASSERT_EQ(lseek(base_fd_, 0, SEEK_SET), 0);
+
+    base_loop_ = std::make_unique<LoopDevice>(base_fd_, 10s);
+    ASSERT_TRUE(base_loop_->valid());
+
+    std::string path = android::base::GetExecutableDirectory();
+    cow_system_ = std::make_unique<TemporaryFile>(path);
+
+    std::unique_ptr<uint8_t[]> random_buffer_1_ = std::make_unique<uint8_t[]>(total_base_size_);
+    loff_t offset = 0;
+
+    // Fill random data
+    for (size_t j = 0; j < (total_base_size_ / BLOCK_SZ); j++) {
+        ASSERT_EQ(ReadFullyAtOffset(rnd_fd, (char*)random_buffer_1_.get() + offset, BLOCK_SZ, 0),
+                  true);
+
+        offset += BLOCK_SZ;
+    }
+
+    CowOptions options;
+    options.compression = "gz";
+    CowWriter writer(options);
+
+    ASSERT_TRUE(writer.Initialize(cow_system_->fd));
+
+    ASSERT_TRUE(writer.AddRawBlocks(0, random_buffer_1_.get(), BLOCK_SZ));
+    ASSERT_TRUE(writer.AddRawBlocks(1, (char*)random_buffer_1_.get() + BLOCK_SZ, BLOCK_SZ));
+
+    ASSERT_TRUE(writer.Finalize());
+
+    SetDeviceControlName();
+
+    StartSnapuserdDaemon();
+    InitCowDevice();
+
+    CreateDmUserDevice();
+    InitDaemon();
+
+    CreateSnapshotDevice();
+
+    unique_fd snapshot_fd(open(snapshot_dev_->path().c_str(), O_RDONLY));
+    ASSERT_TRUE(snapshot_fd > 0);
+
+    std::unique_ptr<uint8_t[]> snapuserd_buffer = std::make_unique<uint8_t[]>(BLOCK_SZ);
+
+    offset = 7680;
+    ASSERT_EQ(ReadFullyAtOffset(snapshot_fd, snapuserd_buffer.get(), 512, offset), true);
+    ASSERT_EQ(memcmp(snapuserd_buffer.get(), (char*)random_buffer_1_.get() + offset, 512), 0);
+}
+
 void CowSnapuserdTest::CreateBaseDevice() {
     unique_fd rnd_fd;
 
@@ -1068,6 +1136,12 @@ TEST(Snapuserd_Test, Snapshot_IO_TEST) {
     harness.Shutdown();
 }
 
+TEST(Snapuserd_Test, Snapshot_END_IO_TEST) {
+    CowSnapuserdTest harness;
+    harness.ReadLastBlock();
+    harness.Shutdown();
+}
+
 TEST(Snapuserd_Test, Snapshot_COPY_Overlap_TEST_1) {
     CowSnapuserdTest harness;
     ASSERT_TRUE(harness.SetupCopyOverlap_1());
diff --git a/fs_mgr/libsnapshot/snapshot.cpp b/fs_mgr/libsnapshot/snapshot.cpp
index 10cb7b8a0..4c94da28f 100644
--- a/fs_mgr/libsnapshot/snapshot.cpp
+++ b/fs_mgr/libsnapshot/snapshot.cpp
@@ -518,6 +518,13 @@ bool SnapshotManager::MapSnapshot(LockedFile* lock, const std::string& name,
             break;
     }
 
+    if (mode == SnapshotStorageMode::Persistent && status.state() == SnapshotState::MERGING) {
+        LOG(ERROR) << "Snapshot: " << name
+                   << " has snapshot status Merging but mode set to Persistent."
+                   << " Changing mode to Snapshot-Merge.";
+        mode = SnapshotStorageMode::Merge;
+    }
+
     DmTable table;
     table.Emplace<DmTargetSnapshot>(0, snapshot_sectors, base_device, cow_device, mode,
                                     kSnapshotChunkSize);
@@ -886,6 +893,10 @@ bool SnapshotManager::QuerySnapshotStatus(const std::string& dm_name, std::strin
     if (target_type) {
         *target_type = DeviceMapper::GetTargetType(target.spec);
     }
+    if (!status->error.empty()) {
+        LOG(ERROR) << "Snapshot: " << dm_name << " returned error code: " << status->error;
+        return false;
+    }
     return true;
 }
 
diff --git a/fs_mgr/libsnapshot/snapuserd_worker.cpp b/fs_mgr/libsnapshot/snapuserd_worker.cpp
index 682f9da58..defb5bb76 100644
--- a/fs_mgr/libsnapshot/snapuserd_worker.cpp
+++ b/fs_mgr/libsnapshot/snapuserd_worker.cpp
@@ -287,16 +287,36 @@ int WorkerThread::ReadData(sector_t sector, size_t size) {
     it = std::lower_bound(chunk_vec.begin(), chunk_vec.end(), std::make_pair(sector, nullptr),
                           Snapuserd::compare);
 
-    if (!(it != chunk_vec.end())) {
-        SNAP_LOG(ERROR) << "ReadData: Sector " << sector << " not found in chunk_vec";
-        return -1;
+    bool read_end_of_device = false;
+    if (it == chunk_vec.end()) {
+        // |-------|-------|-------|
+        // 0       1       2       3
+        //
+        // Block 0 - op 1
+        // Block 1 - op 2
+        // Block 2 - op 3
+        //
+        // chunk_vec will have block 0, 1, 2 which maps to relavant COW ops.
+        //
+        // Each block is 4k bytes. Thus, the last block will span 8 sectors
+        // ranging till block 3 (However, block 3 won't be in chunk_vec as
+        // it doesn't have any mapping to COW ops. Now, if we get an I/O request for a sector
+        // spanning between block 2 and block 3, we need to step back
+        // and get hold of the last element.
+        //
+        // Additionally, dm-snapshot makes sure that I/O request beyond block 3
+        // will not be routed to the daemon. Hence, it is safe to assume that
+        // if a sector is not available in the chunk_vec, the I/O falls in the
+        // end of region.
+        it = std::prev(chunk_vec.end());
+        read_end_of_device = true;
     }
 
     // We didn't find the required sector; hence find the previous sector
     // as lower_bound will gives us the value greater than
     // the requested sector
     if (it->first != sector) {
-        if (it != chunk_vec.begin()) {
+        if (it != chunk_vec.begin() && !read_end_of_device) {
             --it;
         }
 
diff --git a/trusty/storage/proxy/rpmb.c b/trusty/storage/proxy/rpmb.c
index b59fb67f6..48e164124 100644
--- a/trusty/storage/proxy/rpmb.c
+++ b/trusty/storage/proxy/rpmb.c
@@ -16,7 +16,10 @@
 
 #include <errno.h>
 #include <fcntl.h>
+#include <scsi/scsi.h>
+#include <scsi/scsi_proto.h>
 #include <scsi/sg.h>
+#include <stdbool.h>
 #include <stdint.h>
 #include <stdio.h>
 #include <stdlib.h>
@@ -104,21 +107,62 @@ static enum dev_type dev_type = UNKNOWN_RPMB;
 
 static const char* UFS_WAKE_LOCK_NAME = "ufs_seq_wakelock";
 
-#ifdef RPMB_DEBUG
-
-static void print_buf(const char* prefix, const uint8_t* buf, size_t size) {
+/**
+ * log_buf - Log a byte buffer to the android log.
+ * @priority: One of ANDROID_LOG_* priority levels from android_LogPriority in
+ *            android/log.h
+ * @prefix:   A null-terminated string that identifies this buffer. Must be less
+ *            than 128 bytes.
+ * @buf:      Buffer to dump.
+ * @size:     Length of @buf in bytes.
+ */
+#define LOG_BUF_SIZE 256
+static int log_buf(int priority, const char* prefix, const uint8_t* buf, size_t size) {
+    int rc;
     size_t i;
+    char line[LOG_BUF_SIZE] = {0};
+    char* cur = line;
 
-    printf("%s @%p [%zu]", prefix, buf, size);
+    rc = snprintf(line, LOG_BUF_SIZE, "%s @%p [%zu]", prefix, buf, size);
+    if (rc < 0 || rc >= LOG_BUF_SIZE) {
+        goto err;
+    }
+    cur += rc;
     for (i = 0; i < size; i++) {
-        if (i && i % 32 == 0) printf("\n%*s", (int)strlen(prefix), "");
-        printf(" %02x", buf[i]);
+        if (i % 32 == 0) {
+            /*
+             * Flush the line out to the log after we have printed 32 bytes
+             * (also flushes the header line on the first iteration and sets up
+             * for printing the buffer itself)
+             */
+            LOG_PRI(priority, LOG_TAG, "%s", line);
+            memset(line, 0, LOG_BUF_SIZE);
+            cur = line;
+            /* Shift output over by the length of the prefix */
+            rc = snprintf(line, LOG_BUF_SIZE, "%*s", (int)strlen(prefix), "");
+            if (rc < 0 || rc >= LOG_BUF_SIZE) {
+                goto err;
+            }
+            cur += rc;
+        }
+        rc = snprintf(cur, LOG_BUF_SIZE - (cur - line), "%02x ", buf[i]);
+        if (rc < 0 || rc >= LOG_BUF_SIZE - (cur - line)) {
+            goto err;
+        }
+        cur += rc;
     }
-    printf("\n");
-    fflush(stdout);
-}
+    LOG_PRI(priority, LOG_TAG, "%s", line);
 
-#endif
+    return 0;
+
+err:
+    if (rc < 0) {
+        return rc;
+    } else {
+        ALOGE("log_buf prefix was too long");
+        return -1;
+    }
+}
 
 static void set_sg_io_hdr(sg_io_hdr_t* io_hdrp, int dxfer_direction, unsigned char cmd_len,
                           unsigned char mx_sb_len, unsigned int dxfer_len, void* dxferp,
@@ -135,6 +179,111 @@ static void set_sg_io_hdr(sg_io_hdr_t* io_hdrp, int dxfer_direction, unsigned ch
     io_hdrp->timeout = TIMEOUT;
 }
 
+/* Returns false if the sense data was valid and no errors were present */
+static bool check_scsi_sense(const uint8_t* sense_buf, size_t len) {
+    uint8_t response_code = 0;
+    uint8_t sense_key = 0;
+    uint8_t additional_sense_code = 0;
+    uint8_t additional_sense_code_qualifier = 0;
+    uint8_t additional_length = 0;
+
+    if (!sense_buf || len == 0) {
+        ALOGE("Invalid SCSI sense buffer, length: %zu\n", len);
+        return false;
+    }
+
+    response_code = 0x7f & sense_buf[0];
+
+    if (response_code < 0x70 || response_code > 0x73) {
+        ALOGE("Invalid SCSI sense response code: %hhu\n", response_code);
+        return false;
+    }
+
+    if (response_code >= 0x72) {
+        /* descriptor format, SPC-6 4.4.2 */
+        if (len > 1) {
+            sense_key = 0xf & sense_buf[1];
+        }
+        if (len > 2) {
+            additional_sense_code = sense_buf[2];
+        }
+        if (len > 3) {
+            additional_sense_code_qualifier = sense_buf[3];
+        }
+        if (len > 7) {
+            additional_length = sense_buf[7];
+        }
+    } else {
+        /* fixed format, SPC-6 4.4.3 */
+        if (len > 2) {
+            sense_key = 0xf & sense_buf[2];
+        }
+        if (len > 7) {
+            additional_length = sense_buf[7];
+        }
+        if (len > 12) {
+            additional_sense_code = sense_buf[12];
+        }
+        if (len > 13) {
+            additional_sense_code_qualifier = sense_buf[13];
+        }
+    }
+
+    switch (sense_key) {
+        case NO_SENSE:
+        case 0x0f: /* COMPLETED, not present in kernel headers */
+            ALOGD("SCSI success with sense data: key=%hhu, asc=%hhu, ascq=%hhu\n", sense_key,
+                  additional_sense_code, additional_sense_code_qualifier);
+            return true;
+    }
+
+    ALOGE("Unexpected SCSI sense data: key=%hhu, asc=%hhu, ascq=%hhu\n", sense_key,
+          additional_sense_code, additional_sense_code_qualifier);
+    log_buf(ANDROID_LOG_ERROR, "sense buffer: ", sense_buf, len);
+    return false;
+}
+
+static void check_sg_io_hdr(const sg_io_hdr_t* io_hdrp) {
+    if (io_hdrp->status == 0 && io_hdrp->host_status == 0 && io_hdrp->driver_status == 0) {
+        return;
+    }
+
+    if (io_hdrp->status & 0x01) {
+        ALOGE("SG_IO received unknown status, LSB is set: %hhu", io_hdrp->status);
+    }
+
+    if (io_hdrp->masked_status != GOOD && io_hdrp->sb_len_wr > 0) {
+        bool sense_error = check_scsi_sense(io_hdrp->sbp, io_hdrp->sb_len_wr);
+        if (sense_error) {
+            ALOGE("Unexpected SCSI sense. masked_status: %hhu, host_status: %hu, driver_status: "
+                  "%hu\n",
+                  io_hdrp->masked_status, io_hdrp->host_status, io_hdrp->driver_status);
+            return;
+        }
+    }
+
+    switch (io_hdrp->masked_status) {
+        case GOOD:
+            break;
+        case CHECK_CONDITION:
+            /* handled by check_sg_sense above */
+            break;
+        default:
+            ALOGE("SG_IO failed with masked_status: %hhu, host_status: %hu, driver_status: %hu\n",
+                  io_hdrp->masked_status, io_hdrp->host_status, io_hdrp->driver_status);
+            return;
+    }
+
+    if (io_hdrp->host_status != 0) {
+        ALOGE("SG_IO failed with host_status: %hu, driver_status: %hu\n", io_hdrp->host_status,
+              io_hdrp->driver_status);
+    }
+
+    if (io_hdrp->resid != 0) {
+        ALOGE("SG_IO resid was non-zero: %d\n", io_hdrp->resid);
+    }
+}
+
 static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req) {
     struct {
         struct mmc_ioc_multi_cmd multi;
@@ -153,7 +302,7 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req
         mmc_ioc_cmd_set_data((*cmd), write_buf);
 #ifdef RPMB_DEBUG
         ALOGI("opcode: 0x%x, write_flag: 0x%x\n", cmd->opcode, cmd->write_flag);
-        print_buf("request: ", write_buf, req->reliable_write_size);
+        log_buf(ANDROID_LOG_INFO, "request: ", write_buf, req->reliable_write_size);
 #endif
         write_buf += req->reliable_write_size;
         mmc.multi.num_of_cmds++;
@@ -169,7 +318,7 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req
         mmc_ioc_cmd_set_data((*cmd), write_buf);
 #ifdef RPMB_DEBUG
         ALOGI("opcode: 0x%x, write_flag: 0x%x\n", cmd->opcode, cmd->write_flag);
-        print_buf("request: ", write_buf, req->write_size);
+        log_buf(ANDROID_LOG_INFO, "request: ", write_buf, req->write_size);
 #endif
         write_buf += req->write_size;
         mmc.multi.num_of_cmds++;
@@ -225,6 +374,7 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req)
             ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno));
             goto err_op;
         }
+        check_sg_io_hdr(&io_hdr);
         write_buf += req->reliable_write_size;
     }
 
@@ -239,6 +389,7 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req)
             ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno));
             goto err_op;
         }
+        check_sg_io_hdr(&io_hdr);
         write_buf += req->write_size;
     }
 
@@ -252,6 +403,7 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req)
         if (rc < 0) {
             ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno));
         }
+        check_sg_io_hdr(&io_hdr);
     }
 
 err_op:
@@ -353,7 +505,7 @@ int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) {
         goto err_response;
     }
 #ifdef RPMB_DEBUG
-    if (req->read_size) print_buf("response: ", read_buf, req->read_size);
+    if (req->read_size) log_buf(ANDROID_LOG_INFO, "response: ", read_buf, req->read_size);
 #endif
 
     if (msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) {