Installd: Add error message to dexopt

To give better messages to the binder call, add an out parameter.
This is only the start, threading things further into the calls
dexopt makes, and formatting according to exit codes, will be in
a follow-up CL.

Test: installd_dexopt_test
Change-Id: I0271212c5cddf3a6317d6b597e97537865723fdc
diff --git a/cmds/installd/InstalldNativeService.cpp b/cmds/installd/InstalldNativeService.cpp
index 68acc69..1d8b52c 100644
--- a/cmds/installd/InstalldNativeService.cpp
+++ b/cmds/installd/InstalldNativeService.cpp
@@ -1909,10 +1909,11 @@
     const char* profile_name = getCStr(profileName);
     const char* dm_path = getCStr(dexMetadataPath);
     const char* compilation_reason = getCStr(compilationReason);
+    std::string error_msg;
     int res = android::installd::dexopt(apk_path, uid, pkgname, instruction_set, dexoptNeeded,
             oat_dir, dexFlags, compiler_filter, volume_uuid, class_loader_context, se_info,
-            downgrade, targetSdkVersion, profile_name, dm_path, compilation_reason);
-    return res ? error(res, "Failed to dexopt") : ok();
+            downgrade, targetSdkVersion, profile_name, dm_path, compilation_reason, &error_msg);
+    return res ? error(res, error_msg) : ok();
 }
 
 binder::Status InstalldNativeService::markBootComplete(const std::string& instructionSet) {
diff --git a/cmds/installd/dexopt.cpp b/cmds/installd/dexopt.cpp
index 02a6063..57c64c6 100644
--- a/cmds/installd/dexopt.cpp
+++ b/cmds/installd/dexopt.cpp
@@ -28,6 +28,8 @@
 #include <sys/wait.h>
 #include <unistd.h>
 
+#include <iomanip>
+
 #include <android-base/file.h>
 #include <android-base/logging.h>
 #include <android-base/properties.h>
@@ -1870,22 +1872,30 @@
     return success;
 }
 
+static std::string format_dexopt_error(int retcode, const char* dex_path) {
+  return StringPrintf("Dex2oat invocation for %s failed with 0x%04x", dex_path, retcode);
+}
+
 int dexopt(const char* dex_path, uid_t uid, const char* pkgname, const char* instruction_set,
         int dexopt_needed, const char* oat_dir, int dexopt_flags, const char* compiler_filter,
         const char* volume_uuid, const char* class_loader_context, const char* se_info,
         bool downgrade, int target_sdk_version, const char* profile_name,
-        const char* dex_metadata_path, const char* compilation_reason) {
+        const char* dex_metadata_path, const char* compilation_reason, std::string* error_msg) {
     CHECK(pkgname != nullptr);
     CHECK(pkgname[0] != 0);
+    CHECK(error_msg != nullptr);
     CHECK_EQ(dexopt_flags & ~DEXOPT_MASK, 0)
         << "dexopt flags contains unknown fields: " << dexopt_flags;
 
     if (!validate_dex_path_size(dex_path)) {
+        *error_msg = StringPrintf("Failed to validate %s", dex_path);
         return -1;
     }
 
     if (class_loader_context != nullptr && strlen(class_loader_context) > PKG_PATH_MAX) {
-        LOG(ERROR) << "Class loader context exceeds the allowed size: " << class_loader_context;
+        *error_msg = StringPrintf("Class loader context exceeds the allowed size: %s",
+                                  class_loader_context);
+        LOG(ERROR) << *error_msg;
         return -1;
     }
 
@@ -1908,6 +1918,7 @@
                 return 0;  // Nothing to do, report success.
             }
         } else {
+            *error_msg = "Failed processing secondary.";
             return -1;  // We had an error, logged in the process method.
         }
     } else {
@@ -1920,7 +1931,8 @@
     // Open the input file.
     unique_fd input_fd(open(dex_path, O_RDONLY, 0));
     if (input_fd.get() < 0) {
-        ALOGE("installd cannot open '%s' for input during dexopt\n", dex_path);
+        *error_msg = StringPrintf("installd cannot open '%s' for input during dexopt", dex_path);
+        LOG(ERROR) << *error_msg;
         return -1;
     }
 
@@ -1929,6 +1941,7 @@
     Dex2oatFileWrapper out_oat_fd = open_oat_out_file(dex_path, oat_dir, is_public, uid,
             instruction_set, is_secondary_dex, out_oat_path);
     if (out_oat_fd.get() < 0) {
+        *error_msg = "Could not open out oat file.";
         return -1;
     }
 
@@ -1937,6 +1950,7 @@
     Dex2oatFileWrapper out_vdex_fd;
     if (!open_vdex_files_for_dex2oat(dex_path, out_oat_path, dexopt_needed, instruction_set,
             is_public, uid, is_secondary_dex, profile_guided, &in_vdex_fd, &out_vdex_fd)) {
+        *error_msg = "Could not open vdex files.";
         return -1;
     }
 
@@ -1948,7 +1962,8 @@
     if (is_secondary_dex) {
         if (selinux_android_restorecon_pkgdir(oat_dir, se_info, uid,
                 SELINUX_ANDROID_RESTORECON_RECURSE)) {
-            LOG(ERROR) << "Failed to restorecon " << oat_dir;
+            *error_msg = std::string("Failed to restorecon ").append(oat_dir);
+            LOG(ERROR) << *error_msg;
             return -1;
         }
     }
@@ -1972,7 +1987,7 @@
         }
     }
 
