From 7bc87a5a780361928bd1aeed9d2f22233fe05407 Mon Sep 17 00:00:00 2001 From: Elliott Hughes Date: Thu, 4 Aug 2016 16:09:39 -0700 Subject: [PATCH] Move init's kernel logging into libbase. This will let other stuff (such as adbd and recovery) use it too. Bug: http://b/28467098 Change-Id: Idab51f438ed3edd6fe65a56c4b396eaff5f3833e --- base/include/android-base/logging.h | 19 +++--- base/logging.cpp | 90 +++++++++++++++++++++-------- init/action.cpp | 3 +- init/builtins.cpp | 36 ++++++++---- init/log.cpp | 43 +------------- init/log.h | 2 - init/readme.txt | 3 - 7 files changed, 107 insertions(+), 89 deletions(-) diff --git a/base/include/android-base/logging.h b/base/include/android-base/logging.h index 56e2ddeed..66d60c96c 100644 --- a/base/include/android-base/logging.h +++ b/base/include/android-base/logging.h @@ -53,8 +53,8 @@ enum LogId { typedef std::function LogFunction; -extern void StderrLogger(LogId, LogSeverity, const char*, const char*, - unsigned int, const char*); +void KernelLogger(LogId, LogSeverity, const char*, const char*, unsigned int, const char*); +void StderrLogger(LogId, LogSeverity, const char*, const char*, unsigned int, const char*); #ifdef __ANDROID__ // We expose this even though it is the default because a user that wants to @@ -79,17 +79,14 @@ class LogdLogger { // The tag (or '*' for the global level) comes first, followed by a colon and a // letter indicating the minimum priority level we're expected to log. This can // be used to reveal or conceal logs with specific tags. -extern void InitLogging(char* argv[], LogFunction&& logger); +void InitLogging(char* argv[], LogFunction&& logger); // Configures logging using the default logger (logd for the device, stderr for // the host). -extern void InitLogging(char* argv[]); +void InitLogging(char* argv[]); // Replace the current logger. -extern void SetLogger(LogFunction&& logger); - -// Get the minimum severity level for logging. -extern LogSeverity GetMinimumLogSeverity(); +void SetLogger(LogFunction&& logger); class ErrnoRestorer { public: @@ -334,6 +331,12 @@ class LogMessage { DISALLOW_COPY_AND_ASSIGN(LogMessage); }; +// Get the minimum severity level for logging. +LogSeverity GetMinimumLogSeverity(); + +// Set the minimum severity level for logging, returning the old severity. +LogSeverity SetMinimumLogSeverity(LogSeverity new_severity); + // Allows to temporarily change the minimum severity level for logging. class ScopedLogSeverity { public: diff --git a/base/logging.cpp b/base/logging.cpp index 959bb8b05..1f47a9fa3 100644 --- a/base/logging.cpp +++ b/base/logging.cpp @@ -14,12 +14,13 @@ * limitations under the License. */ -#ifdef _WIN32 +#if defined(_WIN32) #include #endif #include "android-base/logging.h" +#include #include #include @@ -30,6 +31,10 @@ #include #endif +#if defined(__linux__) +#include +#endif + #include #include #include @@ -172,10 +177,6 @@ static bool gInitialized = false; static LogSeverity gMinimumLogSeverity = INFO; static auto& gProgramInvocationName = *new std::unique_ptr(); -LogSeverity GetMinimumLogSeverity() { - return gMinimumLogSeverity; -} - static const char* ProgramInvocationName() { if (gProgramInvocationName == nullptr) { gProgramInvocationName.reset(new std::string(getprogname())); @@ -184,6 +185,42 @@ static const char* ProgramInvocationName() { return gProgramInvocationName->c_str(); } +#if defined(__linux__) +void KernelLogger(android::base::LogId, android::base::LogSeverity severity, + const char* tag, const char*, unsigned int, const char* msg) { + static constexpr int kLogSeverityToKernelLogLevel[] = { + [android::base::VERBOSE] = 7, // KERN_DEBUG (there is no verbose kernel log level) + [android::base::DEBUG] = 7, // KERN_DEBUG + [android::base::INFO] = 6, // KERN_INFO + [android::base::WARNING] = 4, // KERN_WARNING + [android::base::ERROR] = 3, // KERN_ERROR + [android::base::FATAL] = 2, // KERN_CRIT + }; + static_assert(arraysize(kLogSeverityToKernelLogLevel) == android::base::FATAL + 1, + "Mismatch in size of kLogSeverityToKernelLogLevel and values in LogSeverity"); + + static int klog_fd = TEMP_FAILURE_RETRY(open("/dev/kmsg", O_WRONLY | O_CLOEXEC)); + if (klog_fd == -1) return; + + int level = kLogSeverityToKernelLogLevel[severity]; + + // The kernel's printk buffer is only 1024 bytes. + // TODO: should we automatically break up long lines into multiple lines? + // Or we could log but with something like "..." at the end? + char buf[1024]; + size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %s\n", level, tag, msg); + if (size > sizeof(buf)) { + size = snprintf(buf, sizeof(buf), "<%d>%s: %zu-byte message too long for printk\n", + level, tag, size); + } + + iovec iov[1]; + iov[0].iov_base = buf; + iov[0].iov_len = size; + TEMP_FAILURE_RETRY(writev(klog_fd, iov, 1)); +} +#endif + void StderrLogger(LogId, LogSeverity severity, const char*, const char* file, unsigned int line, const char* message) { struct tm now; @@ -211,28 +248,26 @@ void StderrLogger(LogId, LogSeverity severity, const char*, const char* file, LogdLogger::LogdLogger(LogId default_log_id) : default_log_id_(default_log_id) { } -static const android_LogPriority kLogSeverityToAndroidLogPriority[] = { - ANDROID_LOG_VERBOSE, ANDROID_LOG_DEBUG, ANDROID_LOG_INFO, - ANDROID_LOG_WARN, ANDROID_LOG_ERROR, ANDROID_LOG_FATAL, -}; -static_assert(arraysize(kLogSeverityToAndroidLogPriority) == FATAL + 1, - "Mismatch in size of kLogSeverityToAndroidLogPriority and values " - "in LogSeverity"); - -static const log_id kLogIdToAndroidLogId[] = { - LOG_ID_MAX, LOG_ID_MAIN, LOG_ID_SYSTEM, -}; -static_assert(arraysize(kLogIdToAndroidLogId) == SYSTEM + 1, - "Mismatch in size of kLogIdToAndroidLogId and values in LogId"); - void LogdLogger::operator()(LogId id, LogSeverity severity, const char* tag, const char* file, unsigned int line, const char* message) { + static constexpr android_LogPriority kLogSeverityToAndroidLogPriority[] = { + ANDROID_LOG_VERBOSE, ANDROID_LOG_DEBUG, ANDROID_LOG_INFO, + ANDROID_LOG_WARN, ANDROID_LOG_ERROR, ANDROID_LOG_FATAL, + }; + static_assert(arraysize(kLogSeverityToAndroidLogPriority) == FATAL + 1, + "Mismatch in size of kLogSeverityToAndroidLogPriority and values in LogSeverity"); + int priority = kLogSeverityToAndroidLogPriority[severity]; if (id == DEFAULT) { id = default_log_id_; } + static constexpr log_id kLogIdToAndroidLogId[] = { + LOG_ID_MAX, LOG_ID_MAIN, LOG_ID_SYSTEM, + }; + static_assert(arraysize(kLogIdToAndroidLogId) == SYSTEM + 1, + "Mismatch in size of kLogIdToAndroidLogId and values in LogId"); log_id lg_id = kLogIdToAndroidLogId[id]; if (priority == ANDROID_LOG_FATAL) { @@ -427,13 +462,22 @@ void LogMessage::LogLine(const char* file, unsigned int line, LogId id, gLogger(id, severity, tag, file, line, message); } -ScopedLogSeverity::ScopedLogSeverity(LogSeverity level) { - old_ = gMinimumLogSeverity; - gMinimumLogSeverity = level; +LogSeverity GetMinimumLogSeverity() { + return gMinimumLogSeverity; +} + +LogSeverity SetMinimumLogSeverity(LogSeverity new_severity) { + LogSeverity old_severity = gMinimumLogSeverity; + gMinimumLogSeverity = new_severity; + return old_severity; +} + +ScopedLogSeverity::ScopedLogSeverity(LogSeverity new_severity) { + old_ = SetMinimumLogSeverity(new_severity); } ScopedLogSeverity::~ScopedLogSeverity() { - gMinimumLogSeverity = old_; + SetMinimumLogSeverity(old_); } } // namespace base diff --git a/init/action.cpp b/init/action.cpp index f3e362eba..ed88f6d89 100644 --- a/init/action.cpp +++ b/init/action.cpp @@ -118,7 +118,8 @@ void Action::ExecuteCommand(const Command& command) const { Timer t; int result = command.InvokeFunc(); - if (klog_get_level() >= KLOG_DEBUG_LEVEL) { + // TODO: this should probably be changed to "if (failed || took a long time)"... + if (android::base::GetMinimumLogSeverity() <= android::base::DEBUG) { std::string trigger_name = BuildTriggersString(); std::string cmd_str = command.BuildCommandString(); std::string source = command.BuildSourceString(); diff --git a/init/builtins.cpp b/init/builtins.cpp index d64c3d265..3d220c53b 100644 --- a/init/builtins.cpp +++ b/init/builtins.cpp @@ -482,11 +482,7 @@ static void import_late(const std::vector& args, size_t start_index * not return. */ static int do_mount_all(const std::vector& args) { - pid_t pid; int ret = -1; - int child_ret = -1; - int status; - struct fstab *fstab; const char* fstabfile = args[1].c_str(); /* @@ -495,9 +491,10 @@ static int do_mount_all(const std::vector& args) { * process if anything goes wrong (crash or memory leak), and wait for * the child to finish in the parent. */ - pid = fork(); + pid_t pid = fork(); if (pid > 0) { /* Parent. Wait for the child to return */ + int status; int wp_ret = TEMP_FAILURE_RETRY(waitpid(pid, &status, 0)); if (wp_ret == -1) { // Unexpected error code. We will continue anyway. @@ -511,9 +508,13 @@ static int do_mount_all(const std::vector& args) { } } else if (pid == 0) { /* child, call fs_mgr_mount_all() */ - klog_set_level(6); /* So we can see what fs_mgr_mount_all() does */ - fstab = fs_mgr_read_fstab(fstabfile); - child_ret = fs_mgr_mount_all(fstab); + + // So we can always see what fs_mgr_mount_all() does. + // Only needed if someone explicitly changes the default log level in their init.rc. + android::base::ScopedLogSeverity info(android::base::INFO); + + struct fstab* fstab = fs_mgr_read_fstab(fstabfile); + int child_ret = fs_mgr_mount_all(fstab); fs_mgr_free_fstab(fstab); if (child_ret == -1) { PLOG(ERROR) << "fs_mgr_mount_all returned an error"; @@ -866,12 +867,23 @@ static int do_restorecon_recursive(const std::vector& args) { } static int do_loglevel(const std::vector& args) { + // TODO: support names instead/as well? int log_level = std::stoi(args[1]); - if (log_level < KLOG_ERROR_LEVEL || log_level > KLOG_DEBUG_LEVEL) { - LOG(ERROR) << "loglevel: invalid log level " << log_level; - return -EINVAL; + android::base::LogSeverity severity; + switch (log_level) { + case 7: severity = android::base::DEBUG; break; + case 6: severity = android::base::INFO; break; + case 5: + case 4: severity = android::base::WARNING; break; + case 3: severity = android::base::ERROR; break; + case 2: + case 1: + case 0: severity = android::base::FATAL; break; + default: + LOG(ERROR) << "loglevel: invalid log level " << log_level; + return -EINVAL; } - klog_set_level(log_level); + android::base::SetMinimumLogSeverity(severity); return 0; } diff --git a/init/log.cpp b/init/log.cpp index 379141a46..861834011 100644 --- a/init/log.cpp +++ b/init/log.cpp @@ -17,52 +17,16 @@ #include "log.h" #include -#include #include -#include -#include -#include #include -static const int kLogSeverityToKLogLevel[] = { - [android::base::VERBOSE] = KLOG_DEBUG_LEVEL, - [android::base::DEBUG] = KLOG_DEBUG_LEVEL, - [android::base::INFO] = KLOG_INFO_LEVEL, - [android::base::WARNING] = KLOG_WARNING_LEVEL, - [android::base::ERROR] = KLOG_ERROR_LEVEL, - [android::base::FATAL] = KLOG_ERROR_LEVEL, -}; -static_assert(arraysize(kLogSeverityToKLogLevel) == android::base::FATAL + 1, - "Mismatch in size of kLogSeverityToKLogLevel and values in LogSeverity"); - -static void KernelLogger(android::base::LogId, android::base::LogSeverity severity, - const char* tag, const char*, unsigned int, const char* msg) { - int level = kLogSeverityToKLogLevel[severity]; - if (level > klog_get_level()) return; - - // The kernel's printk buffer is only 1024 bytes. - // TODO: should we automatically break up long lines into multiple lines? - // Or we could log but with something like "..." at the end? - char buf[1024]; - size_t size = snprintf(buf, sizeof(buf), "<%d>%s: %s\n", level, tag, msg); - if (size > sizeof(buf)) { - size = snprintf(buf, sizeof(buf), "<%d>%s: %zu-byte message too long for printk\n", - level, tag, size); - } - - iovec iov[1]; - iov[0].iov_base = buf; - iov[0].iov_len = size; - klog_writev(level, iov, 1); -} - void InitKernelLogging(char* argv[]) { // Make stdin/stdout/stderr all point to /dev/null. int fd = open("/sys/fs/selinux/null", O_RDWR); if (fd == -1) { int saved_errno = errno; - android::base::InitLogging(argv, &KernelLogger); + android::base::InitLogging(argv, &android::base::KernelLogger); errno = saved_errno; PLOG(FATAL) << "Couldn't open /sys/fs/selinux/null"; } @@ -71,8 +35,7 @@ void InitKernelLogging(char* argv[]) { dup2(fd, 2); if (fd > 2) close(fd); - android::base::InitLogging(argv, &KernelLogger); - klog_set_level(KLOG_INFO_LEVEL); + android::base::InitLogging(argv, &android::base::KernelLogger); } int selinux_klog_callback(int type, const char *fmt, ...) { @@ -87,6 +50,6 @@ int selinux_klog_callback(int type, const char *fmt, ...) { va_start(ap, fmt); vsnprintf(buf, sizeof(buf), fmt, ap); va_end(ap); - KernelLogger(android::base::MAIN, severity, "selinux", nullptr, 0, buf); + android::base::KernelLogger(android::base::MAIN, severity, "selinux", nullptr, 0, buf); return 0; } diff --git a/init/log.h b/init/log.h index cf552a19c..8fa6d74f4 100644 --- a/init/log.h +++ b/init/log.h @@ -19,8 +19,6 @@ #include -#include - void InitKernelLogging(char* argv[]); int selinux_klog_callback(int level, const char* fmt, ...) __printflike(2, 3); diff --git a/init/readme.txt b/init/readme.txt index 7260775f6..4c04f1737 100644 --- a/init/readme.txt +++ b/init/readme.txt @@ -514,6 +514,3 @@ For quicker turnaround when working on init itself, use: Alternatively, use the emulator: emulator -partition-size 1024 -verbose -show-kernel -no-window - -You might want to change the klog_set_level call so you see all the kernel -logging in dmesg (or the emulator output).