Log details for unexpected failure

Add extra context in various places where we might generate
MICRODROID_UNKNOWN_RUNTIME_ERROR.

Define a mechanism for returning extra context information to the
host, and use this to pass back & log the context (but not return it
to the caller).

Add a test.

Test: atest MicrodroidTests
Test: Manual: see new logging
Change-Id: I5625b92113172c6f0805161702be1b6073d2dcd4
diff --git a/microdroid_manager/src/main.rs b/microdroid_manager/src/main.rs
index f465d43..4326f5b 100644
--- a/microdroid_manager/src/main.rs
+++ b/microdroid_manager/src/main.rs
@@ -49,6 +49,7 @@
 use rpcbinder::get_vsock_rpc_interface;
 use rustutils::system_properties;
 use rustutils::system_properties::PropertyWatcher;
+use std::borrow::Cow::{Borrowed, Owned};
 use std::convert::TryInto;
 use std::fs::{self, create_dir, File, OpenOptions};
 use std::io::Write;
@@ -155,7 +156,7 @@
 
 fn write_death_reason_to_serial(err: &Error) -> Result<()> {
     let death_reason = if let Some(e) = err.downcast_ref::<MicrodroidError>() {
-        match e {
+        Borrowed(match e {
             MicrodroidError::FailedToConnectToVirtualizationService(_) => {
                 "MICRODROID_FAILED_TO_CONNECT_TO_VIRTUALIZATION_SERVICE"
             }
@@ -164,9 +165,12 @@
                 "MICRODROID_PAYLOAD_VERIFICATION_FAILED"
             }
             MicrodroidError::InvalidConfig(_) => "MICRODROID_INVALID_PAYLOAD_CONFIG",
-        }
+        })
     } else {
-        "MICRODROID_UNKNOWN_RUNTIME_ERROR"
+        // Send context information back after a separator, to ease diagnosis.
+        // These errors occur before the payload runs, so this should not leak sensitive
+        // information.
+        Owned(format!("MICRODROID_UNKNOWN_RUNTIME_ERROR|{:?}", err))
     };
 
     let death_reason_bytes = death_reason.as_bytes();
@@ -401,7 +405,7 @@
     )
     .context("Failed to run zipfuse")?;
 
-    let config = load_config(payload_metadata)?;
+    let config = load_config(payload_metadata).context("Failed to load payload metadata")?;
 
     let task = config
         .task
@@ -436,10 +440,12 @@
     // Wait until zipfuse has mounted the APK so we can access the payload
     wait_for_property_true(APK_MOUNT_DONE_PROP).context("Failed waiting for APK mount done")?;
 
-    system_properties::write("dev.bootcomplete", "1").context("set dev.bootcomplete")?;
     register_vm_payload_service(service.clone(), dice)?;
     ProcessState::start_thread_pool();
-    exec_task(task, service)
+
+    system_properties::write("dev.bootcomplete", "1").context("set dev.bootcomplete")?;
+
+    exec_task(task, service).context("Failed to run payload")
 }
 
 fn control_service(action: &str, service: &str) -> Result<()> {
@@ -724,7 +730,8 @@
         PayloadMetadata::config_path(path) => {
             let path = Path::new(&path);
             info!("loading config from {:?}...", path);
-            let file = ioutil::wait_for_file(path, WAIT_TIMEOUT)?;
+            let file = ioutil::wait_for_file(path, WAIT_TIMEOUT)
+                .with_context(|| format!("Failed to read {:?}", path))?;
             Ok(serde_json::from_reader(file)?)
         }
         PayloadMetadata::config(payload_config) => {
@@ -819,7 +826,7 @@
     let abi = value.split(',').next().ok_or_else(|| anyhow!("no abilist"))?;
     let path = format!("/mnt/apk/lib/{}/{}", abi, name);
 
-    let metadata = fs::metadata(&path)?;
+    let metadata = fs::metadata(&path).with_context(|| format!("Unable to access {}", path))?;
     if !metadata.is_file() {
         bail!("{} is not a file", &path);
     }
diff --git a/tests/testapk/src/java/com/android/microdroid/test/MicrodroidTests.java b/tests/testapk/src/java/com/android/microdroid/test/MicrodroidTests.java
index 51c145e..466acc7 100644
--- a/tests/testapk/src/java/com/android/microdroid/test/MicrodroidTests.java
+++ b/tests/testapk/src/java/com/android/microdroid/test/MicrodroidTests.java
@@ -418,6 +418,19 @@
     }
 
     @Test
+    public void bootFailsWhenBinaryPathIsInvalid() throws Exception {
+        VirtualMachineConfig.Builder builder = mInner.newVmConfigBuilder()
+                .setPayloadBinaryPath("DoesNotExist.so");
+        VirtualMachineConfig normalConfig = builder.setDebugLevel(DEBUG_LEVEL_FULL).build();
+        mInner.forceCreateNewVirtualMachine("test_vm_invalid_binary_path", normalConfig);
+
+        BootResult bootResult = tryBootVm(TAG, "test_vm_invalid_binary_path");
+        assertThat(bootResult.payloadStarted).isFalse();
+        assertThat(bootResult.deathReason).isEqualTo(
+                VirtualMachineCallback.STOP_REASON_MICRODROID_UNKNOWN_RUNTIME_ERROR);
+    }
+
+    @Test
     public void sameInstancesShareTheSameVmObject() throws Exception {
         VirtualMachineConfig config = mInner.newVmConfigBuilder()
                 .setPayloadBinaryPath("MicrodroidTestNativeLib.so")
diff --git a/virtualizationservice/src/crosvm.rs b/virtualizationservice/src/crosvm.rs
index fa961c2..749970c 100644
--- a/virtualizationservice/src/crosvm.rs
+++ b/virtualizationservice/src/crosvm.rs
@@ -391,7 +391,12 @@
     }
 }
 
-fn death_reason(result: &Result<ExitStatus, io::Error>, failure_reason: &str) -> DeathReason {
+fn death_reason(result: &Result<ExitStatus, io::Error>, mut failure_reason: &str) -> DeathReason {
+    if let Some(position) = failure_reason.find('|') {
+        // Separator indicates extra context information is present after the failure name.
+        error!("Failure info: {}", &failure_reason[(position + 1)..]);
+        failure_reason = &failure_reason[..position];
+    }
     if let Ok(status) = result {
         match failure_reason {
             "PVM_FIRMWARE_PUBLIC_KEY_MISMATCH" => {