-    ALOGV("DexInv: --- BEGIN '%s' ---\n", dex_path);
+    LOG(VERBOSE) << "DexInv: --- BEGIN '" << dex_path << "' ---";
 
     pid_t pid = fork();
     if (pid == 0) {
@@ -1981,7 +1996,7 @@
 
         SetDex2OatScheduling(boot_complete);
         if (flock(out_oat_fd.get(), LOCK_EX | LOCK_NB) != 0) {
-            ALOGE("flock(%s) failed: %s\n", out_oat_path, strerror(errno));
+            PLOG(ERROR) << "flock(" << out_oat_path << ") failed";
             _exit(67);
         }
 
@@ -2008,9 +2023,11 @@
     } else {
         int res = wait_child(pid);
         if (res == 0) {
-            ALOGV("DexInv: --- END '%s' (success) ---\n", dex_path);
+            LOG(VERBOSE) << "DexInv: --- END '" << dex_path << "' (success) ---";
         } else {
-            ALOGE("DexInv: --- END '%s' --- status=0x%04x, process failed\n", dex_path, res);
+            LOG(VERBOSE) << "DexInv: --- END '" << dex_path << "' --- status=0x"
+                         << std::hex << std::setw(4) << res << ", process failed";
+            *error_msg = format_dexopt_error(res, dex_path);
             return res;
         }
     }
diff --git a/cmds/installd/dexopt.h b/cmds/installd/dexopt.h
index 62f9467..bb6fab3 100644
--- a/cmds/installd/dexopt.h
+++ b/cmds/installd/dexopt.h
@@ -106,7 +106,7 @@
         int dexopt_needed, const char* oat_dir, int dexopt_flags, const char* compiler_filter,
         const char* volume_uuid, const char* class_loader_context, const char* se_info,
         bool downgrade, int target_sdk_version, const char* profile_name,
-        const char* dexMetadataPath, const char* compilation_reason);
+        const char* dexMetadataPath, const char* compilation_reason, std::string* error_msg);
 
 bool calculate_oat_file_path_default(char path[PKG_PATH_MAX], const char *oat_dir,
         const char *apk_path, const char *instruction_set);
