logd: record multiple duplicate messages as chatty

If a series of messages arrive from a single source with identical
message content payload, then suppress them and generate a chatty
report.  The checking is done on a per log id basis.

This alters the assumption that chatty messages are always at the
oldest entries, they now show up in the middle too.  To address this
change in behavior we print the first line, a chatty reference
which internally takes little space, then the last line in the series.

This does not conserve processing time in logd, and certainly has no
impact on the long path of formatting and submitting log messages from
from the source, but it may contribute to memory space and signal to
noise savings under heavy spammy loads.

Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Bug: 33535908
Change-Id: I3160c36d4f4e2f8216f528605a1b3993173f4dec

10 files changed, 262 insertions, 42 deletions

diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp
index c3ccd840a..aa05932b0 100644
--- a/logd/LogAudit.cpp
+++ b/logd/LogAudit.cpp
@@ -34,6 +34,7 @@
 #include "LogBuffer.h"
 #include "LogKlog.h"
 #include "LogReader.h"
+#include "LogUtils.h"
 
 #define KMSG_PRIORITY(PRI)                          \
     '<',                                            \
@@ -117,7 +118,8 @@ int LogAudit::logPrint(const char *fmt, ...) {
             if (avcl) {
                 char *avcr = strstr(str, avc);
 
-                skip = avcr && !strcmp(avcl + strlen(avc), avcr + strlen(avc));
+                skip = avcr && !fastcmp<strcmp>(avcl + strlen(avc),
+                                                avcr + strlen(avc));
                 if (skip) {
                     ++count;
                     free(last_str);
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index a00943309..d4765964d 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -33,6 +33,7 @@
 #include "LogBuffer.h"
 #include "LogKlog.h"
 #include "LogReader.h"
+#include "LogUtils.h"
 
 #ifndef __predict_false
 #define __predict_false(exp) __builtin_expect((exp) != 0, 0)
@@ -110,9 +111,65 @@ LogBuffer::LogBuffer(LastLogTimes *times):
         mTimes(*times) {
     pthread_mutex_init(&mLogElementsLock, NULL);
 
+    log_id_for_each(i) {
+        lastLoggedElements[i] = NULL;
+        droppedElements[i] = NULL;
+    }
+
     init();
 }
 
+LogBuffer::~LogBuffer() {
+    log_id_for_each(i) {
+        delete lastLoggedElements[i];
+        delete droppedElements[i];
+    }
+}
+
+static bool identical(LogBufferElement* elem, LogBufferElement* last) {
+    // is it mostly identical?
+//  if (!elem) return false;
+    unsigned short lenl = elem->getMsgLen();
+    if (!lenl) return false;
+//  if (!last) return false;
+    unsigned short lenr = last->getMsgLen();
+    if (!lenr) return false;
+//  if (elem->getLogId() != last->getLogId()) return false;
+    if (elem->getUid() != last->getUid()) return false;
+    if (elem->getPid() != last->getPid()) return false;
+    if (elem->getTid() != last->getTid()) return false;
+
+    // last is more than a minute old, stop squashing identical messages
+    if (elem->getRealTime().nsec() >
+        (last->getRealTime().nsec() + 60 * NS_PER_SEC)) return false;
+
+    // Identical message
+    const char* msgl = elem->getMsg();
+    const char* msgr = last->getMsg();
+    if ((lenl == lenr) && !fastcmp<memcmp>(msgl, msgr, lenl)) return true;
+
+    // audit message (except sequence number) identical?
+    static const char avc[] = "): avc: ";
+
+    if (last->isBinary()) {
+        if (fastcmp<memcmp>(msgl, msgr,
+                            sizeof(android_log_event_string_t) -
+                                sizeof(int32_t))) return false;
+        msgl += sizeof(android_log_event_string_t);
+        lenl -= sizeof(android_log_event_string_t);
+        msgr += sizeof(android_log_event_string_t);
+        lenr -= sizeof(android_log_event_string_t);
+    }
+    const char *avcl = android::strnstr(msgl, lenl, avc);
+    if (!avcl) return false;
+    lenl -= avcl - msgl;
+    const char *avcr = android::strnstr(msgr, lenr, avc);
+    if (!avcr) return false;
+    lenr -= avcr - msgr;
+    if (lenl != lenr) return false;
+    return !fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), lenl);
+}
+
 int LogBuffer::log(log_id_t log_id, log_time realtime,
                    uid_t uid, pid_t pid, pid_t tid,
                    const char *msg, unsigned short len) {
@@ -145,14 +202,57 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
     }
 
     pthread_mutex_lock(&mLogElementsLock);
+    LogBufferElement* currentLast = lastLoggedElements[log_id];
+    if (currentLast) {
+        LogBufferElement *dropped = droppedElements[log_id];
+        unsigned short count = dropped ? dropped->getDropped() : 0;
+        if (identical(elem, currentLast)) {
+            if (dropped) {
+                if (count == USHRT_MAX) {
+                    log(dropped);
+                    count = 1;
+                } else {
+                    delete dropped;
+                    ++count;
+                }
+            }
+            if (count) {
+                stats.add(currentLast);
+                stats.subtract(currentLast);
+                currentLast->setDropped(count);
+            }
+            droppedElements[log_id] = currentLast;
+            lastLoggedElements[log_id] = elem;
+            pthread_mutex_unlock(&mLogElementsLock);
+            return len;
+        }
+        if (dropped) {
+            log(dropped);
+            droppedElements[log_id] = NULL;
+        }
+        if (count) {
+            log(currentLast);
+        } else {
+            delete currentLast;
+        }
+    }
+    lastLoggedElements[log_id] = new LogBufferElement(*elem);
+
+    log(elem);
+    pthread_mutex_unlock(&mLogElementsLock);
+
+    return len;
+}
 
