logd: klogd deal with nuls in dmesg
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
diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index f0b18da..242d7a0 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -81,6 +81,8 @@
// 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
// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
@@ -256,7 +258,7 @@
break;
}
if (*tok) {
- log(tok);
+ log(tok, sublen);
}
}
}
@@ -266,9 +268,11 @@
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 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 @@
}
}
-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 @@
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 @@
// 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 @@
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 @@
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 @@
// logd.klogd:
// return -1 if message logd.klogd: <signature>
//
-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 @@
}
// 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 @@
// 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)) {
// <PRI>[<TIME>] "[INFO]"<tag> ":" message
- bt = buf + 6;
+ bt = p + 6;
+ taglen -= 6;
}
- for(et = bt; *et && (*et != ':') && !isspace(*et); ++et) {
+ for(et = bt; taglen && *et && (*et != ':') && !isspace(*et); ++et, --taglen) {
// skip ':' within [ ... ]
if (*et == '[') {
- while (*et && *et != ']') {
+ while (taglen && *et && *et != ']') {
++et;
+ --taglen;
}
}
}
- for(cp = et; isspace(*cp); ++cp);
+ for(cp = et; taglen && isspace(*cp); ++cp, --taglen);
size_t size;
if (*cp == ':') {
// One Word
tag = bt;
etag = et;
- buf = cp + 1;
- } else {
+ p = cp + 1;
+ } else if (taglen) {
size = et - bt;
if (strncmp(bt, cp, size)) {
// <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
@@ -571,67 +618,72 @@
&& !strncmp(bt, cp, size - 5)) {
const char *b = cp;
cp += size - 5;
+ taglen -= size - 5;
if (*cp == '.') {
- while (!isspace(*++cp) && (*cp != ':'));
+ while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e;
- for(e = cp; isspace(*cp); ++cp);
+ for(e = cp; taglen && isspace(*cp); ++cp, --taglen);
if (*cp == ':') {
tag = b;
etag = e;
- buf = cp + 1;
+ p = cp + 1;
}
}
} else {
- while (!isspace(*++cp) && (*cp != ':'));
+ while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e;
- for(e = cp; isspace(*cp); ++cp);
+ for(e = cp; taglen && isspace(*cp); ++cp, --taglen);
// Two words
if (*cp == ':') {
tag = bt;
etag = e;
- buf = cp + 1;
+ p = cp + 1;
}
}
} else if (isspace(cp[size])) {
cp += size;
- while (isspace(*++cp));
+ taglen -= size;
+ while (--taglen && isspace(*++cp));
// <PRI>[<TIME>] <tag> <tag> : message
if (*cp == ':') {
tag = bt;
etag = et;
- buf = cp + 1;
+ p = cp + 1;
}
} else if (cp[size] == ':') {
// <PRI>[<TIME>] <tag> <tag> : message
tag = bt;
etag = et;
- buf = cp + size + 1;
+ p = cp + size + 1;
} else if ((cp[size] == '.') || isdigit(cp[size])) {
// <PRI>[<TIME>] <tag> '<tag>.<num>' : message
// <PRI>[<TIME>] <tag> '<tag><num>' : message
const char *b = cp;
cp += size;
- while (!isspace(*++cp) && (*cp != ':'));
+ taglen -= size;
+ while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e = cp;
- while (isspace(*cp)) {
+ while (taglen && isspace(*cp)) {
++cp;
+ --taglen;
}
if (*cp == ':') {
tag = b;
etag = e;
- buf = cp + 1;
+ p = cp + 1;
}
} else {
- while (!isspace(*++cp) && (*cp != ':'));
+ while (--taglen && !isspace(*++cp) && (*cp != ':'));
const char *e = cp;
- while (isspace(*cp)) {
+ while (taglen && isspace(*cp)) {
++cp;
+ --taglen;
}
// Two words
if (*cp == ':') {
tag = bt;
etag = e;
- buf = cp + 1;
+ p = cp + 1;
}
}
}
@@ -643,16 +695,16 @@
|| ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2])))
// blacklist
|| ((size == 3) && !strncmp(tag, "CPU", 3))
- || ((size == 7) && !strncmp(tag, "WARNING", 7))
- || ((size == 5) && !strncmp(tag, "ERROR", 5))
- || ((size == 4) && !strncmp(tag, "INFO", 4))) {
- buf = start;
+ || ((size == 7) && !strncasecmp(tag, "WARNING", 7))
+ || ((size == 5) && !strncasecmp(tag, "ERROR", 5))
+ || ((size == 4) && !strncasecmp(tag, "INFO", 4))) {
+ p = start;
etag = tag = "";
}
}
// Suppress additional stutter in tag:
// eg: [143:healthd]healthd -> [143:healthd]
- size_t taglen = etag - tag;
+ taglen = etag - tag;
// Mediatek-special printk induced stutter
const char *mp = strnrchr(tag, ']', taglen);
if (mp && (++mp < etag)) {
@@ -662,17 +714,17 @@
}
}
// skip leading space
- while (isspace(*buf)) {
- ++buf;
+ while ((isspace(*p) || !*p) && (p < &buf[len])) {
+ ++p;
}
- // truncate trailing space
- size_t b = strlen(buf);
- while (b && isspace(buf[b-1])) {
+ // truncate trailing space or nuls
+ size_t b = len - (p - buf);
+ while (b && (isspace(p[b-1]) || !p[b-1])) {
--b;
}
// trick ... allow tag with empty content to be logged. log() drops empty
if (!b && taglen) {
- buf = " ";
+ p = " ";
b = 1;
}
size_t n = 1 + taglen + 1 + b + 1;
@@ -695,13 +747,13 @@
++np;
// Copy parsed tag following priority
- strncpy(np, tag, taglen);
+ memcpy(np, tag, taglen);
np += taglen;
*np = '\0';
++np;
// Copy main message to the remainder
- strncpy(np, buf, b);
+ memcpy(np, p, b);
np[b] = '\0';
// Log message