From 1c8413514409cb3078f7cba8cfcaedb46f1954d0 Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Tue, 28 Apr 2020 17:45:26 -0700 Subject: [PATCH] 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 | 29 ++++++++++++++++------------- init/util.cpp | 47 +++++++++++++++++++++++++++++++++++++++++++++++ init/util.h | 2 ++ 3 files changed, 65 insertions(+), 13 deletions(-) diff --git a/init/init.cpp b/init/init.cpp index b1774950e..3f8f6281c 100644 --- a/init/init.cpp +++ b/init/init.cpp @@ -215,16 +215,6 @@ void ResetWaitForProp() { prop_waiter_state.ResetWaitForProp(); } -static void UnwindMainThreadStack() { - std::unique_ptr 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 @@ static class ShutdownState { std::optional 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 @@ static class ShutdownState { bool do_shutdown_ = false; } shutdown_state; +static void UnwindMainThreadStack() { + std::unique_ptr 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 @@ int SecondStageMain(int argc, char** argv) { 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 @@ int SecondStageMain(int argc, char** argv) { 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())) { diff --git a/init/util.cpp b/init/util.cpp index 24f94ec9e..f9be0551f 100644 --- a/init/util.cpp +++ b/init/util.cpp @@ -30,7 +30,9 @@ #include #include +#include #include +#include #include #include @@ -660,5 +662,50 @@ bool IsRecoveryMode() { return access("/system/bin/recovery", F_OK) == 0; } +// TODO(b/155203339): remove this +// Devices in the lab seem to be stuck during shutdown, but the logs don't capture the last actions +// before shutdown started, so we record those lines, ignoring requests to shutdown, and replay them +// if we identify that the device is stuck. +constexpr size_t kRecordedLogsSize = 30; +std::string recorded_logs[kRecordedLogsSize]; +size_t recorded_log_position = 0; +std::mutex recorded_logs_lock; + +void InitSecondStageLogging(char** argv) { + SetFatalRebootTarget(); + auto second_stage_logger = [](android::base::LogId log_id, android::base::LogSeverity severity, + const char* tag, const char* file, unsigned int line, + const char* message) { + // We only store logs for init, not its children, and only if they're not related to + // sys.powerctl. + if (getpid() == 1 && strstr(message, "sys.powerctl") == nullptr) { + auto lock = std::lock_guard{recorded_logs_lock}; + recorded_logs[recorded_log_position++] = message; + if (recorded_log_position == kRecordedLogsSize) { + recorded_log_position = 0; + } + } + android::base::KernelLogger(log_id, severity, tag, file, line, message); + }; + android::base::InitLogging(argv, second_stage_logger, InitAborter); +} + +void DumpShutdownDebugInformation() { + auto lock = std::lock_guard{recorded_logs_lock}; + android::base::KernelLogger( + android::base::MAIN, android::base::ERROR, "init", nullptr, 0, + "===================== Dumping previous init lines ====================="); + for (size_t i = recorded_log_position; i < kRecordedLogsSize; ++i) { + android::base::KernelLogger(android::base::MAIN, android::base::ERROR, "init", nullptr, 0, + recorded_logs[i].c_str()); + } + for (size_t i = 0; i < recorded_log_position; ++i) { + android::base::KernelLogger(android::base::MAIN, android::base::ERROR, "init", nullptr, 0, + recorded_logs[i].c_str()); + } + android::base::KernelLogger(android::base::MAIN, android::base::ERROR, "init", nullptr, 0, + "===================== End of dump ====================="); +} + } // namespace init } // namespace android diff --git a/init/util.h b/init/util.h index ad322d909..8167b02a2 100644 --- a/init/util.h +++ b/init/util.h @@ -78,6 +78,8 @@ Result>> ParseRestorecon( void SetStdioToDevNull(char** argv); void InitKernelLogging(char** argv); +void InitSecondStageLogging(char** argv); +void DumpShutdownDebugInformation(); bool IsRecoveryMode(); } // namespace init } // namespace android