+// assumes mLogElementsLock held, owns elem, will look after garbage collection
+void LogBuffer::log(LogBufferElement* elem) {
     // Insert elements in time sorted order if possible
     //  NB: if end is region locked, place element at end of list
     LogBufferElementCollection::iterator it = mLogElements.end();
     LogBufferElementCollection::iterator last = it;
     while (last != mLogElements.begin()) {
         --it;
-        if ((*it)->getRealTime() <= realtime) {
+        if ((*it)->getRealTime() <= elem->getRealTime()) {
             break;
         }
         last = it;
@@ -169,7 +269,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
 
         LastLogTimes::iterator times = mTimes.begin();
         while(times != mTimes.end()) {
-            LogTimeEntry *entry = (*times);
+            LogTimeEntry* entry = (*times);
             if (entry->owned_Locked()) {
                 if (!entry->mNonBlock) {
                     end_always = true;
@@ -187,17 +287,14 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
                 || (end_set && (end >= (*last)->getSequence()))) {
             mLogElements.push_back(elem);
         } else {
-            mLogElements.insert(last,elem);
+            mLogElements.insert(last, elem);
         }
 
         LogTimeEntry::unlock();
     }
 
     stats.add(elem);
-    maybePrune(log_id);
-    pthread_mutex_unlock(&mLogElementsLock);
-
-    return len;
+    maybePrune(elem->getLogId());
 }
 
 // Prune at most 10% of the log entries or maxPrune, whichever is less.
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index ff9692e05..932d55f9a 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -99,10 +99,15 @@ class LogBuffer {
 
     bool monotonic;
 
+    LogBufferElement* lastLoggedElements[LOG_ID_MAX];
+    LogBufferElement* droppedElements[LOG_ID_MAX];
+    void log(LogBufferElement* elem);
+
 public:
     LastLogTimes &mTimes;
 
     explicit LogBuffer(LastLogTimes *times);
+    ~LogBuffer();
     void init();
     bool isMonotonic() { return monotonic; }
 
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index ec91f2a83..5e37a30e8 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -50,6 +50,19 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
         0;
 }
 
+LogBufferElement::LogBufferElement(const LogBufferElement &elem) :
+        mTag(elem.mTag),
+        mUid(elem.mUid),
+        mPid(elem.mPid),
+        mTid(elem.mTid),
+        mSequence(elem.mSequence),
+        mRealTime(elem.mRealTime),
+        mMsgLen(elem.mMsgLen),
+        mLogId(elem.mLogId) {
+    mMsg = new char[mMsgLen];
+    memcpy(mMsg, elem.mMsg, mMsgLen);
+}
+
 LogBufferElement::~LogBufferElement() {
     delete [] mMsg;
 }
@@ -157,8 +170,6 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
                           mDropped, (mDropped > 1) ? "s" : "");
 
     size_t hdrLen;
-    // LOG_ID_SECURITY not strictly needed since spam filter not activated,
-    // but required for accuracy.
     if (isBinary()) {
         hdrLen = sizeof(android_log_event_string_t);
     } else {
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index fb7fbed5c..f8ffacd7e 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -59,6 +59,7 @@ public:
     LogBufferElement(log_id_t log_id, log_time realtime,
                      uid_t uid, pid_t pid, pid_t tid,
                      const char *msg, unsigned short len);
+    LogBufferElement(const LogBufferElement &elem);
     virtual ~LogBufferElement();
 
     bool isBinary(void) const {
@@ -79,6 +80,7 @@ public:
         return mDropped = value;
     }
     unsigned short getMsgLen() const { return mMsg ? mMsgLen : 0; }
+    const char* getMsg() const { return mMsg; }
     uint64_t getSequence(void) const { return mSequence; }
     static uint64_t getCurrentSequence(void) { return sequence.load(memory_order_relaxed); }
     log_time getRealTime(void) const { return mRealTime; }
diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index 0b49fc1b3..f22407929 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -306,19 +306,15 @@ static const char suspendStr[] = "PM: suspend entry ";
 static const char resumeStr[] = "PM: suspend exit ";
 static const char suspendedStr[] = "Suspended for ";
 
-static const char *strnstr(const char *s, size_t len, const char *needle) {
+const char* android::strnstr(const char* s, size_t len, const char* needle) {
     char c;
 
-    if (!len) {
-        return NULL;
-    }
+    if (!len) return NULL;
     if ((c = *needle++) != 0) {
         size_t needleLen = strlen(needle);
         do {
             do {
-                if (len <= needleLen) {
-                    return NULL;
-                }
+                if (len <= needleLen) return NULL;
                 --len;
             } while (*s++ != c);
         } while (fastcmp<memcmp>(s, needle, needleLen));
@@ -349,25 +345,25 @@ void LogKlog::sniffTime(log_time &now,
             return;
         }
 
-        const char *b;
-        if (((b = strnstr(cp, len, suspendStr)))
+        const char* b;
+        if (((b = android::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)))
+        } else if (((b = android::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)))
+        } else if (((b = android::strnstr(cp, len, healthd)))
                 && ((size_t)((b += sizeof(healthd) - 1) - cp) < len)
-                && ((b = strnstr(b, len -= b - cp, battery)))
+                && ((b = android::strnstr(b, len -= b - cp, battery)))
                 && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) {
             // NB: healthd is roughly 150us late, so we use it instead to
             //     trigger a check for ntp-induced or hardware clock drift.
             log_time real(CLOCK_REALTIME);
             log_time mono(CLOCK_MONOTONIC);
             correction = (real < mono) ? log_time::EPOCH : (real - mono);
-        } else if (((b = strnstr(cp, len, suspendedStr)))
+        } else if (((b = android::strnstr(cp, len, suspendedStr)))
                 && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
             len -= b - cp;
             log_time real;
@@ -466,18 +462,14 @@ static int parseKernelPrio(const char **buf, size_t len) {
 
 // Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
 // compensated start time.
-void LogKlog::synchronize(const char *buf, size_t len) {
-    const char *cp = strnstr(buf, len, suspendStr);
+void LogKlog::synchronize(const char* buf, size_t len) {
+    const char* cp = android::strnstr(buf, len, suspendStr);
     if (!cp) {
-        cp = strnstr(buf, len, resumeStr);
-        if (!cp) {
-            return;
-        }
+        cp = android::strnstr(buf, len, resumeStr);
+        if (!cp) return;
     } else {
-        const char *rp = strnstr(buf, len, resumeStr);
-        if (rp && (rp < cp)) {
-            cp = rp;
-        }
+        const char* rp = android::strnstr(buf, len, resumeStr);
+        if (rp && (rp < cp)) cp = rp;
     }
 
     do {
@@ -491,7 +483,7 @@ void LogKlog::synchronize(const char *buf, size_t len) {
     log_time now;
     sniffTime(now, &cp, len - (cp - buf), true);
 
-    const char *suspended = strnstr(buf, len, suspendedStr);
+    const char* suspended = android::strnstr(buf, len, suspendedStr);
     if (!suspended || (suspended > cp)) {
         return;
     }
@@ -581,12 +573,12 @@ 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, size_t len) {
-    if (auditd && strnstr(buf, len, " audit(")) {
+int LogKlog::log(const char* buf, size_t len) {
+    if (auditd && android::strnstr(buf, len, " audit(")) {
         return 0;
     }
 
-    const char *p = buf;
+    const char* p = buf;
     int pri = parseKernelPrio(&p, len);
 
     log_time now;
@@ -594,7 +586,7 @@ int LogKlog::log(const char *buf, size_t len) {
 
     // sniff for start marker
     const char klogd_message[] = "logd.klogd: ";
-    const char *start = strnstr(p, len - (p - buf), klogd_message);
+    const char* start = android::strnstr(p, len - (p - buf), klogd_message);
     if (start) {
         uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10);
         if (sig == signature.nsec()) {
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 3c8bd7517..ddbb64fb1 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -71,8 +71,17 @@ void LogStatistics::add(LogBufferElement *element) {
     mSizes[log_id] += size;
     ++mElements[log_id];
 
-    mSizesTotal[log_id] += size;
-    ++mElementsTotal[log_id];
+    if (element->getDropped()) {
+        ++mDroppedElements[log_id];
+    } else {
+        // When caller adding a chatty entry, they will have already
+        // called add() and subtract() for each entry as they are
+        // evaluated and trimmed, thus recording size and number of
+        // elements, but we must recognize the manufactured dropped
+        // entry as not contributing to the lifetime totals.
+        mSizesTotal[log_id] += size;
+        ++mElementsTotal[log_id];
+    }
 
     if (log_id == LOG_ID_KERNEL) {
         return;
diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h
index cb7ae2b69..8bf655b01 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -265,7 +265,7 @@ struct UidEntry : public EntryBaseDropped {
         if (pid != element->getPid()) {
             pid = -1;
         }
-        EntryBase::add(element);
+        EntryBaseDropped::add(element);
     }
 
     std::string formatHeader(const std::string &name, log_id_t id) const;
@@ -419,7 +419,7 @@ struct TagEntry : public EntryBaseDropped {
         if (pid != element->getPid()) {
             pid = -1;
         }
-        EntryBase::add(element);
+        EntryBaseDropped::add(element);
     }
 
     std::string formatHeader(const std::string &name, log_id_t id) const;
diff --git a/logd/LogUtils.h b/logd/LogUtils.h
index ec6806225..d300a2a43 100644
--- a/logd/LogUtils.h
+++ b/logd/LogUtils.h
@@ -40,6 +40,9 @@ char *tidToName(pid_t tid);
 // Furnished in main.cpp. Thread safe.
 const char *tagToName(size_t *len, uint32_t tag);
 
+// Furnished by LogKlog.cpp.
+const char* strnstr(const char* s, size_t len, const char* needle);
+
 }
 
 // Furnished in LogCommand.cpp
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index 254a3f849..4e621e382 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -778,3 +778,102 @@ TEST(logd, SNDTIMEO) {
 
     close(fd);
 }
+
+static inline int32_t get4LE(const char* src)
+{
+    return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
+}
+
+void __android_log_btwrite_multiple__helper(int count) {
+    log_time ts(CLOCK_MONOTONIC);
+
+    struct logger_list *logger_list;
+    ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
+        LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, 0)));
+
+    log_time ts1(CLOCK_MONOTONIC);
+
+    pid_t pid = fork();
+
+    if (pid == 0) {
+        // child
+        for (int i = count; i; --i) {
+            ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
+            usleep(100);
+        }
+        ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
+        usleep(1000000);
+
+        _exit(0);
+    }
+
+    siginfo_t info{};
+    ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
+
+    int expected_count = (count < 2) ? count : 2;
+    int expected_chatty_count = (count <= 2) ? 0 : 1;
+    int expected_expire_count = (count < 2) ? 0 : (count - 2);
+
+    count = 0;
+    int second_count = 0;
+    int chatty_count = 0;
+    int expire_count = 0;
+
+    for (;;) {
+        log_msg log_msg;
+        if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
+
+        if ((log_msg.entry.pid != pid) ||
+            (log_msg.entry.len < (4 + 1 + 8)) ||
+            (log_msg.id() != LOG_ID_EVENTS)) continue;
+
+        char *eventData = log_msg.msg();
+        if (!eventData) continue;
+
+        uint32_t tag = get4LE(eventData);
+
+        if ((eventData[4] == EVENT_TYPE_LONG) && (log_msg.entry.len == (4 + 1 + 8))) {
+            if (tag != 0) continue;
+
+            log_time tx(eventData + 4 + 1);
+            if (ts == tx) {
+                ++count;
+            } else if (ts1 == tx) {
+                ++second_count;
+            }
+        } else if (eventData[4] == EVENT_TYPE_STRING) {
+            // chatty
+            if (tag != 1004) continue;
+            ++chatty_count;
+            // int len = get4LE(eventData + 4 + 1);
+            const char *cp = strstr(eventData + 4 + 1 + 4, " expire ");
+            if (!cp) continue;
+            unsigned val = 0;
+            sscanf(cp, " expire %u lines", &val);
+            expire_count += val;
+        }
+    }
+
+    EXPECT_EQ(expected_count, count);
+    EXPECT_EQ(1, second_count);
+    EXPECT_EQ(expected_chatty_count, chatty_count);
+    EXPECT_EQ(expected_expire_count, expire_count);
+
+    android_logger_list_close(logger_list);
+}
+
+TEST(logd, multiple_test_1) {
+    __android_log_btwrite_multiple__helper(1);
+}
+
+TEST(logd, multiple_test_2) {
+    __android_log_btwrite_multiple__helper(2);
+}
+
+TEST(logd, multiple_test_3) {
+    __android_log_btwrite_multiple__helper(3);
+}
+
+TEST(logd, multiple_test_10) {
+    __android_log_btwrite_multiple__helper(10);
+}