logd: annotate worst-UID pruned entries

- internal dropped entries are associated by prune by worst UID
  and are applied by UID and by PID
- track dropped entries by rewriting them in place
- merge similar dropped entries together for same UID(implied),
  PID and TID so that blame can more clearly be placed
- allow aging of dropped entries by the general backgound pruning
- report individual dropped entries formatted to reader
- add statistics to track dropped entries by UID, the combination
  of statistics and dropped logging can track over-the-top Chattiest
  clients.

Bug: 19608965
Change-Id: Ibc68480df0c69c55703270cd70c6b26aea165853

logd/Android.mk

@@ -32,8 +32,9 @@ LOCAL_SHARED_LIBRARIES := \
 #        "s/^\([0-9]*\)[ \t]*$1[ \t].*/-D`echo $1 | tr a-z A-Z`_LOG_TAG=\1/p" \
 #        $(LOCAL_PATH)/$2/event.logtags)
 #  event_flag := $(call event_logtags,auditd)
+#  event_flag += $(call event_logtags,logd)
 # so make sure we do not regret hard-coding it as follows:
-event_flag := -DAUDITD_LOG_TAG=1003
+event_flag := -DAUDITD_LOG_TAG=1003 -DLOGD_LOG_TAG=1004
 
 LOCAL_CFLAGS := -Werror $(event_flag)
 

logd/LogBuffer.cpp

@@ -297,6 +297,8 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         }
 
         bool kick = false;
+        bool leading = true;
+        LogBufferElement *last = NULL;
         for(it = mLogElements.begin(); it != mLogElements.end();) {
             LogBufferElement *e = *it;
 
@@ -309,26 +311,87 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 continue;
             }
 
-            uid_t uid = e->getUid();
+            unsigned short dropped = e->getDropped();
 
