healthd: logd: add timestamp to kernel logged battery messages

(cherry pick from commit acb1ddf56c98a75a49b263f99ef07ce361dc4323)

Aid monotonic to realtime logging synchronization correction in
the Android ecosystem by providing a periodic notification.  We
now have the following messages in the kernel logs:

- PM: suspend entry %Y-%m-%d %H:%M:%S.%09q UTC
- PM: suspend exit %Y-%m-%d %H:%M:%S.%09q UTC
- Suspended for %s.%03q seconds
- healthd: battery l=100 ... %Y-%m-%d %H:%M:%S.%09q UTC

Alter klogd to resynchronize on healthd messages as well.

NB: Time using strftime format, %q is a reference to fractional
second as introduced into log_time strptime method.

Bug: 21868540
Change-Id: I854afc0a07dff9c7f26d2b2f68990e52bf90e300

2 files changed, 39 insertions, 5 deletions

diff --git a/healthd/BatteryMonitor.cpp b/healthd/BatteryMonitor.cpp
index c75ed13..1cad427 100644
--- a/healthd/BatteryMonitor.cpp
+++ b/healthd/BatteryMonitor.cpp
@@ -24,11 +24,13 @@
 #include <fcntl.h>
 #include <stdio.h>
 #include <stdlib.h>
+#include <sys/types.h>
 #include <unistd.h>
+
 #include <batteryservice/BatteryService.h>
 #include <cutils/klog.h>
 #include <cutils/properties.h>
-#include <sys/types.h>
+#include <log/log_read.h>
 #include <utils/Errors.h>
 #include <utils/String8.h>
 #include <utils/Vector.h>
@@ -275,10 +277,32 @@ bool BatteryMonitor::update(void) {
                  "battery none");
         }
 
-        KLOG_WARNING(LOG_TAG, "%s chg=%s%s%s\n", dmesgline,
-                     props.chargerAcOnline ? "a" : "",
-                     props.chargerUsbOnline ? "u" : "",
-                     props.chargerWirelessOnline ? "w" : "");
+        size_t len = strlen(dmesgline);
+        snprintf(dmesgline + len, sizeof(dmesgline) - len, " chg=%s%s%s",
+                 props.chargerAcOnline ? "a" : "",
+                 props.chargerUsbOnline ? "u" : "",
+                 props.chargerWirelessOnline ? "w" : "");
+
+        log_time realtime(CLOCK_REALTIME);
+        time_t t = realtime.tv_sec;
+        struct tm *tmp = gmtime(&t);
+        if (tmp) {
+            static const char fmt[] = " %Y-%m-%d %H:%M:%S.XXXXXXXXX UTC";
+            len = strlen(dmesgline);
+            if ((len < (sizeof(dmesgline) - sizeof(fmt) - 8)) // margin
+                    && strftime(dmesgline + len, sizeof(dmesgline) - len,
+                                fmt, tmp)) {
+                char *usec = strchr(dmesgline + len, 'X');
+                if (usec) {
+                    len = usec - dmesgline;
+                    snprintf(dmesgline + len, sizeof(dmesgline) - len,
+                             "%09u", realtime.tv_nsec);
+                    usec[9] = ' ';
+                }
+            }
+        }
+
+        KLOG_WARNING(LOG_TAG, "%s\n", dmesgline);
     }
 
     healthd_mode_ops->battery_update(&props);
diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index d3a73a1..39da87c 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -256,6 +256,7 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
     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 ";
 
         if (isspace(*cp)) {
@@ -265,6 +266,15 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
             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)) {
+            // look for " 2???-??-?? ??:??:??.????????? ???"
+            const char *tp;
+            for (tp = cp + sizeof(healthd) - 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)) {
             log_time real;
             char *endp;