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

8 files changed, 261 insertions, 38 deletions

diff --git a/logd/Android.mk b/logd/Android.mk
index 127a66b31..e65e9ff79 100644
--- a/logd/Android.mk
+++ b/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)
 
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index a5844a35e..d8ffb02aa 100644
--- a/logd/LogBuffer.cpp
+++ b/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;
             }
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index 5e780b557..a173e63fe 100644
--- a/logd/LogBufferElement.cpp
+++ b/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;
 }
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index 93671da47..cc18378c6 100644
--- a/logd/LogBufferElement.h
+++ b/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 @@ public:
     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; }
diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp
index 3fbcfd6c3..e0b8fd882 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -71,16 +71,19 @@ void LogStatistics::add(LogBufferElement *e) {
     ++mElements[log_id];
 
     uid_t uid = e->getUid();
+    unsigned short dropped = e->getDropped();
     android::hash_t hash = android::hash_type(uid);
     uidTable_t &table = uidTable[log_id];
     ssize_t index = table.find(-1, hash, uid);
     if (index == -1) {
         UidEntry initEntry(uid);
         initEntry.add(size);
+        initEntry.add_dropped(dropped);
         table.add(hash, initEntry);
     } else {
         UidEntry &entry = table.editEntryAt(index);
         entry.add(size);
+        entry.add_dropped(dropped);
     }
 
     mSizesTotal[log_id] += size;
@@ -96,6 +99,7 @@ void LogStatistics::add(LogBufferElement *e) {
     if (index == -1) {
         PidEntry initEntry(pid, uid, android::pidToName(pid));
         initEntry.add(size);
+        initEntry.add_dropped(dropped);
         pidTable.add(hash, initEntry);
     } else {
         PidEntry &entry = pidTable.editEntryAt(index);
@@ -109,6 +113,7 @@ void LogStatistics::add(LogBufferElement *e) {
             }
         }
         entry.add(size);
+        entry.add_dropped(dropped);
     }
 }
 
@@ -119,12 +124,13 @@ void LogStatistics::subtract(LogBufferElement *e) {
     --mElements[log_id];
 
     uid_t uid = e->getUid();
+    unsigned short dropped = e->getDropped();
     android::hash_t hash = android::hash_type(uid);
     uidTable_t &table = uidTable[log_id];
     ssize_t index = table.find(-1, hash, uid);
     if (index != -1) {
         UidEntry &entry = table.editEntryAt(index);
-        if (entry.subtract(size)) {
+        if (entry.subtract(size) || entry.subtract_dropped(dropped)) {
             table.removeAt(index);
         }
     }
@@ -138,12 +144,43 @@ void LogStatistics::subtract(LogBufferElement *e) {
     index = pidTable.find(-1, hash, pid);
     if (index != -1) {
         PidEntry &entry = pidTable.editEntryAt(index);
-        if (entry.subtract(size)) {
+        if (entry.subtract(size) || entry.subtract_dropped(dropped)) {
             pidTable.removeAt(index);
         }
     }
 }
 
+// Atomically set an entry to drop
+// entry->setDropped(1) must follow this call, caller should do this explicitly.
+void LogStatistics::drop(LogBufferElement *e) {
+    log_id_t log_id = e->getLogId();
+    unsigned short size = e->getMsgLen();
+    mSizes[log_id] -= size;
+
+    uid_t uid = e->getUid();
+    android::hash_t hash = android::hash_type(uid);
+    typeof uidTable[0] &table = uidTable[log_id];
+    ssize_t index = table.find(-1, hash, uid);
+    if (index != -1) {
+        UidEntry &entry = table.editEntryAt(index);
+        entry.subtract(size);
+        entry.add_dropped(1);
+    }
+
+    if (!enable) {
+        return;
+    }
+
+    pid_t pid = e->getPid();
+    hash = android::hash_type(pid);
+    index = pidTable.find(-1, hash, pid);
+    if (index != -1) {
+        PidEntry &entry = pidTable.editEntryAt(index);
+        entry.subtract(size);
+        entry.add_dropped(1);
+    }
+}
+
 // caller must own and free character string
 char *LogStatistics::uidToName(uid_t uid) {
     // Local hard coded favourites
@@ -191,12 +228,22 @@ char *LogStatistics::uidToName(uid_t uid) {
 }
 
 static void format_line(android::String8 &output,
-        android::String8 &name, android::String8 &size) {
-    static const size_t total_len = 70;
-
-    output.appendFormat("%s%*s\n", name.string(),
-        (int)std::max(total_len - name.length() - 1, size.length() + 1),
-        size.string());
+        android::String8 &name, android::String8 &size, android::String8 &pruned) {
+    static const size_t pruned_len = 6;
+    static const size_t total_len = 70 + pruned_len;
+
+    ssize_t drop_len = std::max(pruned.length() + 1, pruned_len);
+    ssize_t size_len = std::max(size.length() + 1,
+                                total_len - name.length() - drop_len - 1);
+
+    if (pruned.length()) {
+        output.appendFormat("%s%*s%*s\n", name.string(),
+                                          (int)size_len, size.string(),
+                                          (int)drop_len, pruned.string());
+    } else {
+        output.appendFormat("%s%*s\n", name.string(),
+                                       (int)size_len, size.string());
+    }
 }
 
 void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
@@ -285,14 +332,18 @@ void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
                     output.appendFormat(
                         "\n\nChattiest UIDs in %s:\n",
                         android_log_id_to_name(id));
-                    android::String8 name("UID");
-                    android::String8 size("Size");
-                    format_line(output, name, size);
                 } else {
                     output.appendFormat(
                         "\n\nLogging for your UID in %s:\n",
                         android_log_id_to_name(id));
                 }
+                android::String8 name("UID");
+                android::String8 size("Size");
+                android::String8 pruned("Pruned");
+                if (id == LOG_ID_CRASH) {
+                    pruned.setTo("");
+                }
+                format_line(output, name, size, pruned);
                 headerPrinted = true;
             }
 
@@ -307,7 +358,13 @@ void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
             android::String8 size("");
             size.appendFormat("%zu", entry->getSizes());
 
-            format_line(output, name, size);
+            android::String8 pruned("");
+            size_t dropped = entry->getDropped();
+            if (dropped) {
+                pruned.appendFormat("%zu", dropped);
+            }
+
+            format_line(output, name, size, pruned);
         }
     }
 
