From ae4d928d816e30dbe57c2c321b0f0759d0567b3f Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 15 Oct 2014 08:49:39 -0700 Subject: [PATCH] logd: Add klogd - Add a klogd to collect the kernel logs and place them into a new kernel log buffer - Parse priority, tag and message from the kernel log messages. - Turn off pruning for worst UID for the kernel log buffer - Sniff for 'PM: suspend exit', 'PM: suspend enter' and 'Suspended for' messages and correct the internal definition time correction against monotonic dynamically. - Discern if we have monotonic or real time (delineation 1980) in audit messages. - perform appropriate math to correct the timestamp to be real time - filter out any external sources of kernel logging Change-Id: I8d4c7c5ac19f1f3218079ee3a05a50e2ca55f60d --- logd/Android.mk | 1 + logd/LogAudit.cpp | 12 +- logd/LogBufferElement.h | 2 +- logd/LogKlog.cpp | 454 ++++++++++++++++++++++++++++++++++++++++ logd/LogKlog.h | 55 +++++ logd/LogListener.cpp | 2 +- logd/LogStatistics.cpp | 16 +- logd/README.property | 7 +- logd/main.cpp | 62 ++++-- 9 files changed, 587 insertions(+), 24 deletions(-) create mode 100644 logd/LogKlog.cpp create mode 100644 logd/LogKlog.h diff --git a/logd/Android.mk b/logd/Android.mk index e65e9ff79..73da8dc61 100644 --- a/logd/Android.mk +++ b/logd/Android.mk @@ -18,6 +18,7 @@ LOCAL_SRC_FILES := \ LogWhiteBlackList.cpp \ libaudit.c \ LogAudit.cpp \ + LogKlog.cpp \ event.logtags LOCAL_SHARED_LIBRARIES := \ diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp index caae54be9..09cdb1894 100644 --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -29,6 +29,7 @@ #include "libaudit.h" #include "LogAudit.h" +#include "LogKlog.h" #define KMSG_PRIORITY(PRI) \ '<', \ @@ -121,6 +122,15 @@ int LogAudit::logPrint(const char *fmt, ...) { && (*cp == ':')) { memcpy(timeptr + sizeof(audit_str) - 1, "0.0", 3); memmove(timeptr + sizeof(audit_str) - 1 + 3, cp, strlen(cp) + 1); + // + // We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to + // differentiate without prejudice, we use 1980 to delineate, earlier + // is monotonic, later is real. + // +# define EPOCH_PLUS_10_YEARS (10 * 1461 / 4 * 24 * 60 * 60) + if (now.tv_sec < EPOCH_PLUS_10_YEARS) { + LogKlog::convertMonotonicToReal(now); + } } else { now.strptime("", ""); // side effect of setting CLOCK_REALTIME } @@ -223,7 +233,7 @@ int LogAudit::logPrint(const char *fmt, ...) { int LogAudit::log(char *buf) { char *audit = strstr(buf, " audit("); if (!audit) { - return -EXDEV; + return 0; } *audit = '\0'; diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 75ec59e80..bca30438e 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -42,7 +42,7 @@ const char *tagToName(uint32_t tag); } static inline bool worstUidEnabledForLogid(log_id_t id) { - return (id != LOG_ID_CRASH) && (id != LOG_ID_EVENTS); + return (id != LOG_ID_CRASH) && (id != LOG_ID_KERNEL) && (id != LOG_ID_EVENTS); } class LogBuffer; diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp new file mode 100644 index 000000000..35fe3a5e9 --- /dev/null +++ b/logd/LogKlog.cpp @@ -0,0 +1,454 @@ +/* + * Copyright (C) 2014 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "LogKlog.h" + +#define KMSG_PRIORITY(PRI) \ + '<', \ + '0' + (LOG_SYSLOG | (PRI)) / 10, \ + '0' + (LOG_SYSLOG | (PRI)) % 10, \ + '>' + +static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' }; + +log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC); + +LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) + : SocketListener(fdRead, false) + , logbuf(buf) + , reader(reader) + , signature(CLOCK_MONOTONIC) + , fdWrite(fdWrite) + , fdRead(fdRead) + , initialized(false) + , enableLogging(true) + , auditd(auditd) { + static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n"; + char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4]; + snprintf(buffer, sizeof(buffer), klogd_message, priority_message, + signature.nsec()); + write(fdWrite, buffer, strlen(buffer)); +} + +bool LogKlog::onDataAvailable(SocketClient *cli) { + if (!initialized) { + prctl(PR_SET_NAME, "logd.klogd"); + initialized = true; + enableLogging = false; + } + + char buffer[LOGGER_ENTRY_MAX_PAYLOAD]; + size_t len = 0; + + for(;;) { + ssize_t retval = 0; + if ((sizeof(buffer) - 1 - len) > 0) { + retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len); + } + if ((retval == 0) && (len == 0)) { + break; + } + if (retval < 0) { + return false; + } + len += retval; + bool full = len == (sizeof(buffer) - 1); + char *ep = buffer + len; + *ep = '\0'; + len = 0; + for(char *ptr, *tok = buffer; + ((tok = strtok_r(tok, "\r\n", &ptr))); + tok = NULL) { + if (((tok + strlen(tok)) == ep) && (retval != 0) && full) { + len = strlen(tok); + memmove(buffer, tok, len); + break; + } + if (*tok) { + log(tok); + } + } + } + + return true; +} + + +void LogKlog::calculateCorrection(const log_time &monotonic, + const char *real_string) { + log_time real; + if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) { + return; + } + // kernel report UTC, log_time::strptime is localtime from calendar. + // Bionic and liblog strptime does not support %z or %Z to pick up + // timezone so we are calculating our own correction. + time_t now = real.tv_sec; + struct tm tm; + memset(&tm, 0, sizeof(tm)); + tm.tm_isdst = -1; + localtime_r(&now, &tm); + real.tv_sec += tm.tm_gmtoff; + correction = real - monotonic; +} + +void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { + const char *cp; + if ((cp = now.strptime(*buf, "[ %s.%q]"))) { + static const char suspend[] = "PM: suspend entry "; + static const char resume[] = "PM: suspend exit "; + static const char suspended[] = "Suspended for "; + + if (isspace(*cp)) { + ++cp; + } + if (!strncmp(cp, suspend, sizeof(suspend) - 1)) { + calculateCorrection(now, cp + sizeof(suspend) - 1); + } else if (!strncmp(cp, resume, sizeof(resume) - 1)) { + calculateCorrection(now, cp + sizeof(resume) - 1); + } else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) { + log_time real; + char *endp; + real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10); + if (*endp == '.') { + real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L; + if (reverse) { + correction -= real; + } else { + correction += real; + } + } + } + + convertMonotonicToReal(now); + *buf = cp; + } else { + now = log_time(CLOCK_REALTIME); + } +} + +// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a +// compensated start time. +void LogKlog::synchronize(const char *buf) { + const char *cp = strstr(buf, "] PM: suspend e"); + if (!cp) { + return; + } + + do { + --cp; + } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.'))); + + log_time now; + sniffTime(now, &cp, true); + + char *suspended = strstr(buf, "] Suspended for "); + if (!suspended || (suspended > cp)) { + return; + } + cp = suspended; + + do { + --cp; + } while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.'))); + + sniffTime(now, &cp, true); +} + +// kernel log prefix, convert to a kernel log priority number +static int parseKernelPrio(const char **buf) { + int pri = LOG_USER | LOG_INFO; + const char *cp = *buf; + if (*cp == '<') { + pri = 0; + while(isdigit(*++cp)) { + pri = (pri * 10) + *cp - '0'; + } + if (*cp == '>') { + ++cp; + } else { + cp = *buf; + pri = LOG_USER | LOG_INFO; + } + *buf = cp; + } + return pri; +} + +// Convert kernel log priority number into an Android Logger priority number +static int convertKernelPrioToAndroidPrio(int pri) { + switch(pri & LOG_PRIMASK) { + case LOG_EMERG: + // FALLTHRU + case LOG_ALERT: + // FALLTHRU + case LOG_CRIT: + return ANDROID_LOG_FATAL; + + case LOG_ERR: + return ANDROID_LOG_ERROR; + + case LOG_WARNING: + return ANDROID_LOG_WARN; + + default: + // FALLTHRU + case LOG_NOTICE: + // FALLTHRU + case LOG_INFO: + break; + + case LOG_DEBUG: + return ANDROID_LOG_DEBUG; + } + + return ANDROID_LOG_INFO; +} + +// +// log a message into the kernel log buffer +// +// Filter rules to parse