Replace the "coldboot" timeout with a property.

Also rename init's existing boot-time related properties so they're
all "ro.*" properties.

Example result:

  # Three properties showing when init started...
  [ro.boottime.init]: [5294587604]
  # ...how long it waited for ueventd...
  [ro.boottime.init.cold_boot_wait]: [646956470]
  # ...and how long SELinux initialization took...
  [ro.boottime.init.selinux]: [45742921]

  # Plus one property for each service, showing when it first started.
  [ro.boottime.InputEventFind]: [10278767840]
  [ro.boottime.adbd]: [8359267180]
  [ro.boottime.atfwd]: [10338554773]
  [ro.boottime.audioserver]: [10298157478]
  [ro.boottime.bootanim]: [9323670089]
  [ro.boottime.cameraserver]: [10299402321]
  [ro.boottime.cnd]: [10335931856]
  [ro.boottime.debuggerd]: [7001352774]
  [ro.boottime.debuggerd64]: [7002261785]
  [ro.boottime.drm]: [10301082113]
  [ro.boottime.fingerprintd]: [10331443314]
  [ro.boottime.flash-nanohub-fw]: [6995265534]
  [ro.boottime.gatekeeperd]: [10340355242]
  [ro.boottime.healthd]: [7856893380]
  [ro.boottime.hwservicemanager]: [7856051088]
  [ro.boottime.imscmservice]: [10290530758]
  [ro.boottime.imsdatadaemon]: [10358136702]
  [ro.boottime.imsqmidaemon]: [10289084872]
  [ro.boottime.installd]: [10303296020]
  [ro.boottime.irsc_util]: [10279807632]
  [ro.boottime.keystore]: [10305034093]
  [ro.boottime.lmkd]: [7863506714]
  [ro.boottime.loc_launcher]: [10324525241]
  [ro.boottime.logd]: [6526221633]
  [ro.boottime.logd-reinit]: [7850662702]
  [ro.boottime.mcfg-sh]: [10337268315]
  [ro.boottime.media]: [10312152687]
  [ro.boottime.mediacodec]: [10306852530]
  [ro.boottime.mediadrm]: [10308707999]
  [ro.boottime.mediaextractor]: [10310681177]
  [ro.boottime.msm_irqbalance]: [7862451974]
  [ro.boottime.netd]: [10313523104]
  [ro.boottime.netmgrd]: [10285009351]
  [ro.boottime.oem_qmi_server]: [10293329092]
  [ro.boottime.per_mgr]: [7857915776]
  [ro.boottime.per_proxy]: [8335121605]
  [ro.boottime.perfd]: [10283443101]
  [ro.boottime.qcamerasvr]: [10329644772]
  [ro.boottime.qmuxd]: [10282346643]
  [ro.boottime.qseecomd]: [6855708593]
  [ro.boottime.qti]: [10286196851]
  [ro.boottime.ril-daemon]: [10314933677]
  [ro.boottime.rmt_storage]: [7859105047]
  [ro.boottime.servicemanager]: [7864555881]
  [ro.boottime.ss_ramdump]: [8337634938]
  [ro.boottime.ssr_setup]: [8336268324]
  [ro.boottime.surfaceflinger]: [7866921402]
  [ro.boottime.thermal-engine]: [10281249924]
  [ro.boottime.time_daemon]: [10322006542]
  [ro.boottime.ueventd]: [5618663938]
  [ro.boottime.vold]: [7003493920]
  [ro.boottime.wificond]: [10316641073]
  [ro.boottime.wpa_supplicant]: [18959816881]
  [ro.boottime.zygote]: [10295295029]
  [ro.boottime.zygote_secondary]: [10296637269]

Bug: http://b/31800756
Test: boots
Change-Id: I094cce0c1bab9406d950ca94212689dc2e15dba5

11 files changed, 113 insertions, 65 deletions

