From df5902c4f3eee1880fb97bb267e4e476a4e024c4 Mon Sep 17 00:00:00 2001
From: Mark Salyzyn <salyzyn@google.com>
Date: Fri, 22 May 2015 15:23:44 -0700
Subject: [PATCH] logd: fix kernel logline stutter

(cherry pick from commit 2c3b300fd8307e8da13608197d0a89bc613de5fb)

- look for cases where one log line contains two without a newline.
- rare condition, occurs when a printk does not have
  a terminating newline under certain race conditions.
- the newline may be performed broken up as a second call
- the timestamps can be reversed (showing the race effects).
- driver(s) should really have the newline in their log messages.

Change-Id: Ibfb56b32047da3d6513db059ca6edad0f0105168
---
 logd/LogKlog.cpp | 138 ++++++++++++++++++++++++++++++++++++++++++++++-
 logd/LogKlog.h   |   2 +
 logd/main.cpp    |   4 +-
 3 files changed, 140 insertions(+), 4 deletions(-)

diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index 8df0d0a84..062ffb28f 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -36,6 +36,140 @@
 
 static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
 
+// Parsing is hard
+
+// called if we see a '<', s is the next character, returns pointer after '>'
+static char *is_prio(char *s) {
+    if (!isdigit(*s++)) {
+        return NULL;
+    }
+    char c;
+    while ((c = *s++)) {
+        if (!isdigit(c) && (c == '>')) {
+            return s;
+        }
+    }
+    return NULL;
+}
+
+// called if we see a '[', s is the next character, returns pointer after ']'
+static char *is_timestamp(char *s) {
+    while (*s == ' ') {
+        ++s;
+    }
+    if (!isdigit(*s++)) {
+        return NULL;
+    }
+    bool first_period = true;
+    char c;
+    while ((c = *s++)) {
+        if ((c == '.') && first_period) {
+            first_period = false;
+            continue;
+        }
+        if (!isdigit(c) && (c == ']')) {
+            return s;
+        }
+    }
+    return NULL;
+}
+
+// Like strtok_r with "\r\n" except that we look for log signatures (regex)
+//   \(\(<[0-9]+>\)\([[] *[0-9]+[]]\)\{0,1\}\|[[] *[0-9]+[]]\)
+// and split if we see a second one without a newline.
+
+#define SIGNATURE_MASK     0xF0
+// <digit> following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature
+#define LESS_THAN_SIG      SIGNATURE_MASK
+#define OPEN_BRACKET_SIG   ((SIGNATURE_MASK << 1) & SIGNATURE_MASK)
+// space is one more than <digit> of 9
+#define OPEN_BRACKET_SPACE (OPEN_BRACKET_SIG | 10)
+
+char *log_strtok_r(char *s, char **last) {
+    if (!s) {
+        if (!(s = *last)) {
+            return NULL;
+        }
+        // fixup for log signature split <,
+        // LESS_THAN_SIG + <digit>
+        if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) {
+            *s = (*s & ~SIGNATURE_MASK) + '0';
+            *--s = '<';
+        }
+        // fixup for log signature split [,
+        // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + <digit>
+        if ((*s & SIGNATURE_MASK) == OPEN_BRACKET_SIG) {
+            if (*s == OPEN_BRACKET_SPACE) {
+                *s = ' ';
+            } else {
+                *s = (*s & ~SIGNATURE_MASK) + '0';
+            }
+            *--s = '[';
+        }
+    }
+
+    s += strspn(s, "\r\n");
+
+    if (!*s) { // no non-delimiter characters
+        *last = NULL;
+        return NULL;
+    }
+    char *peek, *tok = s;
+
+    for (;;) {
+        char c = *s++;
+        switch (c) {
+        case '\0':
+            *last = NULL;
+            return tok;
+
+        case '\r':
+        case '\n':
+            s[-1] = '\0';
+            *last = s;
+            return tok;
+
+        case '<':
+            peek = is_prio(s);
+            if (!peek) {
+                break;
+            }
+            if (s != (tok + 1)) { // not first?
+                s[-1] = '\0';
+                *s &= ~SIGNATURE_MASK;
+                *s |= LESS_THAN_SIG; // signature for '<'
+                *last = s;
+                return tok;
+            }
+            s = peek;
+            if ((*s == '[') && ((peek = is_timestamp(s + 1)))) {
+                s = peek;
+            }
+            break;
+
+        case '[':
+            peek = is_timestamp(s);
+            if (!peek) {
+                break;
+            }
+            if (s != (tok + 1)) { // not first?
+                s[-1] = '\0';
+                if (*s == ' ') {
+                    *s = OPEN_BRACKET_SPACE;
+                } else {
+                    *s &= ~SIGNATURE_MASK;
+                    *s |= OPEN_BRACKET_SIG; // signature for '['
+                }
+                *last = s;
+                return tok;
+            }
+            s = peek;
+            break;
+        }
+    }
+    /* NOTREACHED */
+}
+
 log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC);
 
 LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) :
@@ -81,8 +215,8 @@ bool LogKlog::onDataAvailable(SocketClient *cli) {
         char *ep = buffer + len;
         *ep = '\0';
         len = 0;
-        for(char *ptr, *tok = buffer;
-                ((tok = strtok_r(tok, "\r\n", &ptr)));
+        for(char *ptr = NULL, *tok = buffer;
+                ((tok = log_strtok_r(tok, &ptr)));
                 tok = NULL) {
             if (((tok + strlen(tok)) == ep) && (retval != 0) && full) {
                 len = strlen(tok);
diff --git a/logd/LogKlog.h b/logd/LogKlog.h
index 8de9c87ea..a898c63ae 100644
--- a/logd/LogKlog.h
+++ b/logd/LogKlog.h
@@ -21,6 +21,8 @@
 #include <log/log_read.h>
 #include "LogReader.h"
 
+char *log_strtok_r(char *str, char **saveptr);
+
 class LogKlog : public SocketListener {
     LogBuffer *logbuf;
     LogReader *reader;
diff --git a/logd/main.cpp b/logd/main.cpp
index 6db819e31..805cbe64b 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -417,8 +417,8 @@ int main(int argc, char *argv[]) {
                 kl->synchronize(buf);
             }
 
-            for (char *ptr, *tok = buf;
-                 (rc >= 0) && ((tok = strtok_r(tok, "\r\n", &ptr)));
+            for (char *ptr = NULL, *tok = buf;
+                 (rc >= 0) && ((tok = log_strtok_r(tok, &ptr)));
                  tok = NULL) {
                 if (al) {
                     rc = al->log(tok);