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
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())) {
diff --git a/init/util.cpp b/init/util.cpp
index 24f94ec..f9be055 100644
--- a/init/util.cpp
+++ b/init/util.cpp
@@ -30,7 +30,9 @@
#include <time.h>
#include <unistd.h>
+#include <mutex>
#include <thread>
+#include <vector>
#include <android-base/file.h>
#include <android-base/logging.h>
@@ -660,5 +662,50 @@
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 ad322d9..8167b02 100644
--- a/init/util.h
+++ b/init/util.h
@@ -78,6 +78,8 @@
void SetStdioToDevNull(char** argv);
void InitKernelLogging(char** argv);
+void InitSecondStageLogging(char** argv);
+void DumpShutdownDebugInformation();
bool IsRecoveryMode();
} // namespace init
} // namespace android