diff --git a/init/action.cpp b/init/action.cpp
index 0ea7e14792..65bf292774 100644
--- a/init/action.cpp
+++ b/init/action.cpp
@@ -121,7 +121,7 @@ void Action::ExecuteCommand(const Command& command) const {
     Timer t;
     int result = command.InvokeFunc();
 
-    double duration_ms = t.duration() * 1000;
+    double duration_ms = t.duration_s() * 1000;
     // Any action longer than 50ms will be warned to user as slow operation
     if (duration_ms > 50.0 ||
         android::base::GetMinimumLogSeverity() <= android::base::DEBUG) {
diff --git a/init/builtins.cpp b/init/builtins.cpp
index 6d58754a7f..76e3d6e331 100644
--- a/init/builtins.cpp
+++ b/init/builtins.cpp
@@ -146,8 +146,7 @@ static int wipe_data_via_recovery(const std::string& reason) {
         LOG(ERROR) << "failed to set bootloader message: " << err;
         return -1;
     }
-    android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
-    while (1) { pause(); }  // never reached
+    reboot("recovery");
 }
 
 static void unmount_and_fsck(const struct mntent *entry) {
@@ -727,7 +726,7 @@ static int do_powerctl(const std::vector<std::string>& args) {
         ServiceManager::GetInstance().ForEachService(
             [] (Service* s) { s->Terminate(); });
 
-        while (t.duration() < delay) {
+        while (t.duration_s() < delay) {
             ServiceManager::GetInstance().ReapAnyOutstandingChildren();
 
             int service_count = 0;
@@ -751,11 +750,10 @@ static int do_powerctl(const std::vector<std::string>& args) {
             // Wait a bit before recounting the number or running services.
             std::this_thread::sleep_for(50ms);
         }
-        LOG(VERBOSE) << "Terminating running services took " << t.duration() << " seconds";
+        LOG(VERBOSE) << "Terminating running services took " << t;
     }
 
-    return android_reboot_with_callback(cmd, 0, reboot_target,
-                                        callback_on_ro_remount);
+    return android_reboot_with_callback(cmd, 0, reboot_target, callback_on_ro_remount);
 }
 
 static int do_trigger(const std::vector<std::string>& args) {
diff --git a/init/devices.cpp b/init/devices.cpp
index 2db24b7004..6af237cf9a 100644
--- a/init/devices.cpp
+++ b/init/devices.cpp
@@ -868,7 +868,7 @@ static void handle_firmware_event(uevent* uevent) {
     if (pid == 0) {
         Timer t;
         process_firmware_event(uevent);
-        LOG(INFO) << "loading " << uevent->path << " took " << t.duration() << "s";
+        LOG(INFO) << "loading " << uevent->path << " took " << t;
         _exit(EXIT_SUCCESS);
     } else if (pid == -1) {
         PLOG(ERROR) << "could not fork to process firmware event for " << uevent->firmware;
@@ -1043,7 +1043,7 @@ void device_init() {
     coldboot("/sys/block");
     coldboot("/sys/devices");
     close(open(COLDBOOT_DONE, O_WRONLY|O_CREAT|O_CLOEXEC, 0000));
-    LOG(INFO) << "Coldboot took " << t.duration() << "s.";
+    LOG(INFO) << "Coldboot took " << t;
 }
 
 int get_device_fd() {
diff --git a/init/init.cpp b/init/init.cpp
index ef6f37c0ed..95cb62fea2 100644
--- a/init/init.cpp
+++ b/init/init.cpp
@@ -43,7 +43,6 @@
 #include <android-base/file.h>
 #include <android-base/stringprintf.h>
 #include <android-base/strings.h>
-#include <cutils/android_reboot.h>
 #include <cutils/fs.h>
 #include <cutils/iosched_policy.h>
 #include <cutils/list.h>
@@ -163,14 +162,21 @@ static int wait_for_coldboot_done_action(const std::vector<std::string>& args) {
     Timer t;
 
     LOG(VERBOSE) << "Waiting for " COLDBOOT_DONE "...";
-    // Any longer than 1s is an unreasonable length of time to delay booting.
-    // If you're hitting this timeout, check that you didn't make your
-    // sepolicy regular expressions too expensive (http://b/19899875).
-    if (wait_for_file(COLDBOOT_DONE, 1s)) {
+
+    // Historically we had a 1s timeout here because we weren't otherwise
+    // tracking boot time, and many OEMs made their sepolicy regular
+    // expressions too expensive (http://b/19899875).
+
+    // Now we're tracking boot time, just log the time taken to a system
+    // property. We still panic if it takes more than a minute though,
+    // because any build that slow isn't likely to boot at all, and we'd
+    // rather any test lab devices fail back to the bootloader.
+    if (wait_for_file(COLDBOOT_DONE, 60s) < 0) {
         LOG(ERROR) << "Timed out waiting for " COLDBOOT_DONE;
+        panic();
     }
 
-    LOG(VERBOSE) << "Waiting for " COLDBOOT_DONE " took " << t.duration() << "s.";
+    property_set("ro.boottime.init.cold_boot_wait", std::to_string(t.duration_ns()).c_str());
     return 0;
 }
 
@@ -409,9 +415,8 @@ static int audit_callback(void *data, security_class_t /*cls*/, char *buf, size_
 }
 
 static void security_failure() {
-    LOG(ERROR) << "Security failure; rebooting into recovery mode...";
-    android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
-    while (true) { pause(); }  // never reached
+    LOG(ERROR) << "Security failure...";
+    panic();
 }
 
 static void selinux_initialize(bool in_kernel_domain) {
@@ -443,8 +448,8 @@ static void selinux_initialize(bool in_kernel_domain) {
             security_failure();
         }
 
-        LOG(INFO) << "(Initializing SELinux " << (is_enforcing ? "enforcing" : "non-enforcing")
-                  << " took " << t.duration() << "s.)";
+        // init's first stage can't set properties, so pass the time to the second stage.
+        setenv("INIT_SELINUX_TOOK", std::to_string(t.duration_ns()).c_str(), 1);
     } else {
         selinux_init_all_handles();
     }
@@ -650,7 +655,13 @@ int main(int argc, char** argv) {
         export_kernel_boot_props();
 
         // Make the time that init started available for bootstat to log.
-        property_set("init.start", getenv("INIT_STARTED_AT"));
+        property_set("ro.boottime.init", getenv("INIT_STARTED_AT"));
+        property_set("ro.boottime.init.selinux", getenv("INIT_SELINUX_TOOK"));
+
+        // Clean up our environment.
+        unsetenv("INIT_SECOND_STAGE");
+        unsetenv("INIT_STARTED_AT");
+        unsetenv("INIT_SELINUX_TOOK");
 
         // Now set up SELinux for second stage.
         selinux_initialize(false);
diff --git a/init/init_parser.cpp b/init/init_parser.cpp
index d017390cee..406b339146 100644
--- a/init/init_parser.cpp
+++ b/init/init_parser.cpp
@@ -110,7 +110,7 @@ bool Parser::ParseConfigFile(const std::string& path) {
     // Nexus 9 boot time, so it's disabled by default.
     if (false) DumpState();
 
-    LOG(VERBOSE) << "(Parsing " << path << " took " << t.duration() << "s.)";
+    LOG(VERBOSE) << "(Parsing " << path << " took " << t << ".)";
     return true;
 }
 
diff --git a/init/property_service.cpp b/init/property_service.cpp
index e19829765d..aed84386dd 100644
--- a/init/property_service.cpp
+++ b/init/property_service.cpp
@@ -169,11 +169,18 @@ bool is_legal_property_name(const std::string &name)
     return true;
 }
 
-static int property_set_impl(const char* name, const char* value) {
+int property_set(const char* name, const char* value) {
     size_t valuelen = strlen(value);
 
-    if (!is_legal_property_name(name)) return -1;
-    if (valuelen >= PROP_VALUE_MAX) return -1;
+    if (!is_legal_property_name(name)) {
+        LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: bad name";
+        return -1;
+    }
+    if (valuelen >= PROP_VALUE_MAX) {
+        LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: "
+                   << "value too long";
+        return -1;
+    }
 
     if (strcmp("selinux.restorecon_recursive", name) == 0 && valuelen > 0) {
         if (restorecon(value, SELINUX_ANDROID_RESTORECON_RECURSE) != 0) {
@@ -182,49 +189,42 @@ static int property_set_impl(const char* name, const char* value) {
     }
 
     prop_info* pi = (prop_info*) __system_property_find(name);
-
-    if(pi != 0) {
-        /* ro.* properties may NEVER be modified once set */
-        if(!strncmp(name, "ro.", 3)) return -1;
+    if (pi != nullptr) {
+        // ro.* properties are actually "write-once".
+        if (!strncmp(name, "ro.", 3)) {
+            LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: "
+                       << "property already set";
+            return -1;
+        }
 
         __system_property_update(pi, value, valuelen);
     } else {
         int rc = __system_property_add(name, strlen(name), value, valuelen);
         if (rc < 0) {
+            LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: "
+                       << "__system_property_add failed";
             return rc;
         }
     }
-    /* If name starts with "net." treat as a DNS property. */
+
+    // If name starts with "net." treat as a DNS property.
     if (strncmp("net.", name, strlen("net.")) == 0)  {
         if (strcmp("net.change", name) == 0) {
             return 0;
         }
-       /*
-        * The 'net.change' property is a special property used track when any
-        * 'net.*' property name is updated. It is _ONLY_ updated here. Its value
-        * contains the last updated 'net.*' property.
-        */
+        // The 'net.change' property is a special property used track when any
+        // 'net.*' property name is updated. It is _ONLY_ updated here. Its value
+        // contains the last updated 'net.*' property.
         property_set("net.change", name);
-    } else if (persistent_properties_loaded &&
-            strncmp("persist.", name, strlen("persist.")) == 0) {
-        /*
-         * Don't write properties to disk until after we have read all default properties
-         * to prevent them from being overwritten by default values.
-         */
+    } else if (persistent_properties_loaded && strncmp("persist.", name, strlen("persist.")) == 0) {
+        // Don't write properties to disk until after we have read all default properties
+        // to prevent them from being overwritten by default values.
         write_persistent_property(name, value);
     }
     property_changed(name, value);
     return 0;
 }
 
-int property_set(const char* name, const char* value) {
-    int rc = property_set_impl(name, value);
-    if (rc == -1) {
-        LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed";
-    }
-    return rc;
-}
-
 static void handle_property_set_fd()
 {
     prop_msg msg;
@@ -388,7 +388,7 @@ static void load_properties_from_file(const char* filename, const char* filter)
     }
     data.push_back('\n');
     load_properties(&data[0], filter);
-    LOG(VERBOSE) << "(Loading properties from " << filename << " took " << t.duration() << "s.)";
+    LOG(VERBOSE) << "(Loading properties from " << filename << " took " << t << ".)";
 }
 
 static void load_persistent_properties() {
diff --git a/init/readme.txt b/init/readme.txt
index 7e9d21b69f..7549e3c035 100644
--- a/init/readme.txt
+++ b/init/readme.txt
@@ -440,16 +440,27 @@ Properties
 Init provides information about the services that it is responsible
 for via the below properties.
 
-init.start
+init.svc.<name>
+  State of a named service ("stopped", "stopping", "running", "restarting")
+
+
+Boot timing
+-----------
+Init records some boot timing information in system properties.
+
+ro.boottime.init
   Time after boot in ns (via the CLOCK_BOOTTIME clock) at which the first
   stage of init started.
 
-init.svc.<name>
-  State of a named service ("stopped", "stopping", "running", "restarting")
+ro.boottime.init.selinux
+  How long it took the first stage to initialize SELinux.
+
+ro.boottime.init.cold_boot_wait
+  How long init waited for ueventd's coldboot phase to end.
 
-init.svc.<name>.start
+ro.boottime.<service-name>
   Time after boot in ns (via the CLOCK_BOOTTIME clock) that the service was
-  most recently started.
+  first started.
 
 
 Bootcharting
diff --git a/init/service.cpp b/init/service.cpp
index 1f53a1ba30..4b9724ddf5 100644
--- a/init/service.cpp
+++ b/init/service.cpp
@@ -36,7 +36,6 @@
 #include <android-base/parseint.h>
 #include <android-base/stringprintf.h>
 #include <android-base/strings.h>
-#include <cutils/android_reboot.h>
 #include <system/thread_defs.h>
 
 #include <processgroup/processgroup.h>
@@ -190,9 +189,9 @@ void Service::NotifyStateChange(const std::string& new_state) const {
     property_set(prop_name.c_str(), new_state.c_str());
 
     if (new_state == "running") {
-        prop_name += ".start";
         uint64_t start_ns = time_started_.time_since_epoch().count();
-        property_set(prop_name.c_str(), StringPrintf("%" PRIu64, start_ns).c_str());
+        property_set(StringPrintf("ro.boottime.%s", name_.c_str()).c_str(),
+                     StringPrintf("%" PRIu64, start_ns).c_str());
     }
 }
 
@@ -283,10 +282,8 @@ bool Service::Reap() {
     if ((flags_ & SVC_CRITICAL) && !(flags_ & SVC_RESTART)) {
         if (now < time_crashed_ + 4min) {
             if (++crash_count_ > 4) {
-                LOG(ERROR) << "critical process '" << name_ << "' exited 4 times in 4 minutes; "
-                           << "rebooting into recovery mode";
-                android_reboot(ANDROID_RB_RESTART2, 0, "recovery");
-                return false;
+                LOG(ERROR) << "critical process '" << name_ << "' exited 4 times in 4 minutes";
+                panic();
             }
         } else {
             time_crashed_ = now;
diff --git a/init/signal_handler.cpp b/init/signal_handler.cpp
index 0dea3e0655..1041b82d01 100644
--- a/init/signal_handler.cpp
+++ b/init/signal_handler.cpp
@@ -24,7 +24,6 @@
 #include <unistd.h>
 
 #include <android-base/stringprintf.h>
-#include <cutils/android_reboot.h>
 #include <cutils/list.h>
 #include <cutils/sockets.h>
 
diff --git a/init/util.cpp b/init/util.cpp
index 5205ea0945..38e3b8d829 100644
--- a/init/util.cpp
+++ b/init/util.cpp
@@ -41,6 +41,8 @@
 #include <android-base/stringprintf.h>
 #include <android-base/strings.h>
 #include <android-base/unique_fd.h>
+
+#include <cutils/android_reboot.h>
 /* for ANDROID_SOCKET_* */
 #include <cutils/sockets.h>
 
@@ -472,3 +474,22 @@ bool expand_props(const std::string& src, std::string* dst) {
 
     return true;
 }
+
+void reboot(const char* destination) {
+    android_reboot(ANDROID_RB_RESTART2, 0, destination);
+    // We're init, so android_reboot will actually have been a syscall so there's nothing
+    // to wait for. If android_reboot returns, just abort so that the kernel will reboot
+    // itself when init dies.
+    PLOG(FATAL) << "reboot failed";
+    abort();
+}
+
+void panic() {
+    LOG(ERROR) << "panic: rebooting to bootloader";
+    reboot("bootloader");
+}
+
+std::ostream& operator<<(std::ostream& os, const Timer& t) {
+    os << t.duration_s() << " seconds";
+    return os;
+}
diff --git a/init/util.h b/init/util.h
index d56da39b53..4b5436145f 100644
--- a/init/util.h
+++ b/init/util.h
@@ -21,8 +21,9 @@
 #include <sys/types.h>
 
 #include <chrono>
-#include <string>
 #include <functional>
+#include <ostream>
+#include <string>
 
 #define COLDBOOT_DONE "/dev/.coldboot_done"
 
@@ -51,15 +52,21 @@ class Timer {
   Timer() : start_(boot_clock::now()) {
   }
 
-  double duration() {
+  double duration_s() const {
     typedef std::chrono::duration<double> double_duration;
     return std::chrono::duration_cast<double_duration>(boot_clock::now() - start_).count();
   }
 
+  int64_t duration_ns() const {
+    return (boot_clock::now() - start_).count();
+  }
+
  private:
   boot_clock::time_point start_;
 };
 
+std::ostream& operator<<(std::ostream& os, const Timer& t);
+
 unsigned int decode_uid(const char *s);
 
 int mkdir_recursive(const char *pathname, mode_t mode);
@@ -72,4 +79,8 @@ int restorecon(const char *pathname, int flags = 0);
 std::string bytes_to_hex(const uint8_t *bytes, size_t bytes_len);
 bool is_dir(const char* pathname);
 bool expand_props(const std::string& src, std::string* dst);
+
+void reboot(const char* destination) __attribute__((__noreturn__));
+void panic() __attribute__((__noreturn__));
+
 #endif