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
diff --git a/logd/Android.mk b/logd/Android.mk
index 127a66b..e65e9ff 100644
--- a/logd/Android.mk
+++ b/logd/Android.mk
@@ -32,8 +32,9 @@
# "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 a5844a3..d8ffb02 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -297,6 +297,8 @@
}
bool kick = false;
+ bool leading = true;
+ LogBufferElement *last = NULL;
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
@@ -309,26 +311,87 @@
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;
}
- unsigned short len = e->getMsgLen();
- it = erase(it);
+ if (e->getUid() != worst) {
+ last = NULL;
+ ++it;
+ continue;
+ }
+
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 5e780b5..a173e63 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 @@
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 @@
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 93671da..cc18378 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 @@
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 @@
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 3fbcfd6..e0b8fd8 100644
--- a/logd/LogStatistics.cpp
+++ b/logd/LogStatistics.cpp
@@ -71,16 +71,19 @@
++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 @@
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 @@
}
}
entry.add(size);
+ entry.add_dropped(dropped);
}
}
@@ -119,12 +124,13 @@
--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 @@
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 @@
}
static void format_line(android::String8 &output,
- android::String8 &name, android::String8 &size) {
- static const size_t total_len = 70;
+ 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;
- output.appendFormat("%s%*s\n", name.string(),
- (int)std::max(total_len - name.length() - 1, size.length() + 1),
- size.string());
+ 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 @@
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 @@
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 @@
}
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 @@
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 a65ffe0..f3110d7 100644
--- a/logd/LogStatistics.h
+++ b/logd/LogStatistics.h
@@ -78,13 +78,18 @@
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 @@
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 @@
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 @@
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 6910854..9728db1 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 a63f034..db8c19b 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)