From 4efc87e5ebd7612d119cd8c09bf78b32093c258e Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Fri, 4 Sep 2015 11:37:42 -0700 Subject: [PATCH] logd: klogd deal with nuls in dmesg (cherry pick from commit 151beac76d372c5c1bd71e656a6cfbd177e36509) Switch to using string and length in all transactions, treating trailing nuls the same as spaces. ToDo: change dumpstate (bugreport) to use logcat -b printable _regardless_ Bug: 23517551 Change-Id: I42162365e6bf8ed79d356e7b689a673902116fdb --- logd/LogAudit.cpp | 6 +- logd/LogAudit.h | 2 +- logd/LogKlog.cpp | 216 ++++++++++++++++++++++++++++------------------ logd/LogKlog.h | 11 +-- logd/main.cpp | 6 +- 5 files changed, 147 insertions(+), 94 deletions(-) diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp index 4b3547ce1..7db17d1df 100644 --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -239,9 +239,9 @@ int LogAudit::logPrint(const char *fmt, ...) { return rc; } -int LogAudit::log(char *buf) { +int LogAudit::log(char *buf, size_t len) { char *audit = strstr(buf, " audit("); - if (!audit) { + if (!audit || (audit >= &buf[len])) { return 0; } @@ -249,7 +249,7 @@ int LogAudit::log(char *buf) { int rc; char *type = strstr(buf, "type="); - if (type) { + if (type && (type < &buf[len])) { rc = logPrint("%s %s", type, audit + 1); } else { rc = logPrint("%s", audit + 1); diff --git a/logd/LogAudit.h b/logd/LogAudit.h index f977be983..23428228a 100644 --- a/logd/LogAudit.h +++ b/logd/LogAudit.h @@ -28,7 +28,7 @@ class LogAudit : public SocketListener { public: LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg); - int log(char *buf); + int log(char *buf, size_t len); protected: virtual bool onDataAvailable(SocketClient *cli); diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp index f0b18da02..242d7a0a4 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -81,6 +81,8 @@ static char *is_timestamp(char *s, size_t len) { // Like strtok_r with "\r\n" except that we look for log signatures (regex) // \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \) // and split if we see a second one without a newline. +// We allow nuls in content, monitoring the overall length and sub-length of +// the discovered tokens. #define SIGNATURE_MASK 0xF0 // following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature @@ -256,7 +258,7 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { break; } if (*tok) { - log(tok); + log(tok, sublen); } } } @@ -266,9 +268,11 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { void LogKlog::calculateCorrection(const log_time &monotonic, - const char *real_string) { + const char *real_string, + size_t len) { log_time real; - if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) { + const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC"); + if (!ep || (ep > &real_string[len])) { return; } // kernel report UTC, log_time::strptime is localtime from calendar. @@ -287,41 +291,79 @@ static const char suspendStr[] = "PM: suspend entry "; static const char resumeStr[] = "PM: suspend exit "; static const char suspendedStr[] = "Suspended for "; -void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { - const char *cp; - if ((cp = now.strptime(*buf, "[ %s.%q]"))) { +static const char *strnstr(const char *s, size_t len, const char *needle) { + char c; + + if (!len) { + return NULL; + } + if ((c = *needle++) != 0) { + size_t needleLen = strlen(needle); + do { + do { + if (len <= needleLen) { + return NULL; + } + --len; + } while (*s++ != c); + } while (memcmp(s, needle, needleLen) != 0); + s--; + } + return s; +} + +void LogKlog::sniffTime(log_time &now, + const char **buf, size_t len, + bool reverse) { + const char *cp = now.strptime(*buf, "[ %s.%q]"); + if (cp && (cp >= &(*buf)[len])) { + cp = NULL; + } + len -= cp - *buf; + if (cp) { static const char healthd[] = "healthd"; static const char battery[] = ": battery "; - if (isspace(*cp)) { + if (len && isspace(*cp)) { ++cp; + --len; } *buf = cp; const char *b; - if ((b = strstr(cp, suspendStr))) { - calculateCorrection(now, b + sizeof(suspendStr) - 1); - } else if ((b = strstr(cp, resumeStr))) { - calculateCorrection(now, b + sizeof(resumeStr) - 1); - } else if (((b = strstr(cp, healthd))) && ((b = strstr(b, battery)))) { + if (((b = strnstr(cp, len, suspendStr))) + && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { + len -= b - cp; + calculateCorrection(now, b, len); + } else if (((b = strnstr(cp, len, resumeStr))) + && ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) { + len -= b - cp; + calculateCorrection(now, b, len); + } else if (((b = strnstr(cp, len, healthd))) + && ((size_t)((b += sizeof(healthd) - 1) - cp) < len) + && ((b = strnstr(b, len -= b - cp, battery))) + && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) { + len -= b - cp; // NB: healthd is roughly 150us late, worth the price to deal with // ntp-induced or hardware clock drift. // look for " 2???-??-?? ??:??:??.????????? ???" - const char *tp; - for (tp = b + sizeof(battery) - 1; *tp && (*tp != '\n'); ++tp) { - if ((tp[0] == ' ') && (tp[1] == '2') && (tp[5] == '-')) { - calculateCorrection(now, tp + 1); + for (; len && *b && (*b != '\n'); ++b, --len) { + if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) { + calculateCorrection(now, b + 1, len - 1); break; } } - } else if ((b = strstr(cp, suspendedStr))) { + } else if (((b = strnstr(cp, len, suspendedStr))) + && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { + len -= b - cp; log_time real; char *endp; - real.tv_sec = strtol(b + sizeof(suspendedStr) - 1, &endp, 10); - if (*endp == '.') { + real.tv_sec = strtol(b, &endp, 10); + if ((*endp == '.') && ((size_t)(endp - b) < len)) { unsigned long multiplier = NS_PER_SEC; real.tv_nsec = 0; - while (isdigit(*++endp) && (multiplier /= 10)) { + len -= endp - b; + while (--len && isdigit(*++endp) && (multiplier /= 10)) { real.tv_nsec += (*endp - '0') * multiplier; } if (reverse) { @@ -338,8 +380,8 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { } } -pid_t LogKlog::sniffPid(const char *cp) { - while (*cp) { +pid_t LogKlog::sniffPid(const char *cp, size_t len) { + while (len) { // Mediatek kernels with modified printk if (*cp == '[') { int pid = 0; @@ -350,20 +392,21 @@ pid_t LogKlog::sniffPid(const char *cp) { break; // Only the first one } ++cp; + --len; } return 0; } // kernel log prefix, convert to a kernel log priority number -static int parseKernelPrio(const char **buf) { +static int parseKernelPrio(const char **buf, size_t len) { int pri = LOG_USER | LOG_INFO; const char *cp = *buf; - if (*cp == '<') { + if (len && (*cp == '<')) { pri = 0; - while(isdigit(*++cp)) { + while(--len && isdigit(*++cp)) { pri = (pri * 10) + *cp - '0'; } - if (*cp == '>') { + if (len && (*cp == '>')) { ++cp; } else { cp = *buf; @@ -376,15 +419,15 @@ static int parseKernelPrio(const char **buf) { // 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, suspendStr); +void LogKlog::synchronize(const char *buf, size_t len) { + const char *cp = strnstr(buf, len, suspendStr); if (!cp) { - cp = strstr(buf, resumeStr); + cp = strnstr(buf, len, resumeStr); if (!cp) { return; } } else { - const char *rp = strstr(buf, resumeStr); + const char *rp = strnstr(buf, len, resumeStr); if (rp && (rp < cp)) { cp = rp; } @@ -396,12 +439,12 @@ void LogKlog::synchronize(const char *buf) { if (*cp == '\n') { ++cp; } - parseKernelPrio(&cp); + parseKernelPrio(&cp, len - (cp - buf)); log_time now; - sniffTime(now, &cp, true); + sniffTime(now, &cp, len - (cp - buf), true); - char *suspended = strstr(buf, suspendedStr); + const char *suspended = strnstr(buf, len, suspendedStr); if (!suspended || (suspended > cp)) { return; } @@ -413,9 +456,9 @@ void LogKlog::synchronize(const char *buf) { if (*cp == '\n') { ++cp; } - parseKernelPrio(&cp); + parseKernelPrio(&cp, len - (cp - buf)); - sniffTime(now, &cp, true); + sniffTime(now, &cp, len - (cp - buf), true); } // Convert kernel log priority number into an Android Logger priority number @@ -491,19 +534,20 @@ static const char *strnrchr(const char *s, size_t len, char c) { // logd.klogd: // return -1 if message logd.klogd: // -int LogKlog::log(const char *buf) { - if (auditd && strstr(buf, " audit(")) { +int LogKlog::log(const char *buf, size_t len) { + if (auditd && strnstr(buf, len, " audit(")) { return 0; } - int pri = parseKernelPrio(&buf); + const char *p = buf; + int pri = parseKernelPrio(&p, len); log_time now; - sniffTime(now, &buf, false); + sniffTime(now, &p, len - (p - buf), false); // sniff for start marker const char klogd_message[] = "logd.klogd: "; - const char *start = strstr(buf, klogd_message); + const char *start = strnstr(p, len - (p - buf), klogd_message); if (start) { uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10); if (sig == signature.nsec()) { @@ -522,7 +566,7 @@ int LogKlog::log(const char *buf) { } // Parse pid, tid and uid - const pid_t pid = sniffPid(buf); + const pid_t pid = sniffPid(p, len - (p - buf)); const pid_t tid = pid; const uid_t uid = pid ? logbuf->pidToUid(pid) : 0; @@ -530,40 +574,43 @@ int LogKlog::log(const char *buf) { // Some may view the following as an ugly heuristic, the desire is to // beautify the kernel logs into an Android Logging format; the goal is // admirable but costly. - while (isspace(*buf)) { - ++buf; + while ((isspace(*p) || !*p) && (p < &buf[len])) { + ++p; } - if (!*buf) { + if (p >= &buf[len]) { // timestamp, no content return 0; } - start = buf; + start = p; const char *tag = ""; const char *etag = tag; - if (!isspace(*buf)) { + size_t taglen = len - (p - buf); + if (!isspace(*p) && *p) { const char *bt, *et, *cp; - bt = buf; - if (!strncmp(buf, "[INFO]", 6)) { + bt = p; + if (!strncmp(p, "[INFO]", 6)) { // [