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

5 files changed, 147 insertions, 94 deletions

diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp
index 4b3547c..7db17d1 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 f977be9..2342822 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 0965ffd..4064de1 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -77,6 +77,8 @@ static char *is_timestamp(char *s) {
 // 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
@@ -222,7 +224,7 @@ bool LogKlog::onDataAvailable(SocketClient *cli) {
                 break;
             }
             if (*tok) {
-                log(tok);
+                log(tok, sublen);
             }
         }
     }
@@ -232,9 +234,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.
@@ -253,41 +257,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) {
@@ -304,8 +346,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;
@@ -316,20 +358,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;
@@ -342,15 +385,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;
         }
@@ -362,12 +405,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;
     }
@@ -379,9 +422,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
@@ -457,19 +500,20 @@ static const char *strnrchr(const char *s, size_t len, char c) {
 //  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()) {
@@ -488,7 +532,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;
 
@@ -496,40 +540,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)) {
             // <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
@@ -537,67 +584,72 @@ int LogKlog::log(const char *buf) {
                         && !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;
                 }
             }
         }
@@ -609,16 +661,16 @@ int LogKlog::log(const char *buf) {
                 || ((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)) {
@@ -628,17 +680,17 @@ int LogKlog::log(const char *buf) {
         }
     }
     // 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;
@@ -661,13 +713,13 @@ int LogKlog::log(const char *buf) {
     ++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
diff --git a/logd/LogKlog.h b/logd/LogKlog.h
index 7e4fde0..d1a248e 100644
--- a/logd/LogKlog.h
+++ b/logd/LogKlog.h
@@ -40,15 +40,16 @@ class LogKlog : public SocketListener {
 
 public:
     LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd);
-    int log(const char *buf);
-    void synchronize(const char *buf);
+    int log(const char *buf, size_t len);
+    void synchronize(const char *buf, size_t len);
 
     static void convertMonotonicToReal(log_time &real) { real += correction; }
 
 protected:
-    void sniffTime(log_time &now, const char **buf, bool reverse);
-    pid_t sniffPid(const char *buf);
-    void calculateCorrection(const log_time &monotonic, const char *real_string);
+    void sniffTime(log_time &now, const char **buf, size_t len, bool reverse);
+    pid_t sniffPid(const char *buf, size_t len);
+    void calculateCorrection(const log_time &monotonic,
+                             const char *real_string, size_t len);
     virtual bool onDataAvailable(SocketClient *cli);
 
 };
diff --git a/logd/main.cpp b/logd/main.cpp
index a3241d0..e6ccac9 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -305,17 +305,17 @@ static void readDmesg(LogAudit *al, LogKlog *kl) {
     buf[len - 1] = '\0';
 
     if (kl) {
-        kl->synchronize(buf.get());
+        kl->synchronize(buf.get(), len);
     }
 
     for (char *ptr = NULL, *tok = buf.get();
          (rc >= 0) && ((tok = log_strtok_r(tok, &ptr)));
          tok = NULL) {
         if (al) {
-            rc = al->log(tok);
+            rc = al->log(tok, sublen);
         }
         if (kl) {
-            rc = kl->log(tok);
+            rc = kl->log(tok, sublen);
         }
     }
 }