Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 1c841351 authored by Tom Cherry's avatar Tom Cherry
Browse files

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
parent e3e77d38

init/init.cpp

+16 −13
Original line number Original line Diff line number Diff line
@@ -215,16 +215,6 @@ void ResetWaitForProp() { 
    prop_waiter_state.ResetWaitForProp();

    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 {

static class ShutdownState {

  public:

  public:

    void TriggerShutdown(const std::string& command) {

    void TriggerShutdown(const std::string& command) {
@@ -242,13 +232,13 @@ static class ShutdownState { 
    std::optional<std::string> CheckShutdown() {

    std::optional<std::string> CheckShutdown() {

        auto lock = std::lock_guard{shutdown_command_lock_};

        auto lock = std::lock_guard{shutdown_command_lock_};

        if (do_shutdown_ && !IsShuttingDown()) {

        if (do_shutdown_ && !IsShuttingDown()) {

            do_shutdown_ = false;

            return shutdown_command_;

            return shutdown_command_;

        }

        }

        return {};

        return {};

    }

    }





    bool do_shutdown() const { return do_shutdown_; }

    bool do_shutdown() const { return do_shutdown_; }

    void set_do_shutdown(bool value) { do_shutdown_ = value; }





  private:

  private:

    std::mutex shutdown_command_lock_;

    std::mutex shutdown_command_lock_;
@@ -256,16 +246,28 @@ static class ShutdownState { 
    bool do_shutdown_ = false;

    bool do_shutdown_ = false;

} shutdown_state;

} 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() {

void DebugRebootLogging() {

    LOG(INFO) << "do_shutdown: " << shutdown_state.do_shutdown()

    LOG(INFO) << "sys.powerctl: do_shutdown: " << shutdown_state.do_shutdown()

              << " IsShuttingDown: " << IsShuttingDown();

              << " IsShuttingDown: " << IsShuttingDown();

    if (shutdown_state.do_shutdown()) {

    if (shutdown_state.do_shutdown()) {

        LOG(ERROR) << "sys.powerctl set while a previous shutdown command has not been handled";

        LOG(ERROR) << "sys.powerctl set while a previous shutdown command has not been handled";

        UnwindMainThreadStack();

        UnwindMainThreadStack();

        DumpShutdownDebugInformation();

    }

    }

    if (IsShuttingDown()) {

    if (IsShuttingDown()) {

        LOG(ERROR) << "sys.powerctl set while init is already shutting down";

        LOG(ERROR) << "sys.powerctl set while init is already shutting down";

        UnwindMainThreadStack();

        UnwindMainThreadStack();

        DumpShutdownDebugInformation();

    }

    }

}

}
@@ -719,7 +721,7 @@ int SecondStageMain(int argc, char** argv) { 
    trigger_shutdown = [](const std::string& command) { shutdown_state.TriggerShutdown(command); };

    trigger_shutdown = [](const std::string& command) { shutdown_state.TriggerShutdown(command); };





    SetStdioToDevNull(argv);

    SetStdioToDevNull(argv);

    InitKernelLogging(argv);

    InitSecondStageLogging(argv);

    LOG(INFO) << "init second stage started!";

    LOG(INFO) << "init second stage started!";





    // Init should not crash because of a dependence on any other process, therefore we ignore

    // 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

            LOG(INFO) << "Got shutdown_command '" << *shutdown_command

                      << "' Calling HandlePowerctlMessage()";

                      << "' Calling HandlePowerctlMessage()";

            HandlePowerctlMessage(*shutdown_command);

            HandlePowerctlMessage(*shutdown_command);

            shutdown_state.set_do_shutdown(false);

        }

        }





        if (!(prop_waiter_state.MightBeWaiting() || Service::is_exec_service_running())) {

        if (!(prop_waiter_state.MightBeWaiting() || Service::is_exec_service_running())) {

init/util.cpp

+47 −0
Original line number Original line Diff line number Diff line
@@ -30,7 +30,9 @@ 
#include <time.h>

#include <time.h>

#include <unistd.h>

#include <unistd.h>





#include <mutex>

#include <thread>

#include <thread>

#include <vector>





#include <android-base/file.h>

#include <android-base/file.h>

#include <android-base/logging.h>

#include <android-base/logging.h>
@@ -660,5 +662,50 @@ bool IsRecoveryMode() { 
    return access("/system/bin/recovery", F_OK) == 0;

    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 init

}  // namespace android
 
}  // namespace android

init/util.h

+2 −0
Original line number Original line Diff line number Diff line
@@ -78,6 +78,8 @@ Result<std::pair<int, std::vector<std::string>>> ParseRestorecon( 




void SetStdioToDevNull(char** argv);

void SetStdioToDevNull(char** argv);

void InitKernelLogging(char** argv);

void InitKernelLogging(char** argv);

void InitSecondStageLogging(char** argv);

void DumpShutdownDebugInformation();

bool IsRecoveryMode();

bool IsRecoveryMode();

}  // namespace init

}  // namespace init

}  // namespace android
 
}  // namespace android