From 3f78f93302c737b454ea63bac0bb15553b953d01 Mon Sep 17 00:00:00 2001
From: Mark Salyzyn <salyzyn@google.com>
Date: Tue, 1 Sep 2015 13:09:23 -0700
Subject: [PATCH] logd: klogd: sniff for time correction on Mediatek

(cherry pick from commit 2d159bf3b597eb6defbb9e74c60a003bc9387a0a)

Need some more flexibility when parsing kernel messages
cluttered with extra fluff. This is the minimal relaxation
we can do to the rules to ensure that we work on all
possible devices and kernels when sniffing for time
correction information.

We want to minimize any future maintenance, keep in mind
klogd is a "userdebug" or "eng" feature and is disabled
in "user" builds. Manage expectations.

Bug: 23517551
Change-Id: I026d074e14fb2550e728683e85a973bd87e78a9c
---
 logd/LogKlog.cpp | 110 +++++++++++++++++++++++++++++------------------
 1 file changed, 68 insertions(+), 42 deletions(-)

diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index c6109f56e..0965ffd55 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -249,36 +249,47 @@ void LogKlog::calculateCorrection(const log_time &monotonic,
     correction = real - monotonic;
 }
 
+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 suspend[] = "PM: suspend entry ";
-        static const char resume[] = "PM: suspend exit ";
-        static const char healthd[] = "healthd: battery ";
-        static const char suspended[] = "Suspended for ";
+        static const char healthd[] = "healthd";
+        static const char battery[] = ": battery ";
 
         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, healthd, sizeof(healthd) - 1)) {
+        *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)))) {
+            // 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 = cp + sizeof(healthd) - 1; *tp && (*tp != '\n'); ++tp) {
+            for (tp = b + sizeof(battery) - 1; *tp && (*tp != '\n'); ++tp) {
                 if ((tp[0] == ' ') && (tp[1] == '2') && (tp[5] == '-')) {
                     calculateCorrection(now, tp + 1);
                     break;
                 }
             }
-        } else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) {
+        } else if ((b = strstr(cp, suspendedStr))) {
             log_time real;
             char *endp;
-            real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10);
+            real.tv_sec = strtol(b + sizeof(suspendedStr) - 1, &endp, 10);
             if (*endp == '.') {
-                real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L;
+                unsigned long multiplier = NS_PER_SEC;
+                real.tv_nsec = 0;
+                while (isdigit(*++endp) && (multiplier /= 10)) {
+                    real.tv_nsec += (*endp - '0') * multiplier;
+                }
                 if (reverse) {
                     correction -= real;
                 } else {
@@ -288,7 +299,6 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
         }
 
         convertMonotonicToReal(now);
-        *buf = cp;
     } else {
         now = log_time(CLOCK_REALTIME);
     }
@@ -310,34 +320,6 @@ pid_t LogKlog::sniffPid(const char *cp) {
     return 0;
 }
 
-// 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;
@@ -358,6 +340,50 @@ static int parseKernelPrio(const char **buf) {
     return pri;
 }
 
+// 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);
+    if (!cp) {
+        cp = strstr(buf, resumeStr);
+        if (!cp) {
+            return;
+        }
+    } else {
+        const char *rp = strstr(buf, resumeStr);
+        if (rp && (rp < cp)) {
+            cp = rp;
+        }
+    }
+
+    do {
+        --cp;
+    } while ((cp > buf) && (*cp != '\n'));
+    if (*cp == '\n') {
+        ++cp;
+    }
+    parseKernelPrio(&cp);
+
+    log_time now;
+    sniffTime(now, &cp, true);
+
+    char *suspended = strstr(buf, suspendedStr);
+    if (!suspended || (suspended > cp)) {
+        return;
+    }
+    cp = suspended;
+
+    do {
+        --cp;
+    } while ((cp > buf) && (*cp != '\n'));
+    if (*cp == '\n') {
+        ++cp;
+    }
+    parseKernelPrio(&cp);
+
+    sniffTime(now, &cp, true);
+}
+
 // Convert kernel log priority number into an Android Logger priority number
 static int convertKernelPrioToAndroidPrio(int pri) {
     switch(pri & LOG_PRIMASK) {