@@ -330,7 +387,8 @@ void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
                 }
                 android::String8 name("  PID/UID");
                 android::String8 size("Size");
-                format_line(output, name, size);
+                android::String8 pruned("Pruned");
+                format_line(output, name, size, pruned);
                 headerPrinted = true;
             }
 
@@ -350,7 +408,13 @@ void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) {
             android::String8 size("");
             size.appendFormat("%zu", entry->getSizes());
 
-            format_line(output, name, size);
+            android::String8 pruned("");
+            size_t dropped = entry->getDropped();
+            if (dropped) {
+                pruned.appendFormat("%zu", dropped);
+            }
+
+            format_line(output, name, size, pruned);
         }
     }
 
diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h
index a65ffe0f9..f3110d755 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -78,13 +78,18 @@ public:
 struct UidEntry {
     const uid_t uid;
     size_t size;
+    size_t dropped;
 
-    UidEntry(uid_t uid):uid(uid),size(0) { }
+    UidEntry(uid_t uid):uid(uid),size(0),dropped(0) { }
 
     inline const uid_t&getKey() const { return uid; }
     size_t getSizes() const { return size; }
+    size_t getDropped() const { return dropped; }
+
     inline void add(size_t s) { size += s; }
-    inline bool subtract(size_t s) { size -= s; return !size; }
+    inline void add_dropped(size_t d) { dropped += d; }
+    inline bool subtract(size_t s) { size -= s; return !dropped && !size; }
+    inline bool subtract_dropped(size_t d) { dropped -= d; return !dropped && !size; }
 };
 
 struct PidEntry {
@@ -92,13 +97,15 @@ struct PidEntry {
     uid_t uid;
     char *name;
     size_t size;
+    size_t dropped;
 
-    PidEntry(pid_t p, uid_t u, char *n):pid(p),uid(u),name(n),size(0) { }
+    PidEntry(pid_t p, uid_t u, char *n):pid(p),uid(u),name(n),size(0),dropped(0) { }
     PidEntry(const PidEntry &c):
         pid(c.pid),
         uid(c.uid),
         name(c.name ? strdup(c.name) : NULL),
-        size(c.size) { }
+        size(c.size),
+        dropped(c.dropped) { }
     ~PidEntry() { free(name); }
 
     const pid_t&getKey() const { return pid; }
@@ -107,8 +114,11 @@ struct PidEntry {
     const char*getName() const { return name; }
     char *setName(char *n) { free(name); return name = n; }
     size_t getSizes() const { return size; }
+    size_t getDropped() const { return dropped; }
     inline void add(size_t s) { size += s; }
-    inline bool subtract(size_t s) { size -= s; return !size; }
+    inline void add_dropped(size_t d) { dropped += d; }
+    inline bool subtract(size_t s) { size -= s; return !dropped && !size; }
+    inline bool subtract_dropped(size_t d) { dropped -= d; return !dropped && !size; }
 };
 
 // Log Statistics
@@ -134,6 +144,10 @@ public:
 
     void add(LogBufferElement *entry);
     void subtract(LogBufferElement *entry);
+    // entry->setDropped(1) must follow this call
+    void drop(LogBufferElement *entry);
+    // Correct for merging two entries referencing dropped content
+    void erase(LogBufferElement *e) { --mElements[e->getLogId()]; }
 
     std::unique_ptr<const UidEntry *[]> sort(size_t n, log_id i) { return uidTable[i].sort(n); }
 
diff --git a/logd/LogWhiteBlackList.cpp b/logd/LogWhiteBlackList.cpp
index 691085480..9728db17b 100644
--- a/logd/LogWhiteBlackList.cpp
+++ b/logd/LogWhiteBlackList.cpp
@@ -15,7 +15,6 @@
  */
 
 #include <ctype.h>
-#include <malloc.h>
 
 #include <utils/String8.h>
 
diff --git a/logd/event.logtags b/logd/event.logtags
index a63f03417..db8c19b37 100644
--- a/logd/event.logtags
+++ b/logd/event.logtags
@@ -34,3 +34,4 @@
 # TODO: generate ".java" and ".h" files with integer constants from this file.
 
 1003  auditd (avc|3)
+1004  logd (dropped|3)