logd: multiple identical do not report expired

Report multiple identical chatty messages differently than for
regular expire chatty messages.  Multiple identical will
report identical count, while spam filter will report
expire count.

This should reduce the expected flood of people confused
but chatty messages in continuous logcat output.

Test: gTest logd_unit_tests --gtest_filter=logd.multiple*
Change-Id: Iad93d3efc6a3938a4b87ccadddbd86626a015d44

logd/LogBuffer.cpp

@@ -1100,6 +1100,10 @@ uint64_t LogBuffer::flushTo(
         }
     }
 
+    // Help detect if the valid message before is from the same source so
+    // we can differentiate chatty filter types.
+    pid_t lastTid[LOG_ID_MAX] = { 0 };
+
     for (; it != mLogElements.end(); ++it) {
         LogBufferElement *element = *it;
 
@@ -1126,10 +1130,19 @@ uint64_t LogBuffer::flushTo(
             }
         }
 
+        bool sameTid = lastTid[element->getLogId()] == element->getTid();
+        // Dropped (chatty) immediately following a valid log from the
+        // same source in the same log buffer indicates we have a
+        // multiple identical squash.  chatty that differs source
+        // is due to spam filter.  chatty to chatty of different
+        // source is also due to spam filter.
+        lastTid[element->getLogId()] = (element->getDropped() && !sameTid) ?
+                0 : element->getTid();
+
         pthread_mutex_unlock(&mLogElementsLock);
 
         // range locking in LastLogTimes looks after us
-        max = element->flushTo(reader, this, privileged);
+        max = element->flushTo(reader, this, privileged, sameTid);
 
         if (max == element->FLUSH_ERROR) {
             return max;

logd/LogBufferElement.cpp

@@ -113,8 +113,8 @@ char *android::tidToName(pid_t tid) {
 }
 
 // assumption: mMsg == NULL
-size_t LogBufferElement::populateDroppedMessage(char *&buffer,
-        LogBuffer *parent) {
+size_t LogBufferElement::populateDroppedMessage(char*& buffer,
+        LogBuffer* parent, bool lastSame) {
     static const char tag[] = "chatty";
 
     if (!__android_log_is_loggable_len(ANDROID_LOG_INFO,
@@ -123,7 +123,7 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
         return 0;
     }
 
-    static const char format_uid[] = "uid=%u%s%s expire %u line%s";
+    static const char format_uid[] = "uid=%u%s%s %s %u line%s";
     parent->lock();
     const char *name = parent->uidToName(mUid);
     parent->unlock();
@@ -165,8 +165,9 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
         }
     }
     // identical to below to calculate the buffer size required
+    const char* type = lastSame ? "identical" : "expire";
     size_t len = snprintf(NULL, 0, format_uid, mUid, name ? name : "",
-                          commName ? commName : "",
+                          commName ? commName : "", type,
                           mDropped, (mDropped > 1) ? "s" : "");
 
     size_t hdrLen;
@@ -198,7 +199,7 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
     }
 
     snprintf(buffer + hdrLen, len + 1, format_uid, mUid, name ? name : "",
-             commName ? commName : "",
+             commName ? commName : "", type,
              mDropped, (mDropped > 1) ? "s" : "");
     free(const_cast<char *>(name));
     free(const_cast<char *>(commName));
@@ -206,8 +207,8 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
     return retval;
 }
 
-uint64_t LogBufferElement::flushTo(SocketClient *reader, LogBuffer *parent,
-                                   bool privileged) {
+uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
+                                   bool privileged, bool lastSame) {
     struct logger_entry_v4 entry;
 
     memset(&entry, 0, sizeof(struct logger_entry_v4));
@@ -229,7 +230,7 @@ uint64_t LogBufferElement::flushTo(SocketClient *reader, LogBuffer *parent,
     char *buffer = NULL;
 
     if (!mMsg) {
-        entry.len = populateDroppedMessage(buffer, parent);
+        entry.len = populateDroppedMessage(buffer, parent, lastSame);
         if (!entry.len) {
             return mSequence;
         }

logd/LogBufferElement.h

@@ -53,8 +53,9 @@ class LogBufferElement {
     static atomic_int_fast64_t sequence;
 
     // assumption: mMsg == NULL
-    size_t populateDroppedMessage(char *&buffer,
-                                  LogBuffer *parent);
+    size_t populateDroppedMessage(char*& buffer,
+                                  LogBuffer* parent,
+                                  bool lastSame);
 public:
     LogBufferElement(log_id_t log_id, log_time realtime,
                      uid_t uid, pid_t pid, pid_t tid,
@@ -86,7 +87,8 @@ public:
     log_time getRealTime(void) const { return mRealTime; }
 
     static const uint64_t FLUSH_ERROR;
-    uint64_t flushTo(SocketClient *writer, LogBuffer *parent, bool privileged);
+    uint64_t flushTo(SocketClient* writer, LogBuffer* parent,
+                     bool privileged, bool lastSame);
 };
 
 #endif

logd/tests/logd_test.cpp

@@ -853,11 +853,13 @@ void __android_log_btwrite_multiple__helper(int count) {
 
     int expected_count = (count < 2) ? count : 2;
     int expected_chatty_count = (count <= 2) ? 0 : 1;
-    int expected_expire_count = (count < 2) ? 0 : (count - 2);
+    int expected_identical_count = (count < 2) ? 0 : (count - 2);
+    static const int expected_expire_count = 0;
 
     count = 0;
     int second_count = 0;
     int chatty_count = 0;
+    int identical_count = 0;
     int expire_count = 0;
 
     for (;;) {
@@ -887,11 +889,16 @@ void __android_log_btwrite_multiple__helper(int count) {
             ++chatty_count;
             // int len = get4LE(eventData + 4 + 1);
             log_msg.buf[LOGGER_ENTRY_MAX_LEN] = '\0';
-            const char *cp = strstr(eventData + 4 + 1 + 4, " expire ");
-            if (!cp) continue;
-            unsigned val = 0;
-            sscanf(cp, " expire %u lines", &val);
-            expire_count += val;
+            const char *cp;
+            if ((cp = strstr(eventData + 4 + 1 + 4, " identical "))) {
+                unsigned val = 0;
+                sscanf(cp, " identical %u lines", &val);
+                identical_count += val;
+            } else if ((cp = strstr(eventData + 4 + 1 + 4, " expire "))) {
+                unsigned val = 0;
+                sscanf(cp, " expire %u lines", &val);
+                expire_count += val;
+            }
         }
     }
 
@@ -900,6 +907,7 @@ void __android_log_btwrite_multiple__helper(int count) {
     EXPECT_EQ(expected_count, count);
     EXPECT_EQ(1, second_count);
     EXPECT_EQ(expected_chatty_count, chatty_count);
+    EXPECT_EQ(expected_identical_count, identical_count);
     EXPECT_EQ(expected_expire_count, expire_count);
 }