diff --git a/cmds/installd/otapreopt.cpp b/cmds/installd/otapreopt.cpp
index 20e7e49..0fcb7d3 100644
--- a/cmds/installd/otapreopt.cpp
+++ b/cmds/installd/otapreopt.cpp
@@ -568,6 +568,7 @@
     // Run dexopt with the parameters of parameters_.
     // TODO(calin): embed the profile name in the parameters.
     int Dexopt() {
+        std::string dummy;
         return dexopt(parameters_.apk_path,
                       parameters_.uid,
                       parameters_.pkgName,
@@ -583,7 +584,8 @@
                       parameters_.target_sdk_version,
                       parameters_.profile_name,
                       parameters_.dex_metadata_path,
-                      parameters_.compilation_reason);
+                      parameters_.compilation_reason,
+                      &dummy);
     }
 
     int RunPreopt() {
diff --git a/cmds/installd/tests/installd_dexopt_test.cpp b/cmds/installd/tests/installd_dexopt_test.cpp
index d640558..7c75713 100644
--- a/cmds/installd/tests/installd_dexopt_test.cpp
+++ b/cmds/installd/tests/installd_dexopt_test.cpp
@@ -249,7 +249,7 @@
 
     void CompileSecondaryDex(const std::string& path, int32_t dex_storage_flag,
             bool should_binder_call_succeed, bool should_dex_be_compiled = true,
-            int32_t uid = -1) {
+            /*out */ binder::Status* binder_result = nullptr, int32_t uid = -1) {
         if (uid == -1) {
             uid = kTestAppUid;
         }
@@ -290,6 +290,9 @@
         ASSERT_EQ(expected_access, access(odex.c_str(), R_OK));
         ASSERT_EQ(expected_access, access(vdex.c_str(), R_OK));
         ASSERT_EQ(-1, access(art.c_str(), R_OK));  // empty profiles do not generate an image.
+        if (binder_result != nullptr) {
+            *binder_result = result;
+        }
     }
 
     void reconcile_secondary_dex(const std::string& path, int32_t storage_flag,
@@ -335,10 +338,18 @@
                              const char* oat_dir,
                              int32_t uid,
                              int32_t dexopt_needed,
+                             binder::Status* binder_result = nullptr,
                              const char* dm_path = nullptr,
                              bool downgrade = false) {
-        return CompilePrimaryDex(
-                compiler_filter, dex_flags, oat_dir, uid, dexopt_needed, dm_path, downgrade, true);
+        CompilePrimaryDex(compiler_filter,
+                          dex_flags,
+                          oat_dir,
+                          uid,
+                          dexopt_needed,
+                          dm_path,
+                          downgrade,
+                          true,
+                          binder_result);
     }
 
     void CompilePrimaryDexFail(std::string compiler_filter,
@@ -346,10 +357,18 @@
                                const char* oat_dir,
                                int32_t uid,
                                int32_t dexopt_needed,
+                               binder::Status* binder_result = nullptr,
                                const char* dm_path = nullptr,
                                bool downgrade = false) {
-        return CompilePrimaryDex(
-                compiler_filter, dex_flags, oat_dir, uid, dexopt_needed, dm_path, downgrade, false);
+        CompilePrimaryDex(compiler_filter,
+                          dex_flags,
+                          oat_dir,
+                          uid,
+                          dexopt_needed,
+                          dm_path,
+                          downgrade,
+                          false,
+                          binder_result);
     }
 
     void CompilePrimaryDex(std::string compiler_filter,
@@ -359,7 +378,8 @@
                            int32_t dexopt_needed,
                            const char* dm_path,
                            bool downgrade,
-                           bool should_binder_call_succeed) {
+                           bool should_binder_call_succeed,
+                           /*out */ binder::Status* binder_result) {
         std::unique_ptr<std::string> package_name_ptr(new std::string(package_name_));
         std::unique_ptr<std::string> out_path(
                 oat_dir == nullptr ? nullptr : new std::string(oat_dir));
@@ -400,6 +420,9 @@
         ASSERT_EQ(should_binder_call_succeed, result.isOk()) << result.toString8().c_str();
 
         if (!should_binder_call_succeed) {
+            if (binder_result != nullptr) {
+                *binder_result = result;
+            }
             return;
         }
         // Check the access to the compiler output.
@@ -417,6 +440,9 @@
         if (compiler_filter == "speed-profile") {
             CheckFileAccess(art, kSystemUid, uid, mode);
         }
+        if (binder_result != nullptr) {
+            *binder_result = result;
+        }
     }
 
     std::string GetPrimaryDexArtifact(const char* oat_dir,
@@ -462,26 +488,34 @@
 TEST_F(DexoptTest, DexoptSecondaryDoesNotExist) {
     LOG(INFO) << "DexoptSecondaryDoesNotExist";
     // If the file validates but does not exist we do not treat it as an error.
+    binder::Status status;
     CompileSecondaryDex(secondary_dex_ce_ + "not.there", DEXOPT_STORAGE_CE,
-        /*binder_ok*/ true,  /*compile_ok*/ false);
+        /*binder_ok*/ true,  /*compile_ok*/ false, &status);
+    EXPECT_STREQ(status.toString8().c_str(), "No error");
 }
 
 TEST_F(DexoptTest, DexoptSecondaryStorageValidationError) {
     LOG(INFO) << "DexoptSecondaryStorageValidationError";
+    binder::Status status;
     CompileSecondaryDex(secondary_dex_ce_, DEXOPT_STORAGE_DE,
-        /*binder_ok*/ false,  /*compile_ok*/ false);
+        /*binder_ok*/ false,  /*compile_ok*/ false, &status);
+    EXPECT_STREQ(status.toString8().c_str(), "Status(-8): '-1: Failed processing secondary.'");
 }
 
 TEST_F(DexoptTest, DexoptSecondaryAppOwnershipValidationError) {
     LOG(INFO) << "DexoptSecondaryAppOwnershipValidationError";
+    binder::Status status;
     CompileSecondaryDex("/data/data/random.app/secondary.jar", DEXOPT_STORAGE_CE,
-        /*binder_ok*/ false,  /*compile_ok*/ false);
+        /*binder_ok*/ false,  /*compile_ok*/ false, &status);
+    EXPECT_STREQ(status.toString8().c_str(), "Status(-8): '-1: Failed processing secondary.'");
 }
 
 TEST_F(DexoptTest, DexoptSecondaryAcessViaDifferentUidError) {
     LOG(INFO) << "DexoptSecondaryAcessViaDifferentUidError";
+    binder::Status status;
     CompileSecondaryDex(secondary_dex_ce_, DEXOPT_STORAGE_CE,
-        /*binder_ok*/ false,  /*compile_ok*/ false, kSystemUid);
+        /*binder_ok*/ false,  /*compile_ok*/ false, &status, kSystemUid);
+    EXPECT_STREQ(status.toString8().c_str(), "Status(-8): '-1: Failed processing secondary.'");
 }
 
 TEST_F(DexoptTest, DexoptPrimaryPublic) {
@@ -495,11 +529,16 @@
 
 TEST_F(DexoptTest, DexoptPrimaryFailedInvalidFilter) {
     LOG(INFO) << "DexoptPrimaryFailedInvalidFilter";
+    binder::Status status;
     CompilePrimaryDexFail("awesome-filter",
                           DEXOPT_IDLE_BACKGROUND_JOB | DEXOPT_PUBLIC,
                           app_oat_dir_.c_str(),
                           kTestAppGid,
-                          DEX2OAT_FROM_SCRATCH);
+                          DEX2OAT_FROM_SCRATCH,
+                          &status);
+    EXPECT_STREQ(status.toString8().c_str(),
+                 "Status(-8): \'256: Dex2oat invocation for "
+                 "/data/app/com.installd.test.dexopt/base.jar failed with 0x0100\'");
 }
 
 TEST_F(DexoptTest, DexoptPrimaryProfileNonPublic) {