commit 1c8413514409cb3078f7cba8cfcaedb46f1954d0
author Tom Cherry <tomcherry@google.com> Tue Apr 28 17:45:26 2020 -0700
committer Tom Cherry <tomcherry@google.com> Wed Apr 29 09:01:53 2020 -0700
tree 37977b4b9600fe90ff9f6ac0430870aa08fdc86f
parent e3e77d382fd1e1dbb2acb777658064e78be94237

init: add even more debugging information for reboot

There are devices stuck waiting for vendor_init to finish a command,
without giving much more information.  Instead of setting aside the
last run command, it's more valuable to store and dump the last 30
logs seen.

Bug: 155203339
Test: these logs appear during hung reboots
Test: normal reboots have no difference.
Change-Id: I99cae248eb81eaf34ef66b910fa653a9fa135f68

init/init.cpp

diff --git a/init/init.cpp b/init/init.cpp
index b177495..3f8f628 100644
--- a/init/init.cpp
+++ b/init/init.cpp
@@ -215,16 +215,6 @@
     prop_waiter_state.ResetWaitForProp();
 }
 
-static void UnwindMainThreadStack() {
-    std::unique_ptr<Backtrace> backtrace(Backtrace::Create(BACKTRACE_CURRENT_PROCESS, 1));
-    if (!backtrace->Unwind(0)) {
-        LOG(ERROR) << __FUNCTION__ << ": Failed to unwind callstack.";
-    }
-    for (size_t i = 0; i < backtrace->NumFrames(); i++) {
-        LOG(ERROR) << backtrace->FormatFrameData(i);
-    }
-}
-
 static class ShutdownState {
   public:
     void TriggerShutdown(const std::string& command) {
@@ -242,13 +232,13 @@
     std::optional<std::string> CheckShutdown() {
         auto lock = std::lock_guard{shutdown_command_lock_};
         if (do_shutdown_ && !IsShuttingDown()) {
-            do_shutdown_ = false;
             return shutdown_command_;
         }
         return {};
     }
 
     bool do_shutdown() const { return do_shutdown_; }
+    void set_do_shutdown(bool value) { do_shutdown_ = value; }
 
   private:
     std::mutex shutdown_command_lock_;
@@ -256,16 +246,28 @@
     bool do_shutdown_ = false;
 } shutdown_state;
 
+static void UnwindMainThreadStack() {
+    std::unique_ptr<Backtrace> backtrace(Backtrace::Create(BACKTRACE_CURRENT_PROCESS, 1));
+    if (!backtrace->Unwind(0)) {
+        LOG(ERROR) << __FUNCTION__ << "sys.powerctl: Failed to unwind callstack.";
+    }
+    for (size_t i = 0; i < backtrace->NumFrames(); i++) {
+        LOG(ERROR) << "sys.powerctl: " << backtrace->FormatFrameData(i);
+    }
+}
+
 void DebugRebootLogging() {
-    LOG(INFO) << "do_shutdown: " << shutdown_state.do_shutdown()
+    LOG(INFO) << "sys.powerctl: do_shutdown: " << shutdown_state.do_shutdown()
               << " IsShuttingDown: " << IsShuttingDown();
     if (shutdown_state.do_shutdown()) {
         LOG(ERROR) << "sys.powerctl set while a previous shutdown command has not been handled";
         UnwindMainThreadStack();
+        DumpShutdownDebugInformation();
     }
     if (IsShuttingDown()) {
         LOG(ERROR) << "sys.powerctl set while init is already shutting down";
         UnwindMainThreadStack();
+        DumpShutdownDebugInformation();
     }
 }
 
@@ -719,7 +721,7 @@
     trigger_shutdown = [](const std::string& command) { shutdown_state.TriggerShutdown(command); };
 
     SetStdioToDevNull(argv);
-    InitKernelLogging(argv);
+    InitSecondStageLogging(argv);
     LOG(INFO) << "init second stage started!";
 
     // Init should not crash because of a dependence on any other process, therefore we ignore
@@ -872,6 +874,7 @@
             LOG(INFO) << "Got shutdown_command '" << *shutdown_command
                       << "' Calling HandlePowerctlMessage()";
             HandlePowerctlMessage(*shutdown_command);
+            shutdown_state.set_do_shutdown(false);
         }
 
         if (!(prop_waiter_state.MightBeWaiting() || Service::is_exec_service_running())) {