-            // !Worst and !BlackListed?
-            if ((uid != worst) && (!hasBlacklist || !mPrune.naughty(e))) {
+            // remove any leading drops
+            if (leading && dropped) {
+                it = erase(it);
+                continue;
+            }
+
+            pid_t pid = e->getPid();
+
+            // merge any drops
+            if (last && dropped
+             && ((dropped + last->getDropped()) < USHRT_MAX)
+             && (last->getPid() == pid)
+             && (last->getTid() == e->getTid())) {
+                it = mLogElements.erase(it);
+                stats.erase(e);
+                delete e;
+                last->setDropped(dropped + last->getDropped());
+                continue;
+            }
+
+            leading = false;
+
+            if (hasBlacklist && mPrune.naughty(e)) {
+                last = NULL;
+                it = erase(it);
+                if (dropped) {
+                    continue;
+                }
+
+                pruneRows--;
+                if (pruneRows == 0) {
+                    break;
+                }
+
+                if (e->getUid() == worst) {
+                    kick = true;
+                    if (worst_sizes < second_worst_sizes) {
+                        break;
+                    }
+                    worst_sizes -= e->getMsgLen();
+                }
+                continue;
+            }
+
+            if (dropped) {
+                last = e;
+                ++it;
+                continue;
+            }
+
+            if (e->getUid() != worst) {
+                last = NULL;
                 ++it;
                 continue;
             }
 
-            unsigned short len = e->getMsgLen();
-            it = erase(it);
             pruneRows--;
             if (pruneRows == 0) {
                 break;
             }
 
-            if (uid != worst) {
-                continue;
-            }
-
             kick = true;
+
+            unsigned short len = e->getMsgLen();
+            stats.drop(e);
+            e->setDropped(1);
+            // merge any drops
+            if (last
+             && (last->getDropped() < (USHRT_MAX - 1))
+             && (last->getPid() == pid)
+             && (last->getTid() == e->getTid())) {
+                it = mLogElements.erase(it);
+                stats.erase(e);
+                delete e;
+                last->setDropped(last->getDropped() + 1);
+            } else {
+                last = e;
+                ++it;
+            }
             if (worst_sizes < second_worst_sizes) {
                 break;
             }

logd/LogBufferElement.cpp

@@ -14,14 +14,17 @@
  * limitations under the License.
  */
 
+#include <endian.h>
 #include <stdio.h>
 #include <string.h>
 #include <time.h>
 #include <unistd.h>
 
 #include <log/logger.h>
+#include <private/android_logger.h>
 
 #include "LogBufferElement.h"
+#include "LogCommand.h"
 #include "LogReader.h"
 
 const uint64_t LogBufferElement::FLUSH_ERROR(0);
@@ -45,11 +48,59 @@ LogBufferElement::~LogBufferElement() {
     delete [] mMsg;
 }
 
+// assumption: mMsg == NULL
+size_t LogBufferElement::populateDroppedMessage(char *&buffer, bool privileged) {
+    static const char format_uid[] = "uid=%u dropped=%u";
+    static const size_t unprivileged_offset = 7;
+    static const char tag[] = "logd";
+
+    size_t len;
+    if (privileged) {
+        len = snprintf(NULL, 0, format_uid, mUid, mDropped);
+    } else {
+        len = snprintf(NULL, 0, format_uid + unprivileged_offset, mDropped);
+    }
+
+    size_t hdrLen;
+    if (mLogId == LOG_ID_EVENTS) {
+        hdrLen = sizeof(android_log_event_string_t);
+    } else {
+        hdrLen = 1 + sizeof(tag);
+    }
+
+    buffer = static_cast<char *>(calloc(1, hdrLen + len + 1));
+    if (!buffer) {
+        return 0;
+    }
+
+    size_t retval = hdrLen + len;
+    if (mLogId == LOG_ID_EVENTS) {
+        android_log_event_string_t *e = reinterpret_cast<android_log_event_string_t *>(buffer);
+
+        e->header.tag = htole32(LOGD_LOG_TAG);
+        e->type = EVENT_TYPE_STRING;
+        e->length = htole32(len);
+    } else {
+        ++retval;
+        buffer[0] = ANDROID_LOG_INFO;
+        strcpy(buffer + 1, tag);
+    }
+
+    if (privileged) {
+        snprintf(buffer + hdrLen, len + 1, format_uid, mUid, mDropped);
+    } else {
+        snprintf(buffer + hdrLen, len + 1, format_uid + unprivileged_offset, mDropped);
+    }
+
+    return retval;
+}
+
 uint64_t LogBufferElement::flushTo(SocketClient *reader) {
     struct logger_entry_v3 entry;
+
     memset(&entry, 0, sizeof(struct logger_entry_v3));
+
     entry.hdr_size = sizeof(struct logger_entry_v3);
-    entry.len = mMsgLen;
     entry.lid = mLogId;
     entry.pid = mPid;
     entry.tid = mTid;
@@ -59,11 +110,26 @@ uint64_t LogBufferElement::flushTo(SocketClient *reader) {
     struct iovec iovec[2];
     iovec[0].iov_base = &entry;
     iovec[0].iov_len = sizeof(struct logger_entry_v3);
-    iovec[1].iov_base = mMsg;
-    iovec[1].iov_len = mMsgLen;
-    if (reader->sendDatav(iovec, 2)) {
-        return FLUSH_ERROR;
+
+    char *buffer = NULL;
+
+    if (!mMsg) {
+        entry.len = populateDroppedMessage(buffer, clientHasLogCredentials(reader));
+        if (!entry.len) {
+            return mSequence;
+        }
+        iovec[1].iov_base = buffer;
+    } else {
+        entry.len = mMsgLen;
+        iovec[1].iov_base = mMsg;
+    }
+    iovec[1].iov_len = entry.len;
+
+    uint64_t retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mSequence;
+
+    if (buffer) {
+        free(buffer);
     }
 
-    return mSequence;
+    return retval;
 }

logd/LogBufferElement.h

@@ -18,6 +18,7 @@
 #define _LOGD_LOG_BUFFER_ELEMENT_H__
 
 #include <stdatomic.h>
+#include <stdlib.h>
 #include <sys/types.h>
 
 #include <sysutils/SocketClient.h>
@@ -38,11 +39,17 @@ class LogBufferElement {
     const pid_t mPid;
     const pid_t mTid;
     char *mMsg;
-    const unsigned short mMsgLen;
+    union {
+        const unsigned short mMsgLen; // mMSg != NULL
+        unsigned short mDropped;      // mMsg == NULL
+    };
     const uint64_t mSequence;
     const log_time mRealTime;
     static atomic_int_fast64_t sequence;
 
+    // assumption: mMsg == NULL
+    size_t populateDroppedMessage(char *&buffer, bool privileged);
+
 public:
     LogBufferElement(log_id_t log_id, log_time realtime,
                      uid_t uid, pid_t pid, pid_t tid,
@@ -53,7 +60,15 @@ class LogBufferElement {
     uid_t getUid(void) const { return mUid; }
     pid_t getPid(void) const { return mPid; }
     pid_t getTid(void) const { return mTid; }
-    unsigned short getMsgLen() const { return mMsgLen; }
+    unsigned short getDropped(void) const { return mMsg ? 0 : mDropped; }
+    unsigned short setDropped(unsigned short value) {
+        if (mMsg) {
+            free(mMsg);
+            mMsg = NULL;
+        }
+        return mDropped = value;
+    }
+    unsigned short getMsgLen() const { return mMsg ? mMsgLen : 0; }
     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; }