diff options
Diffstat (limited to 'logd')
-rw-r--r-- | logd/Android.mk | 12 | ||||
-rw-r--r-- | logd/CommandListener.cpp | 22 | ||||
-rw-r--r-- | logd/CommandListener.h | 11 | ||||
-rw-r--r-- | logd/FlushCommand.cpp | 2 | ||||
-rw-r--r-- | logd/FlushCommand.h | 4 | ||||
-rw-r--r-- | logd/LogAudit.cpp | 120 | ||||
-rw-r--r-- | logd/LogAudit.h | 3 | ||||
-rw-r--r-- | logd/LogBuffer.cpp | 388 | ||||
-rw-r--r-- | logd/LogBuffer.h | 19 | ||||
-rw-r--r-- | logd/LogBufferElement.cpp | 85 | ||||
-rw-r--r-- | logd/LogBufferElement.h | 43 | ||||
-rw-r--r-- | logd/LogCommand.cpp | 1 | ||||
-rw-r--r-- | logd/LogListener.cpp | 38 | ||||
-rw-r--r-- | logd/LogReader.cpp | 44 | ||||
-rw-r--r-- | logd/LogStatistics.cpp | 1096 | ||||
-rw-r--r-- | logd/LogStatistics.h | 246 | ||||
-rw-r--r-- | logd/LogTimes.cpp | 46 | ||||
-rw-r--r-- | logd/LogTimes.h | 19 | ||||
-rw-r--r-- | logd/LogWhiteBlackList.cpp | 17 | ||||
-rw-r--r-- | logd/LogWhiteBlackList.h | 2 | ||||
-rw-r--r-- | logd/README.property | 6 | ||||
-rw-r--r-- | logd/event.logtags | 1 | ||||
-rw-r--r-- | logd/libaudit.c | 2 | ||||
-rw-r--r-- | logd/main.cpp | 218 | ||||
-rw-r--r-- | logd/tests/Android.mk | 1 | ||||
-rw-r--r-- | logd/tests/logd_test.cpp | 164 |
26 files changed, 1234 insertions, 1376 deletions
diff --git a/logd/Android.mk b/logd/Android.mk index 188511f..e65e9ff 100644 --- a/logd/Android.mk +++ b/logd/Android.mk @@ -26,7 +26,17 @@ LOCAL_SHARED_LIBRARIES := \ libcutils \ libutils -LOCAL_CFLAGS := -Werror $(shell sed -n 's/^\([0-9]*\)[ \t]*auditd[ \t].*/-DAUDITD_LOG_TAG=\1/p' $(LOCAL_PATH)/event.logtags) +# This is what we want to do: +# event_logtags = $(shell \ +# sed -n \ +# "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 -DLOGD_LOG_TAG=1004 + +LOCAL_CFLAGS := -Werror $(event_flag) include $(BUILD_EXECUTABLE) diff --git a/logd/CommandListener.cpp b/logd/CommandListener.cpp index d7088b4..bdfed3b 100644 --- a/logd/CommandListener.cpp +++ b/logd/CommandListener.cpp @@ -44,6 +44,7 @@ CommandListener::CommandListener(LogBuffer *buf, LogReader * /*reader*/, registerCmd(new GetStatisticsCmd(buf)); registerCmd(new SetPruneListCmd(buf)); registerCmd(new GetPruneListCmd(buf)); + registerCmd(new ReinitCmd()); } CommandListener::ShutdownCmd::ShutdownCmd(LogBuffer *buf, LogReader *reader, @@ -68,7 +69,11 @@ CommandListener::ClearCmd::ClearCmd(LogBuffer *buf) { } static void setname() { - prctl(PR_SET_NAME, "logd.control"); + static bool name_set; + if (!name_set) { + prctl(PR_SET_NAME, "logd.control"); + name_set = true; + } } int CommandListener::ClearCmd::runCommand(SocketClient *cli, @@ -296,6 +301,21 @@ int CommandListener::SetPruneListCmd::runCommand(SocketClient *cli, return 0; } +CommandListener::ReinitCmd::ReinitCmd() + : LogCommand("reinit") +{ } + +int CommandListener::ReinitCmd::runCommand(SocketClient *cli, + int /*argc*/, char ** /*argv*/) { + setname(); + + reinit_signal_handler(SIGHUP); + + cli->sendMsg("success"); + + return 0; +} + int CommandListener::getLogSocket() { static const char socketName[] = "logd"; int sock = android_get_control_socket(socketName); diff --git a/logd/CommandListener.h b/logd/CommandListener.h index cd1c306..83e06b4 100644 --- a/logd/CommandListener.h +++ b/logd/CommandListener.h @@ -23,6 +23,9 @@ #include "LogReader.h" #include "LogListener.h" +// See main.cpp for implementation +void reinit_signal_handler(int /*signal*/); + class CommandListener : public FrameworkListener { LogBuffer &mBuf; @@ -60,6 +63,14 @@ private: LogBufferCmd(GetStatistics) LogBufferCmd(GetPruneList) LogBufferCmd(SetPruneList) + + class ReinitCmd : public LogCommand { + public: + ReinitCmd(); + virtual ~ReinitCmd() {} + int runCommand(SocketClient *c, int argc, char ** argv); + }; + }; #endif diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp index 3be07c0..26a1861 100644 --- a/logd/FlushCommand.cpp +++ b/logd/FlushCommand.cpp @@ -27,7 +27,7 @@ FlushCommand::FlushCommand(LogReader &reader, unsigned long tail, unsigned int logMask, pid_t pid, - log_time start) + uint64_t start) : mReader(reader) , mNonBlock(nonBlock) , mTail(tail) diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h index f34c06a..61c6858 100644 --- a/logd/FlushCommand.h +++ b/logd/FlushCommand.h @@ -31,7 +31,7 @@ class FlushCommand : public SocketClientCommand { unsigned long mTail; unsigned int mLogMask; pid_t mPid; - log_time mStart; + uint64_t mStart; public: FlushCommand(LogReader &mReader, @@ -39,7 +39,7 @@ public: unsigned long tail = -1, unsigned int logMask = -1, pid_t pid = 0, - log_time start = LogTimeEntry::EPOCH); + uint64_t start = 1); virtual void runSocketCommand(SocketClient *client); static bool hasReadLogs(SocketClient *client); diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp index ee2f32d..caae54b 100644 --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -15,39 +15,44 @@ */ #include <ctype.h> +#include <endian.h> #include <errno.h> #include <limits.h> #include <stdarg.h> #include <stdlib.h> -#include <sys/klog.h> #include <sys/prctl.h> #include <sys/uio.h> #include <syslog.h> +#include <private/android_filesystem_config.h> +#include <private/android_logger.h> + #include "libaudit.h" #include "LogAudit.h" -#define KMSG_PRIORITY(PRI) \ - '<', \ - '0' + (LOG_AUTH | (PRI)) / 10, \ - '0' + (LOG_AUTH | (PRI)) % 10, \ +#define KMSG_PRIORITY(PRI) \ + '<', \ + '0' + LOG_MAKEPRI(LOG_AUTH, LOG_PRI(PRI)) / 10, \ + '0' + LOG_MAKEPRI(LOG_AUTH, LOG_PRI(PRI)) % 10, \ '>' -LogAudit::LogAudit(LogBuffer *buf, LogReader *reader, int fdDmsg) +LogAudit::LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg) : SocketListener(getLogSocket(), false) , logbuf(buf) , reader(reader) - , fdDmesg(-1) { + , fdDmesg(fdDmesg) + , initialized(false) { static const char auditd_message[] = { KMSG_PRIORITY(LOG_INFO), 'l', 'o', 'g', 'd', '.', 'a', 'u', 'd', 'i', 't', 'd', ':', ' ', 's', 't', 'a', 'r', 't', '\n' }; - write(fdDmsg, auditd_message, sizeof(auditd_message)); - logDmesg(); - fdDmesg = fdDmsg; + write(fdDmesg, auditd_message, sizeof(auditd_message)); } bool LogAudit::onDataAvailable(SocketClient *cli) { - prctl(PR_SET_NAME, "logd.auditd"); + if (!initialized) { + prctl(PR_SET_NAME, "logd.auditd"); + initialized = true; + } struct audit_message rep; @@ -60,7 +65,8 @@ bool LogAudit::onDataAvailable(SocketClient *cli) { return false; } - logPrint("type=%d %.*s", rep.nlh.nlmsg_type, rep.nlh.nlmsg_len, rep.data); + logPrint("type=%d %.*s", + rep.nlh.nlmsg_type, rep.nlh.nlmsg_len, rep.data); return true; } @@ -87,7 +93,7 @@ int LogAudit::logPrint(const char *fmt, ...) { } bool info = strstr(str, " permissive=1") || strstr(str, " policy loaded "); - if (fdDmesg >= 0) { + if ((fdDmesg >= 0) && initialized) { struct iovec iov[3]; static const char log_info[] = { KMSG_PRIORITY(LOG_INFO) }; static const char log_warning[] = { KMSG_PRIORITY(LOG_WARNING) }; @@ -105,7 +111,7 @@ int LogAudit::logPrint(const char *fmt, ...) { pid_t pid = getpid(); pid_t tid = gettid(); - uid_t uid = getuid(); + uid_t uid = AID_LOGD; log_time now; static const char audit_str[] = " audit("; @@ -136,31 +142,27 @@ int LogAudit::logPrint(const char *fmt, ...) { // log to events size_t l = strlen(str); - size_t n = l + sizeof(uint32_t) + sizeof(uint8_t) + sizeof(uint32_t); + size_t n = l + sizeof(android_log_event_string_t); bool notify = false; - char *newstr = reinterpret_cast<char *>(malloc(n)); - if (!newstr) { + android_log_event_string_t *event = static_cast<android_log_event_string_t *>(malloc(n)); + if (!event) { rc = -ENOMEM; } else { - cp = newstr; - *cp++ = AUDITD_LOG_TAG & 0xFF; - *cp++ = (AUDITD_LOG_TAG >> 8) & 0xFF; - *cp++ = (AUDITD_LOG_TAG >> 16) & 0xFF; - *cp++ = (AUDITD_LOG_TAG >> 24) & 0xFF; - *cp++ = EVENT_TYPE_STRING; - *cp++ = l & 0xFF; - *cp++ = (l >> 8) & 0xFF; - *cp++ = (l >> 16) & 0xFF; - *cp++ = (l >> 24) & 0xFF; - memcpy(cp, str, l); - - logbuf->log(LOG_ID_EVENTS, now, uid, pid, tid, newstr, - (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX); - free(newstr); - - notify = true; + event->header.tag = htole32(AUDITD_LOG_TAG); + event->type = EVENT_TYPE_STRING; + event->length = htole32(l); + memcpy(event->data, str, l); + + rc = logbuf->log(LOG_ID_EVENTS, now, uid, pid, tid, + reinterpret_cast<char *>(event), + (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX); + free(event); + + if (rc >= 0) { + notify = true; + } } // log to main @@ -188,7 +190,7 @@ int LogAudit::logPrint(const char *fmt, ...) { } n = (estr - str) + strlen(ecomm) + l + 2; - newstr = reinterpret_cast<char *>(malloc(n)); + char *newstr = static_cast<char *>(malloc(n)); if (!newstr) { rc = -ENOMEM; } else { @@ -197,50 +199,44 @@ int LogAudit::logPrint(const char *fmt, ...) { strncpy(newstr + 1 + l, str, estr - str); strcpy(newstr + 1 + l + (estr - str), ecomm); - logbuf->log(LOG_ID_MAIN, now, uid, pid, tid, newstr, - (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX); + rc = logbuf->log(LOG_ID_MAIN, now, uid, pid, tid, newstr, + (n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX); free(newstr); - notify = true; + if (rc >= 0) { + notify = true; + } } free(str); if (notify) { reader->notifyNewLog(); + if (rc < 0) { + rc = n; + } } return rc; } -void LogAudit::logDmesg() { - int len = klogctl(KLOG_SIZE_BUFFER, NULL, 0); - if (len <= 0) { - return; +int LogAudit::log(char *buf) { + char *audit = strstr(buf, " audit("); + if (!audit) { + return -EXDEV; } - len++; - char buf[len]; + *audit = '\0'; - int rc = klogctl(KLOG_READ_ALL, buf, len); - - buf[len - 1] = '\0'; - - for(char *tok = buf; (rc >= 0) && ((tok = strtok(tok, "\r\n"))); tok = NULL) { - char *audit = strstr(tok, " audit("); - if (!audit) { - continue; - } - - *audit++ = '\0'; - - char *type = strstr(tok, "type="); - if (type) { - rc = logPrint("%s %s", type, audit); - } else { - rc = logPrint("%s", audit); - } + int rc; + char *type = strstr(buf, "type="); + if (type) { + rc = logPrint("%s %s", type, audit + 1); + } else { + rc = logPrint("%s", audit + 1); } + *audit = ' '; + return rc; } int LogAudit::getLogSocket() { diff --git a/logd/LogAudit.h b/logd/LogAudit.h index 111030a..f977be9 100644 --- a/logd/LogAudit.h +++ b/logd/LogAudit.h @@ -24,16 +24,17 @@ class LogAudit : public SocketListener { LogBuffer *logbuf; LogReader *reader; int fdDmesg; + bool initialized; public: LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg); + int log(char *buf); protected: virtual bool onDataAvailable(SocketClient *cli); private: static int getLogSocket(); - void logDmesg(); int logPrint(const char *fmt, ...) __attribute__ ((__format__ (__printf__, 2, 3))); }; diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 8c1c344..1dced11 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -15,8 +15,8 @@ */ #include <ctype.h> +#include <errno.h> #include <stdio.h> -#include <stdlib.h> #include <string.h> #include <sys/user.h> #include <time.h> @@ -27,8 +27,6 @@ #include "LogBuffer.h" #include "LogReader.h" -#include "LogStatistics.h" -#include "LogWhiteBlackList.h" // Default #define LOG_BUFFER_SIZE (256 * 1024) // Tuned on a per-platform basis here? @@ -92,11 +90,7 @@ static unsigned long property_get_size(const char *key) { return value; } -LogBuffer::LogBuffer(LastLogTimes *times) - : dgramQlenStatistics(false) - , mTimes(*times) { - pthread_mutex_init(&mLogElementsLock, NULL); - +void LogBuffer::init() { static const char global_tuneable[] = "persist.logd.size"; // Settings App static const char global_default[] = "ro.logd.size"; // BoardConfig.mk @@ -132,11 +126,18 @@ LogBuffer::LogBuffer(LastLogTimes *times) } } -void 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) { +LogBuffer::LogBuffer(LastLogTimes *times) + : mTimes(*times) { + pthread_mutex_init(&mLogElementsLock, NULL); + + init(); +} + +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) { if ((log_id >= LOG_ID_MAX) || (log_id < 0)) { - return; + return -EINVAL; } LogBufferElement *elem = new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len); @@ -147,25 +148,9 @@ void LogBuffer::log(log_id_t log_id, log_time realtime, // NB: if end is region locked, place element at end of list LogBufferElementCollection::iterator it = mLogElements.end(); LogBufferElementCollection::iterator last = it; - while (--it != mLogElements.begin()) { + while (last != mLogElements.begin()) { + --it; if ((*it)->getRealTime() <= realtime) { - // halves the peak performance, use with caution - if (dgramQlenStatistics) { - LogBufferElementCollection::iterator ib = it; - unsigned short buckets, num = 1; - for (unsigned short i = 0; (buckets = stats.dgramQlen(i)); ++i) { - buckets -= num; - num += buckets; - while (buckets && (--ib != mLogElements.begin())) { - --buckets; - } - if (buckets) { - break; - } - stats.recordDiff( - elem->getRealTime() - (*ib)->getRealTime(), i); - } - } break; } last = it; @@ -174,7 +159,7 @@ void LogBuffer::log(log_id_t log_id, log_time realtime, if (last == mLogElements.end()) { mLogElements.push_back(elem); } else { - log_time end = log_time::EPOCH; + uint64_t end = 1; bool end_set = false; bool end_always = false; @@ -197,7 +182,7 @@ void LogBuffer::log(log_id_t log_id, log_time realtime, } if (end_always - || (end_set && (end >= (*last)->getMonotonicTime()))) { + || (end_set && (end >= (*last)->getSequence()))) { mLogElements.push_back(elem); } else { mLogElements.insert(last,elem); @@ -206,9 +191,11 @@ void LogBuffer::log(log_id_t log_id, log_time realtime, LogTimeEntry::unlock(); } - stats.add(len, log_id, uid, pid); + stats.add(elem); maybePrune(log_id); pthread_mutex_unlock(&mLogElementsLock); + + return len; } // If we're using more than 256K of memory for log entries, prune @@ -229,6 +216,94 @@ void LogBuffer::maybePrune(log_id_t id) { } } +LogBufferElementCollection::iterator LogBuffer::erase(LogBufferElementCollection::iterator it) { + LogBufferElement *e = *it; + + it = mLogElements.erase(it); + stats.subtract(e); + delete e; + + return it; +} + +// Define a temporary mechanism to report the last LogBufferElement pointer +// for the specified uid, pid and tid. Used below to help merge-sort when +// pruning for worst UID. +class LogBufferElementKey { + const union { + struct { + uint16_t uid; + uint16_t pid; + uint16_t tid; + uint16_t padding; + } __packed; + uint64_t value; + } __packed; + +public: + LogBufferElementKey(uid_t u, pid_t p, pid_t t):uid(u),pid(p),tid(t),padding(0) { } + LogBufferElementKey(uint64_t k):value(k) { } + + uint64_t getKey() { return value; } +}; + +class LogBufferElementEntry { + const uint64_t key; + LogBufferElement *last; + +public: + LogBufferElementEntry(const uint64_t &k, LogBufferElement *e):key(k),last(e) { } + + const uint64_t&getKey() const { return key; } + + LogBufferElement *getLast() { return last; } +}; + +class LogBufferElementLast : public android::BasicHashtable<uint64_t, LogBufferElementEntry> { + +public: + bool merge(LogBufferElement *e, unsigned short dropped) { + LogBufferElementKey key(e->getUid(), e->getPid(), e->getTid()); + android::hash_t hash = android::hash_type(key.getKey()); + ssize_t index = find(-1, hash, key.getKey()); + if (index != -1) { + LogBufferElementEntry &entry = editEntryAt(index); + LogBufferElement *l = entry.getLast(); + unsigned short d = l->getDropped(); + if ((dropped + d) > USHRT_MAX) { + removeAt(index); + } else { + l->setDropped(dropped + d); + return true; + } + } + return false; + } + + size_t add(LogBufferElement *e) { + LogBufferElementKey key(e->getUid(), e->getPid(), e->getTid()); + android::hash_t hash = android::hash_type(key.getKey()); + return android::BasicHashtable<uint64_t, LogBufferElementEntry>:: + add(hash, LogBufferElementEntry(key.getKey(), e)); + } + + inline void clear() { + android::BasicHashtable<uint64_t, LogBufferElementEntry>::clear(); + } + + void clear(LogBufferElement *e) { + uint64_t current = e->getRealTime().nsec() - NS_PER_SEC; + ssize_t index = -1; + while((index = next(index)) >= 0) { + if (current > editEntryAt(index).getLast()->getRealTime().nsec()) { + removeAt(index); + index = -1; + } + } + } + +}; + // prune "pruneRows" of type "id" from the buffer. // // mLogElementsLock must be held when this function is called. @@ -241,7 +316,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { LastLogTimes::iterator t = mTimes.begin(); while(t != mTimes.end()) { LogTimeEntry *entry = (*t); - if (entry->owned_Locked() + if (entry->owned_Locked() && entry->isWatching(id) && (!oldest || (oldest->mStart > entry->mStart))) { oldest = entry; } @@ -254,7 +329,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { for(it = mLogElements.begin(); it != mLogElements.end();) { LogBufferElement *e = *it; - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { + if (oldest && (oldest->mStart <= e->getSequence())) { break; } @@ -263,12 +338,8 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { continue; } - uid_t uid = e->getUid(); - - if (uid == caller_uid) { - it = mLogElements.erase(it); - stats.subtract(e->getMsgLen(), id, uid, e->getPid()); - delete e; + if (e->getUid() == caller_uid) { + it = erase(it); pruneRows--; if (pruneRows == 0) { break; @@ -282,31 +353,44 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } // prune by worst offender by uid + bool hasBlacklist = mPrune.naughty(); while (pruneRows > 0) { // recalculate the worst offender on every batched pass uid_t worst = (uid_t) -1; size_t worst_sizes = 0; size_t second_worst_sizes = 0; - if ((id != LOG_ID_CRASH) && mPrune.worstUidEnabled()) { - LidStatistics &l = stats.id(id); - l.sort(); - UidStatisticsCollection::iterator iu = l.begin(); - if (iu != l.end()) { - UidStatistics *u = *iu; - worst = u->getUid(); - worst_sizes = u->sizes(); - if (++iu != l.end()) { - second_worst_sizes = (*iu)->sizes(); + if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) { + std::unique_ptr<const UidEntry *[]> sorted = stats.sort(2, id); + + if (sorted.get()) { + if (sorted[0] && sorted[1]) { + worst_sizes = sorted[0]->getSizes(); + // Calculate threshold as 12.5% of available storage + size_t threshold = log_buffer_size(id) / 8; + if (worst_sizes > threshold) { + worst = sorted[0]->getKey(); + second_worst_sizes = sorted[1]->getSizes(); + if (second_worst_sizes < threshold) { + second_worst_sizes = threshold; + } + } } } } + // skip if we have neither worst nor naughty filters + if ((worst == (uid_t) -1) && !hasBlacklist) { + break; + } + bool kick = false; + bool leading = true; + LogBufferElementLast last; for(it = mLogElements.begin(); it != mLogElements.end();) { LogBufferElement *e = *it; - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { + if (oldest && (oldest->mStart <= e->getSequence())) { break; } @@ -315,27 +399,82 @@ 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(); - if ((uid == worst) || mPrune.naughty(e)) { // Worst or BlackListed + // remove any leading drops + if (leading && dropped) { + it = erase(it); + continue; + } + + // merge any drops + if (dropped && last.merge(e, dropped)) { it = mLogElements.erase(it); - unsigned short len = e->getMsgLen(); - stats.subtract(len, id, uid, e->getPid()); + stats.erase(e); delete e; + continue; + } + + leading = false; + + if (hasBlacklist && mPrune.naughty(e)) { + last.clear(e); + it = erase(it); + if (dropped) { + continue; + } + pruneRows--; - if (uid == worst) { + if (pruneRows == 0) { + break; + } + + if (e->getUid() == worst) { kick = true; - if ((pruneRows == 0) || (worst_sizes < second_worst_sizes)) { + if (worst_sizes < second_worst_sizes) { break; } - worst_sizes -= len; - } else if (pruneRows == 0) { - break; + worst_sizes -= e->getMsgLen(); } + continue; + } + + if (dropped) { + last.add(e); + ++it; + continue; + } + + if (e->getUid() != worst) { + last.clear(e); + ++it; + continue; + } + + pruneRows--; + if (pruneRows == 0) { + break; + } + + kick = true; + + unsigned short len = e->getMsgLen(); + stats.drop(e); + e->setDropped(1); + if (last.merge(e, 1)) { + it = mLogElements.erase(it); + stats.erase(e); + delete e; } else { + last.add(e); ++it; } + if (worst_sizes < second_worst_sizes) { + break; + } + worst_sizes -= len; } + last.clear(); if (!kick || !mPrune.worstUidEnabled()) { break; // the following loop will ask bad clients to skip/drop @@ -343,58 +482,63 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } bool whitelist = false; + bool hasWhitelist = mPrune.nice(); it = mLogElements.begin(); while((pruneRows > 0) && (it != mLogElements.end())) { LogBufferElement *e = *it; - if (e->getLogId() == id) { - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { - if (!whitelist) { - if (stats.sizes(id) > (2 * log_buffer_size(id))) { - // kick a misbehaving log reader client off the island - oldest->release_Locked(); - } else { - oldest->triggerSkip_Locked(pruneRows); - } - } + + if (e->getLogId() != id) { + it++; + continue; + } + + if (oldest && (oldest->mStart <= e->getSequence())) { + if (whitelist) { break; } - if (mPrune.nice(e)) { // WhiteListed - whitelist = true; - it++; - continue; + if (stats.sizes(id) > (2 * log_buffer_size(id))) { + // kick a misbehaving log reader client off the island + oldest->release_Locked(); + } else { + oldest->triggerSkip_Locked(id, pruneRows); } + break; + } - it = mLogElements.erase(it); - stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid()); - delete e; - pruneRows--; - } else { + if (hasWhitelist && mPrune.nice(e)) { // WhiteListed + whitelist = true; it++; + continue; } + + it = erase(it); + pruneRows--; } + // Do not save the whitelist if we are reader range limited if (whitelist && (pruneRows > 0)) { it = mLogElements.begin(); while((it != mLogElements.end()) && (pruneRows > 0)) { LogBufferElement *e = *it; - if (e->getLogId() == id) { - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { - if (stats.sizes(id) > (2 * log_buffer_size(id))) { - // kick a misbehaving log reader client off the island - oldest->release_Locked(); - } else { - oldest->triggerSkip_Locked(pruneRows); - } - break; + + if (e->getLogId() != id) { + ++it; + continue; + } + + if (oldest && (oldest->mStart <= e->getSequence())) { + if (stats.sizes(id) > (2 * log_buffer_size(id))) { + // kick a misbehaving log reader client off the island + oldest->release_Locked(); + } else { + oldest->triggerSkip_Locked(id, pruneRows); } - it = mLogElements.erase(it); - stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid()); - delete e; - pruneRows--; - } else { - it++; + break; } + + it = erase(it); + pruneRows--; } } @@ -436,28 +580,51 @@ unsigned long LogBuffer::getSize(log_id_t id) { return retval; } -log_time LogBuffer::flushTo( - SocketClient *reader, const log_time start, bool privileged, - bool (*filter)(const LogBufferElement *element, void *arg), void *arg) { +uint64_t LogBuffer::flushTo( + SocketClient *reader, const uint64_t start, bool privileged, + int (*filter)(const LogBufferElement *element, void *arg), void *arg) { LogBufferElementCollection::iterator it; - log_time max = start; + uint64_t max = start; uid_t uid = reader->getUid(); pthread_mutex_lock(&mLogElementsLock); - for (it = mLogElements.begin(); it != mLogElements.end(); ++it) { + + if (start <= 1) { + // client wants to start from the beginning + it = mLogElements.begin(); + } else { + // Client wants to start from some specified time. Chances are + // we are better off starting from the end of the time sorted list. + for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { + --it; + LogBufferElement *element = *it; + if (element->getSequence() <= start) { + it++; + break; + } + } + } + + for (; it != mLogElements.end(); ++it) { LogBufferElement *element = *it; if (!privileged && (element->getUid() != uid)) { continue; } - if (element->getMonotonicTime() <= start) { + if (element->getSequence() <= start) { continue; } // NB: calling out to another object with mLogElementsLock held (safe) - if (filter && !(*filter)(element, arg)) { - continue; + if (filter) { + int ret = (*filter)(element, arg); + if (ret == false) { + continue; + } + if (ret != true) { + break; + } } pthread_mutex_unlock(&mLogElementsLock); @@ -477,22 +644,9 @@ log_time LogBuffer::flushTo( } void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) { - log_time oldest(CLOCK_MONOTONIC); - pthread_mutex_lock(&mLogElementsLock); - // Find oldest element in the log(s) - LogBufferElementCollection::iterator it; - for (it = mLogElements.begin(); it != mLogElements.end(); ++it) { - LogBufferElement *element = *it; - - if ((logMask & (1 << element->getLogId()))) { - oldest = element->getMonotonicTime(); - break; - } - } - - stats.format(strp, uid, logMask, oldest); + stats.format(strp, uid, logMask); pthread_mutex_unlock(&mLogElementsLock); } diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 879baea..9ee243d 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -37,7 +37,6 @@ class LogBuffer { pthread_mutex_t mLogElementsLock; LogStatistics stats; - bool dgramQlenStatistics; PruneList mPrune; @@ -47,13 +46,14 @@ public: LastLogTimes &mTimes; LogBuffer(LastLogTimes *times); + void init(); - void log(log_id_t log_id, log_time realtime, - uid_t uid, pid_t pid, pid_t tid, - const char *msg, unsigned short len); - log_time flushTo(SocketClient *writer, const log_time start, + int log(log_id_t log_id, log_time realtime, + uid_t uid, pid_t pid, pid_t tid, + const char *msg, unsigned short len); + uint64_t flushTo(SocketClient *writer, const uint64_t start, bool privileged, - bool (*filter)(const LogBufferElement *element, void *arg) = NULL, + int (*filter)(const LogBufferElement *element, void *arg) = NULL, void *arg = NULL); void clear(log_id_t id, uid_t uid = AID_ROOT); @@ -63,11 +63,6 @@ public: // *strp uses malloc, use free to release. void formatStatistics(char **strp, uid_t uid, unsigned int logMask); - void enableDgramQlenStatistics() { - stats.enableDgramQlenStatistics(); - dgramQlenStatistics = true; - } - void enableStatistics() { stats.enableStatistics(); } @@ -83,7 +78,7 @@ public: private: void maybePrune(log_id_t id); void prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT); - + LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it); }; #endif // _LOGD_LOG_BUFFER_H__ diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index d959ceb..a173e63 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -14,17 +14,21 @@ * 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 log_time LogBufferElement::FLUSH_ERROR((uint32_t)0, (uint32_t)0); +const uint64_t LogBufferElement::FLUSH_ERROR(0); +atomic_int_fast64_t LogBufferElement::sequence; LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, @@ -34,7 +38,7 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, , mPid(pid) , mTid(tid) , mMsgLen(len) - , mMonotonicTime(CLOCK_MONOTONIC) + , mSequence(sequence.fetch_add(1, memory_order_relaxed)) , mRealTime(realtime) { mMsg = new char[len]; memcpy(mMsg, msg, len); @@ -44,11 +48,59 @@ LogBufferElement::~LogBufferElement() { delete [] mMsg; } -log_time LogBufferElement::flushTo(SocketClient *reader) { +// 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; @@ -58,11 +110,26 @@ log_time 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 mMonotonicTime; + return retval; } diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index fdca973..7b6456d 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -17,20 +17,42 @@ #ifndef _LOGD_LOG_BUFFER_ELEMENT_H__ #define _LOGD_LOG_BUFFER_ELEMENT_H__ +#include <stdatomic.h> +#include <stdlib.h> #include <sys/types.h> + #include <sysutils/SocketClient.h> #include <log/log.h> #include <log/log_read.h> +namespace android { + +// Furnished in main.cpp. Caller must own and free returned value +// This function is designed for a single caller and is NOT thread-safe +char *uidToName(uid_t uid); + +} + +static inline bool worstUidEnabledForLogid(log_id_t id) { + return (id != LOG_ID_CRASH) && (id != LOG_ID_EVENTS); +} + class LogBufferElement { const log_id_t mLogId; const uid_t mUid; const pid_t mPid; const pid_t mTid; char *mMsg; - const unsigned short mMsgLen; - const log_time mMonotonicTime; + 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, @@ -42,12 +64,21 @@ 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; } - log_time getMonotonicTime(void) const { return mMonotonicTime; } + 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; } - static const log_time FLUSH_ERROR; - log_time flushTo(SocketClient *writer); + static const uint64_t FLUSH_ERROR; + uint64_t flushTo(SocketClient *writer); }; #endif diff --git a/logd/LogCommand.cpp b/logd/LogCommand.cpp index e4c138e..b78c0e0 100644 --- a/logd/LogCommand.cpp +++ b/logd/LogCommand.cpp @@ -17,6 +17,7 @@ #include <errno.h> #include <stdio.h> #include <stdlib.h> +#include <string.h> #include <private/android_filesystem_config.h> diff --git a/logd/LogListener.cpp b/logd/LogListener.cpp index 8186cea..05ced06 100644 --- a/logd/LogListener.cpp +++ b/logd/LogListener.cpp @@ -23,6 +23,8 @@ #include <cutils/sockets.h> #include <log/logger.h> +#include <private/android_filesystem_config.h> +#include <private/android_logger.h> #include "LogListener.h" @@ -33,7 +35,11 @@ LogListener::LogListener(LogBuffer *buf, LogReader *reader) { } bool LogListener::onDataAvailable(SocketClient *cli) { - prctl(PR_SET_NAME, "logd.writer"); + static bool name_set; + if (!name_set) { + prctl(PR_SET_NAME, "logd.writer"); + name_set = true; + } char buffer[sizeof_log_id_t + sizeof(uint16_t) + sizeof(log_time) + LOGGER_ENTRY_MAX_PAYLOAD]; @@ -54,7 +60,7 @@ bool LogListener::onDataAvailable(SocketClient *cli) { int socket = cli->getSocket(); ssize_t n = recvmsg(socket, &hdr, 0); - if (n <= (ssize_t)(sizeof_log_id_t + sizeof(uint16_t) + sizeof(log_time))) { + if (n <= (ssize_t)(sizeof(android_log_header_t))) { return false; } @@ -74,37 +80,29 @@ bool LogListener::onDataAvailable(SocketClient *cli) { return false; } - if (cred->uid == getuid()) { + if (cred->uid == AID_LOGD) { // ignore log messages we send to ourself. // Such log messages are often generated by libraries we depend on // which use standard Android logging. return false; } - // First log element is always log_id. - log_id_t log_id = (log_id_t) *((typeof_log_id_t *) buffer); - if (log_id < 0 || log_id >= LOG_ID_MAX) { + android_log_header_t *header = reinterpret_cast<android_log_header_t *>(buffer); + if (/* header->id < LOG_ID_MIN || */ header->id >= LOG_ID_MAX) { return false; } - char *msg = ((char *)buffer) + sizeof_log_id_t; - n -= sizeof_log_id_t; - - // second element is the thread id of the caller - pid_t tid = (pid_t) *((uint16_t *) msg); - msg += sizeof(uint16_t); - n -= sizeof(uint16_t); - // third element is the realtime at point of caller - log_time realtime(msg); - msg += sizeof(log_time); - n -= sizeof(log_time); + char *msg = ((char *)buffer) + sizeof(android_log_header_t); + n -= sizeof(android_log_header_t); // NB: hdr.msg_flags & MSG_TRUNC is not tested, silently passing a // truncated message to the logs. - logbuf->log(log_id, realtime, cred->uid, cred->pid, tid, msg, - ((size_t) n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX); - reader->notifyNewLog(); + if (logbuf->log((log_id_t)header->id, header->realtime, + cred->uid, cred->pid, header->tid, msg, + ((size_t) n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX) >= 0) { + reader->notifyNewLog(); + } return true; } diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 26df087..745e847 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -37,7 +37,11 @@ void LogReader::notifyNewLog() { } bool LogReader::onDataAvailable(SocketClient *cli) { - prctl(PR_SET_NAME, "logd.reader"); + static bool name_set; + if (!name_set) { + prctl(PR_SET_NAME, "logd.reader"); + name_set = true; + } char buffer[255]; @@ -100,50 +104,51 @@ bool LogReader::onDataAvailable(SocketClient *cli) { nonBlock = true; } - // Convert realtime to monotonic time - if (start == log_time::EPOCH) { - start = LogTimeEntry::EPOCH; - } else { + uint64_t sequence = 1; + // Convert realtime to sequence number + if (start != log_time::EPOCH) { class LogFindStart { const pid_t mPid; const unsigned mLogMask; bool startTimeSet; log_time &start; - log_time last; + uint64_t &sequence; + uint64_t last; public: - LogFindStart(unsigned logMask, pid_t pid, log_time &start) + LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence) : mPid(pid) , mLogMask(logMask) , startTimeSet(false) , start(start) - , last(LogTimeEntry::EPOCH) + , sequence(sequence) + , last(sequence) { } - static bool callback(const LogBufferElement *element, void *obj) { + static int callback(const LogBufferElement *element, void *obj) { LogFindStart *me = reinterpret_cast<LogFindStart *>(obj); - if (!me->startTimeSet - && (!me->mPid || (me->mPid == element->getPid())) + if ((!me->mPid || (me->mPid == element->getPid())) && (me->mLogMask & (1 << element->getLogId()))) { if (me->start == element->getRealTime()) { - me->start = element->getMonotonicTime(); + me->sequence = element->getSequence(); me->startTimeSet = true; + return -1; } else { if (me->start < element->getRealTime()) { - me->start = me->last; + me->sequence = me->last; me->startTimeSet = true; + return -1; } - me->last = element->getMonotonicTime(); + me->last = element->getSequence(); } } return false; } bool found() { return startTimeSet; } - } logFindStart(logMask, pid, start); + } logFindStart(logMask, pid, start, sequence); - logbuf().flushTo(cli, LogTimeEntry::EPOCH, - FlushCommand::hasReadLogs(cli), + logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli), logFindStart.callback, &logFindStart); if (!logFindStart.found()) { @@ -151,12 +156,11 @@ bool LogReader::onDataAvailable(SocketClient *cli) { doSocketDelete(cli); return false; } - log_time now(CLOCK_MONOTONIC); - start = now; + sequence = LogBufferElement::getCurrentSequence(); } } - FlushCommand command(*this, nonBlock, tail, logMask, pid, start); + FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence); command.runSocketCommand(cli); return true; } diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 2a45590..eadc4dd 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -14,9 +14,11 @@ * limitations under the License. */ +#include <algorithm> // std::max #include <fcntl.h> -#include <stdarg.h> -#include <time.h> +#include <stdio.h> +#include <string.h> +#include <unistd.h> #include <log/logger.h> #include <private/android_filesystem_config.h> @@ -24,80 +26,24 @@ #include "LogStatistics.h" -PidStatistics::PidStatistics(pid_t pid, char *name) - : pid(pid) - , mSizesTotal(0) - , mElementsTotal(0) - , mSizes(0) - , mElements(0) - , name(name) - , mGone(false) -{ } - -#ifdef DO_NOT_ERROR_IF_PIDSTATISTICS_USES_A_COPY_CONSTRUCTOR -PidStatistics::PidStatistics(const PidStatistics ©) - : pid(copy->pid) - , name(copy->name ? strdup(copy->name) : NULL) - , mSizesTotal(copy->mSizesTotal) - , mElementsTotal(copy->mElementsTotal) - , mSizes(copy->mSizes) - , mElements(copy->mElements) - , mGone(copy->mGone) -{ } -#endif - -PidStatistics::~PidStatistics() { - free(name); -} - -bool PidStatistics::pidGone() { - if (mGone || (pid == gone)) { - return true; - } - if (pid == 0) { - return false; - } - if (kill(pid, 0) && (errno != EPERM)) { - mGone = true; - return true; +LogStatistics::LogStatistics() + : enable(false) { + log_id_for_each(id) { + mSizes[id] = 0; + mElements[id] = 0; + mSizesTotal[id] = 0; + mElementsTotal[id] = 0; } - return false; -} - -void PidStatistics::setName(char *new_name) { - free(name); - name = new_name; -} - -void PidStatistics::add(unsigned short size) { - mSizesTotal += size; - ++mElementsTotal; - mSizes += size; - ++mElements; } -bool PidStatistics::subtract(unsigned short size) { - mSizes -= size; - --mElements; - return (mElements == 0) && pidGone(); -} - -void PidStatistics::addTotal(size_t size, size_t element) { - if (pid == gone) { - mSizesTotal += size; - mElementsTotal += element; - } -} +namespace android { -// must call free to release return value -// If only we could sniff our own logs for: -// <time> <pid> <pid> E AndroidRuntime: Process: <name>, PID: <pid> -// which debuggerd prints as a process is crashing. -char *PidStatistics::pidToName(pid_t pid) { +// caller must own and free character string +static char *pidToName(pid_t pid) { char *retval = NULL; if (pid == 0) { // special case from auditd for kernel retval = strdup("logd.auditd"); - } else if (pid != gone) { + } else { char buffer[512]; snprintf(buffer, sizeof(buffer), "/proc/%u/cmdline", pid); int fd = open(buffer, O_RDONLY); @@ -116,418 +62,191 @@ char *PidStatistics::pidToName(pid_t pid) { return retval; } -UidStatistics::UidStatistics(uid_t uid) - : uid(uid) - , mSizes(0) - , mElements(0) { - Pids.clear(); } -UidStatistics::~UidStatistics() { - PidStatisticsCollection::iterator it; - for (it = begin(); it != end();) { - delete (*it); - it = erase(it); - } -} +void LogStatistics::add(LogBufferElement *e) { + log_id_t log_id = e->getLogId(); + unsigned short size = e->getMsgLen(); + mSizes[log_id] += size; + ++mElements[log_id]; -void UidStatistics::add(unsigned short size, pid_t pid) { - mSizes += size; - ++mElements; - - PidStatistics *p = NULL; - PidStatisticsCollection::iterator last; - PidStatisticsCollection::iterator it; - for (last = it = begin(); it != end(); last = it, ++it) { - p = *it; - if (pid == p->getPid()) { - p->add(size); - return; - } - } - // insert if the gone entry. - bool insert_before_last = (last != it) && p && (p->getPid() == p->gone); - p = new PidStatistics(pid, pidToName(pid)); - if (insert_before_last) { - insert(last, p); + 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 { - push_back(p); + UidEntry &entry = table.editEntryAt(index); + entry.add(size); + entry.add_dropped(dropped); } - p->add(size); -} -void UidStatistics::subtract(unsigned short size, pid_t pid) { - mSizes -= size; - --mElements; - - PidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - PidStatistics *p = *it; - if (pid == p->getPid()) { - if (p->subtract(size)) { - size_t szsTotal = p->sizesTotal(); - size_t elsTotal = p->elementsTotal(); - delete p; - erase(it); - it = end(); - --it; - if (it == end()) { - p = new PidStatistics(p->gone); - push_back(p); - } else { - p = *it; - if (p->getPid() != p->gone) { - p = new PidStatistics(p->gone); - push_back(p); - } - } - p->addTotal(szsTotal, elsTotal); - } - return; - } - } -} - -void UidStatistics::sort() { - for (bool pass = true; pass;) { - pass = false; - PidStatisticsCollection::iterator it = begin(); - if (it != end()) { - PidStatisticsCollection::iterator lt = it; - PidStatistics *l = (*lt); - while (++it != end()) { - PidStatistics *n = (*it); - if ((n->getPid() != n->gone) && (n->sizes() > l->sizes())) { - pass = true; - erase(it); - insert(lt, n); - it = lt; - n = l; - } - lt = it; - l = n; - } - } - } -} + mSizesTotal[log_id] += size; + ++mElementsTotal[log_id]; -size_t UidStatistics::sizes(pid_t pid) { - if (pid == pid_all) { - return sizes(); + if (!enable) { + return; } - PidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - PidStatistics *p = *it; - if (pid == p->getPid()) { - return p->sizes(); + pid_t pid = e->getPid(); + hash = android::hash_type(pid); + index = pidTable.find(-1, hash, pid); + 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); + if (entry.getUid() != uid) { + entry.setUid(uid); + entry.setName(android::pidToName(pid)); + } else if (!entry.getName()) { + char *name = android::pidToName(pid); + if (name) { + entry.setName(name); + } } + entry.add(size); + entry.add_dropped(dropped); } - return 0; } -size_t UidStatistics::elements(pid_t pid) { - if (pid == pid_all) { - return elements(); - } +void LogStatistics::subtract(LogBufferElement *e) { + log_id_t log_id = e->getLogId(); + unsigned short size = e->getMsgLen(); + mSizes[log_id] -= size; + --mElements[log_id]; - PidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - PidStatistics *p = *it; - if (pid == p->getPid()) { - return p->elements(); + 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) || entry.subtract_dropped(dropped)) { + table.removeAt(index); } } - return 0; -} -size_t UidStatistics::sizesTotal(pid_t pid) { - size_t sizes = 0; - PidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - PidStatistics *p = *it; - if ((pid == pid_all) || (pid == p->getPid())) { - sizes += p->sizesTotal(); - } + if (!enable) { + return; } - return sizes; -} -size_t UidStatistics::elementsTotal(pid_t pid) { - size_t elements = 0; - PidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - PidStatistics *p = *it; - if ((pid == pid_all) || (pid == p->getPid())) { - elements += p->elementsTotal(); + pid_t pid = e->getPid(); + hash = android::hash_type(pid); + index = pidTable.find(-1, hash, pid); + if (index != -1) { + PidEntry &entry = pidTable.editEntryAt(index); + if (entry.subtract(size) || entry.subtract_dropped(dropped)) { + pidTable.removeAt(index); } } - return elements; } -LidStatistics::LidStatistics() { - Uids.clear(); -} +// 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; -LidStatistics::~LidStatistics() { - UidStatisticsCollection::iterator it; - for (it = begin(); it != end();) { - delete (*it); - it = Uids.erase(it); + 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); } -} - -void LidStatistics::add(unsigned short size, uid_t uid, pid_t pid) { - UidStatistics *u; - UidStatisticsCollection::iterator it; - UidStatisticsCollection::iterator last; - if (uid == (uid_t) -1) { // init - uid = (uid_t) AID_ROOT; + if (!enable) { + return; } - for (last = it = begin(); it != end(); last = it, ++it) { - u = *it; - if (uid == u->getUid()) { - u->add(size, pid); - if ((last != it) && ((*last)->sizesTotal() < u->sizesTotal())) { - Uids.erase(it); - Uids.insert(last, u); - } - 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); } - u = new UidStatistics(uid); - if ((last != it) && ((*last)->sizesTotal() < (size_t) size)) { - Uids.insert(last, u); - } else { - Uids.push_back(u); - } - u->add(size, pid); } -void LidStatistics::subtract(unsigned short size, uid_t uid, pid_t pid) { - if (uid == (uid_t) -1) { // init - uid = (uid_t) AID_ROOT; +// caller must own and free character string +char *LogStatistics::uidToName(uid_t uid) { + // Local hard coded favourites + if (uid == AID_LOGD) { + return strdup("auditd"); } - UidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - UidStatistics *u = *it; - if (uid == u->getUid()) { - u->subtract(size, pid); - return; - } - } -} + // Android hard coded + const struct android_id_info *info = android_ids; -void LidStatistics::sort() { - for (bool pass = true; pass;) { - pass = false; - UidStatisticsCollection::iterator it = begin(); - if (it != end()) { - UidStatisticsCollection::iterator lt = it; - UidStatistics *l = (*lt); - while (++it != end()) { - UidStatistics *n = (*it); - if (n->sizes() > l->sizes()) { - pass = true; - Uids.erase(it); - Uids.insert(lt, n); - it = lt; - n = l; - } - lt = it; - l = n; - } + for (size_t i = 0; i < android_id_count; ++i) { + if (info->aid == uid) { + return strdup(info->name); } + ++info; } -} -size_t LidStatistics::sizes(uid_t uid, pid_t pid) { - size_t sizes = 0; - UidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - UidStatistics *u = *it; - if ((uid == uid_all) || (uid == u->getUid())) { - sizes += u->sizes(pid); - } + // Parse /data/system/packages.list + char *name = android::uidToName(uid); + if (name) { + return name; } - return sizes; -} -size_t LidStatistics::elements(uid_t uid, pid_t pid) { - size_t elements = 0; - UidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - UidStatistics *u = *it; - if ((uid == uid_all) || (uid == u->getUid())) { - elements += u->elements(pid); - } - } - return elements; -} + // report uid -> pid(s) -> pidToName if unique + ssize_t index = -1; + while ((index = pidTable.next(index)) != -1) { + const PidEntry &entry = pidTable.entryAt(index); -size_t LidStatistics::sizesTotal(uid_t uid, pid_t pid) { - size_t sizes = 0; - UidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - UidStatistics *u = *it; - if ((uid == uid_all) || (uid == u->getUid())) { - sizes += u->sizesTotal(pid); - } - } - return sizes; -} + if (entry.getUid() == uid) { + const char *n = entry.getName(); -size_t LidStatistics::elementsTotal(uid_t uid, pid_t pid) { - size_t elements = 0; - UidStatisticsCollection::iterator it; - for (it = begin(); it != end(); ++it) { - UidStatistics *u = *it; - if ((uid == uid_all) || (uid == u->getUid())) { - elements += u->elementsTotal(pid); + if (n) { + if (!name) { + name = strdup(n); + } else if (strcmp(name, n)) { + free(name); + return NULL; + } + } } } - return elements; -} - -LogStatistics::LogStatistics() - : mStatistics(false) - , dgramQlenStatistics(false) - , start(CLOCK_MONOTONIC) { - log_id_for_each(i) { - mSizes[i] = 0; - mElements[i] = 0; - } - - for(unsigned short bucket = 0; dgramQlen(bucket); ++bucket) { - mMinimum[bucket].tv_sec = mMinimum[bucket].tv_sec_max; - mMinimum[bucket].tv_nsec = mMinimum[bucket].tv_nsec_max; - } -} -// Each bucket below represents a dgramQlen of log messages. By -// finding the minimum period of time from start to finish -// of each dgramQlen, we can get a performance expectation for -// the user space logger. The net result is that the period -// of time divided by the dgramQlen will give us the average time -// between log messages; at the point where the average time -// is greater than the throughput capability of the logger -// we will not longer require the benefits of the FIFO formed -// by max_dgram_qlen. We will also expect to see a very visible -// knee in the average time between log messages at this point, -// so we do not necessarily have to compare the rate against the -// measured performance (BM_log_maximum_retry) of the logger. -// -// for example (reformatted): -// -// Minimum time between log events per dgramQlen: -// 1 2 3 5 10 20 30 50 100 200 300 400 500 600 -// 5u2 12u 13u 15u 16u 27u 30u 36u 407u 3m1 3m3 3m9 3m9 5m5 -// -// demonstrates a clear knee rising at 100, so this means that for this -// case max_dgram_qlen = 100 would be more than sufficient to handle the -// worst that the system could stuff into the logger. The -// BM_log_maximum_retry performance (derated by the log collection) on the -// same system was 33.2us so we would almost be fine with max_dgram_qlen = 50. -// BM_log_maxumum_retry with statistics off is roughly 20us, so -// max_dgram_qlen = 20 would work. We will be more than willing to have -// a large engineering margin so the rule of thumb that lead us to 100 is -// fine. -// -// bucket dgramQlen are tuned for /proc/sys/net/unix/max_dgram_qlen = 300 -const unsigned short LogStatistics::mBuckets[] = { - 1, 2, 3, 5, 10, 20, 30, 50, 100, 200, 300, 400, 500, 600 -}; - -unsigned short LogStatistics::dgramQlen(unsigned short bucket) { - if (bucket >= sizeof(mBuckets) / sizeof(mBuckets[0])) { - return 0; - } - return mBuckets[bucket]; + // No one + return name; } -unsigned long long LogStatistics::minimum(unsigned short bucket) { - if (mMinimum[bucket].tv_sec == mMinimum[bucket].tv_sec_max) { - return 0; - } - return mMinimum[bucket].nsec(); -} +static void format_line(android::String8 &output, + 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; -void LogStatistics::recordDiff(log_time diff, unsigned short bucket) { - if ((diff.tv_sec || diff.tv_nsec) && (mMinimum[bucket] > diff)) { - mMinimum[bucket] = diff; - } -} + 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); -void LogStatistics::add(unsigned short size, - log_id_t log_id, uid_t uid, pid_t pid) { - mSizes[log_id] += size; - ++mElements[log_id]; - if (!mStatistics) { - return; - } - id(log_id).add(size, uid, pid); -} - -void LogStatistics::subtract(unsigned short size, - log_id_t log_id, uid_t uid, pid_t pid) { - mSizes[log_id] -= size; - --mElements[log_id]; - if (!mStatistics) { - return; - } - id(log_id).subtract(size, uid, pid); -} - -size_t LogStatistics::sizes(log_id_t log_id, uid_t uid, pid_t pid) { - if (log_id != log_id_all) { - return id(log_id).sizes(uid, pid); - } - size_t sizes = 0; - log_id_for_each(i) { - sizes += id(i).sizes(uid, pid); - } - return sizes; -} - -size_t LogStatistics::elements(log_id_t log_id, uid_t uid, pid_t pid) { - if (log_id != log_id_all) { - return id(log_id).elements(uid, pid); - } - size_t elements = 0; - log_id_for_each(i) { - elements += id(i).elements(uid, pid); - } - return elements; -} - -size_t LogStatistics::sizesTotal(log_id_t log_id, uid_t uid, pid_t pid) { - if (log_id != log_id_all) { - return id(log_id).sizesTotal(uid, pid); - } - size_t sizes = 0; - log_id_for_each(i) { - sizes += id(i).sizesTotal(uid, pid); - } - return sizes; -} - -size_t LogStatistics::elementsTotal(log_id_t log_id, uid_t uid, pid_t pid) { - if (log_id != log_id_all) { - return id(log_id).elementsTotal(uid, pid); - } - size_t elements = 0; - log_id_for_each(i) { - elements += id(i).elementsTotal(uid, pid); + 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()); } - return elements; } -void LogStatistics::format(char **buf, - uid_t uid, unsigned int logMask, log_time oldest) { - static const unsigned short spaces_current = 13; +void LogStatistics::format(char **buf, uid_t uid, unsigned int logMask) { static const unsigned short spaces_total = 19; if (*buf) { @@ -535,411 +254,254 @@ void LogStatistics::format(char **buf, *buf = NULL; } - android::String8 string(" span -> size/num"); + // Report on total logging, current and for all time + + android::String8 output("size/num"); size_t oldLength; - short spaces = 2; + short spaces = 1; - log_id_for_each(i) { - if (!(logMask & (1 << i))) { + log_id_for_each(id) { + if (!(logMask & (1 << id))) { continue; } - oldLength = string.length(); + oldLength = output.length(); if (spaces < 0) { spaces = 0; } - string.appendFormat("%*s%s", spaces, "", android_log_id_to_name(i)); - spaces += spaces_total + oldLength - string.length(); + output.appendFormat("%*s%s", spaces, "", android_log_id_to_name(id)); + spaces += spaces_total + oldLength - output.length(); + } - LidStatistics &l = id(i); - l.sort(); + spaces = 4; + output.appendFormat("\nTotal"); - UidStatisticsCollection::iterator iu; - for (iu = l.begin(); iu != l.end(); ++iu) { - (*iu)->sort(); + log_id_for_each(id) { + if (!(logMask & (1 << id))) { + continue; } - } - - spaces = 1; - log_time t(CLOCK_MONOTONIC); - unsigned long long d; - if (mStatistics) { - d = t.nsec() - start.nsec(); - string.appendFormat("\nTotal%4llu:%02llu:%02llu.%09llu", - d / NS_PER_SEC / 60 / 60, (d / NS_PER_SEC / 60) % 60, - (d / NS_PER_SEC) % 60, d % NS_PER_SEC); - - log_id_for_each(i) { - if (!(logMask & (1 << i))) { - continue; - } - oldLength = string.length(); - if (spaces < 0) { - spaces = 0; - } - string.appendFormat("%*s%zu/%zu", spaces, "", - sizesTotal(i), elementsTotal(i)); - spaces += spaces_total + oldLength - string.length(); + oldLength = output.length(); + if (spaces < 0) { + spaces = 0; } - spaces = 1; + output.appendFormat("%*s%zu/%zu", spaces, "", + sizesTotal(id), elementsTotal(id)); + spaces += spaces_total + oldLength - output.length(); } - d = t.nsec() - oldest.nsec(); - string.appendFormat("\nNow%6llu:%02llu:%02llu.%09llu", - d / NS_PER_SEC / 60 / 60, (d / NS_PER_SEC / 60) % 60, - (d / NS_PER_SEC) % 60, d % NS_PER_SEC); + spaces = 6; + output.appendFormat("\nNow"); - log_id_for_each(i) { - if (!(logMask & (1 << i))) { + log_id_for_each(id) { + if (!(logMask & (1 << id))) { continue; } - size_t els = elements(i); + size_t els = elements(id); if (els) { - oldLength = string.length(); + oldLength = output.length(); if (spaces < 0) { spaces = 0; } - string.appendFormat("%*s%zu/%zu", spaces, "", sizes(i), els); - spaces -= string.length() - oldLength; + output.appendFormat("%*s%zu/%zu", spaces, "", sizes(id), els); + spaces -= output.length() - oldLength; } spaces += spaces_total; } - // Construct list of worst spammers by Pid - static const unsigned char num_spammers = 10; - bool header = false; + // Report on Chattiest - log_id_for_each(i) { - if (!(logMask & (1 << i))) { + // Chattiest by application (UID) + static const size_t maximum_sorted_entries = 32; + log_id_for_each(id) { + if (!(logMask & (1 << id))) { continue; } - PidStatisticsCollection pids; - pids.clear(); - - LidStatistics &l = id(i); - UidStatisticsCollection::iterator iu; - for (iu = l.begin(); iu != l.end(); ++iu) { - UidStatistics &u = *(*iu); - PidStatisticsCollection::iterator ip; - for (ip = u.begin(); ip != u.end(); ++ip) { - PidStatistics *p = (*ip); - if (p->getPid() == p->gone) { - break; - } + bool headerPrinted = false; + std::unique_ptr<const UidEntry *[]> sorted = sort(maximum_sorted_entries, id); + ssize_t index = -1; + while ((index = uidTable_t::next(index, sorted, maximum_sorted_entries)) >= 0) { + const UidEntry *entry = sorted[index]; + uid_t u = entry->getKey(); + if ((uid != AID_ROOT) && (u != uid)) { + continue; + } - size_t mySizes = p->sizes(); - - PidStatisticsCollection::iterator q; - unsigned char num = 0; - for (q = pids.begin(); q != pids.end(); ++q) { - if (mySizes > (*q)->sizes()) { - pids.insert(q, p); - break; - } - // do we need to traverse deeper in the list? - if (++num > num_spammers) { - break; - } + if (!headerPrinted) { + output.appendFormat("\n\n"); + android::String8 name(""); + if (uid == AID_ROOT) { + name.appendFormat( + "Chattiest UIDs in %s log buffer:", + android_log_id_to_name(id)); + } else { + name.appendFormat( + "Logging for your UID in %s log buffer:", + android_log_id_to_name(id)); } - if (q == pids.end()) { - pids.push_back(p); + android::String8 size("Size"); + android::String8 pruned("Pruned"); + if (!worstUidEnabledForLogid(id)) { + pruned.setTo(""); } - } - } - - size_t threshold = sizes(i); - if (threshold < 65536) { - threshold = 65536; - } - threshold /= 100; - - PidStatisticsCollection::iterator pt = pids.begin(); - - for(int line = 0; - (pt != pids.end()) && (line < num_spammers); - ++line, pt = pids.erase(pt)) { - PidStatistics *p = *pt; + format_line(output, name, size, pruned); - size_t sizes = p->sizes(); - if (sizes < threshold) { - break; - } - - char *name = p->getName(); - pid_t pid = p->getPid(); - if (!name || !*name) { - name = pidToName(pid); - if (name) { - if (*name) { - p->setName(name); - } else { - free(name); - name = NULL; - } + name.setTo("UID PACKAGE"); + size.setTo("BYTES"); + pruned.setTo("LINES"); + if (!worstUidEnabledForLogid(id)) { + pruned.setTo(""); } - } + format_line(output, name, size, pruned); - if (!header) { - string.appendFormat("\n\nChattiest clients:\n" - "log id %-*s PID[?] name", - spaces_total, "size/total"); - header = true; + headerPrinted = true; } - size_t sizesTotal = p->sizesTotal(); - - android::String8 sz(""); - sz.appendFormat((sizes != sizesTotal) ? "%zu/%zu" : "%zu", - sizes, sizesTotal); - - android::String8 pd(""); - pd.appendFormat("%u%c", pid, p->pidGone() ? '?' : ' '); - - string.appendFormat("\n%-7s%-*s %-7s%s", - line ? "" : android_log_id_to_name(i), - spaces_total, sz.string(), pd.string(), - name ? name : ""); - } + android::String8 name(""); + name.appendFormat("%u", u); + char *n = uidToName(u); + if (n) { + name.appendFormat("%*s%s", (int)std::max(6 - name.length(), (size_t)1), "", n); + free(n); + } - pids.clear(); - } + android::String8 size(""); + size.appendFormat("%zu", entry->getSizes()); - if (dgramQlenStatistics) { - const unsigned short spaces_time = 6; - const unsigned long long max_seconds = 100000; - spaces = 0; - string.append("\n\nMinimum time between log events per max_dgram_qlen:\n"); - for(unsigned short i = 0; dgramQlen(i); ++i) { - oldLength = string.length(); - if (spaces < 0) { - spaces = 0; + android::String8 pruned(""); + size_t dropped = entry->getDropped(); + if (dropped) { + pruned.appendFormat("%zu", dropped); } - string.appendFormat("%*s%u", spaces, "", dgramQlen(i)); - spaces += spaces_time + oldLength - string.length(); - } - string.append("\n"); - spaces = 0; - unsigned short n; - for(unsigned short i = 0; (n = dgramQlen(i)); ++i) { - unsigned long long duration = minimum(i); - if (duration) { - duration /= n; - if (duration >= (NS_PER_SEC * max_seconds)) { - duration = NS_PER_SEC * (max_seconds - 1); - } - oldLength = string.length(); - if (spaces < 0) { - spaces = 0; - } - string.appendFormat("%*s", spaces, ""); - if (duration >= (NS_PER_SEC * 10)) { - string.appendFormat("%llu", - (duration + (NS_PER_SEC / 2)) - / NS_PER_SEC); - } else if (duration >= (NS_PER_SEC / (1000 / 10))) { - string.appendFormat("%llum", - (duration + (NS_PER_SEC / 2 / 1000)) - / (NS_PER_SEC / 1000)); - } else if (duration >= (NS_PER_SEC / (1000000 / 10))) { - string.appendFormat("%lluu", - (duration + (NS_PER_SEC / 2 / 1000000)) - / (NS_PER_SEC / 1000000)); - } else { - string.appendFormat("%llun", duration); - } - spaces -= string.length() - oldLength; - } - spaces += spaces_time; - } - } - log_id_for_each(i) { - if (!(logMask & (1 << i))) { - continue; + format_line(output, name, size, pruned); } + } - header = false; - bool first = true; - - UidStatisticsCollection::iterator ut; - for(ut = id(i).begin(); ut != id(i).end(); ++ut) { - UidStatistics *up = *ut; - if ((uid != AID_ROOT) && (uid != up->getUid())) { - continue; - } - - PidStatisticsCollection::iterator pt = up->begin(); - if (pt == up->end()) { + if (enable) { + bool headerPrinted = false; + std::unique_ptr<const PidEntry *[]> sorted = pidTable.sort(maximum_sorted_entries); + ssize_t index = -1; + while ((index = pidTable.next(index, sorted, maximum_sorted_entries)) >= 0) { + const PidEntry *entry = sorted[index]; + uid_t u = entry->getUid(); + if ((uid != AID_ROOT) && (u != uid)) { continue; } - android::String8 intermediate; - - if (!header) { - // header below tuned to match spaces_total and spaces_current - spaces = 0; - intermediate = string.format("%s: UID/PID Total size/num", - android_log_id_to_name(i)); - string.appendFormat("\n\n%-31sNow " - "UID/PID[?] Total Now", - intermediate.string()); - intermediate.clear(); - header = true; - } + if (!headerPrinted) { + output.appendFormat("\n\n"); + android::String8 name(""); + if (uid == AID_ROOT) { + name.appendFormat("Chattiest PIDs:"); + } else { + name.appendFormat("Logging for this PID:"); + } + android::String8 size("Size"); + android::String8 pruned("Pruned"); + format_line(output, name, size, pruned); - bool oneline = ++pt == up->end(); - --pt; + name.setTo(" PID/UID COMMAND LINE"); + size.setTo("BYTES"); + pruned.setTo("LINES"); + format_line(output, name, size, pruned); - if (!oneline) { - first = true; - } else if (!first && (spaces > 0)) { - string.appendFormat("%*s", spaces, ""); + headerPrinted = true; } - spaces = 0; - uid_t u = up->getUid(); - PidStatistics *pp = *pt; - pid_t p = pp->getPid(); - - intermediate = string.format(oneline - ? ((p == PidStatistics::gone) - ? "%d/?" - : "%d/%d%c") - : "%d", - u, p, pp->pidGone() ? '?' : '\0'); - string.appendFormat(first ? "\n%-12s" : "%-12s", - intermediate.string()); - intermediate.clear(); - - size_t elsTotal = up->elementsTotal(); - oldLength = string.length(); - string.appendFormat("%zu/%zu", up->sizesTotal(), elsTotal); - spaces += spaces_total + oldLength - string.length(); - - size_t els = up->elements(); - if (els == elsTotal) { - if (spaces < 0) { - spaces = 0; - } - string.appendFormat("%*s=", spaces, ""); - spaces = -1; - } else if (els) { - oldLength = string.length(); - if (spaces < 0) { - spaces = 0; + android::String8 name(""); + name.appendFormat("%5u/%u", entry->getKey(), u); + const char *n = entry->getName(); + if (n) { + name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", n); + } else { + char *un = uidToName(u); + if (un) { + name.appendFormat("%*s%s", (int)std::max(12 - name.length(), (size_t)1), "", un); + free(un); } - string.appendFormat("%*s%zu/%zu", spaces, "", up->sizes(), els); - spaces -= string.length() - oldLength; } - spaces += spaces_current; - first = !first; + android::String8 size(""); + size.appendFormat("%zu", entry->getSizes()); - if (oneline) { - continue; + android::String8 pruned(""); + size_t dropped = entry->getDropped(); + if (dropped) { + pruned.appendFormat("%zu", dropped); } - size_t gone_szs = 0; - size_t gone_els = 0; - - for(; pt != up->end(); ++pt) { - pp = *pt; - p = pp->getPid(); - - // If a PID no longer has any current logs, and is not - // active anymore, skip & report totals for gone. - elsTotal = pp->elementsTotal(); - size_t szsTotal = pp->sizesTotal(); - if (p == pp->gone) { - gone_szs += szsTotal; - gone_els += elsTotal; - continue; - } - els = pp->elements(); - bool gone = pp->pidGone(); - if (gone && (els == 0)) { - // ToDo: garbage collection: move this statistical bucket - // from its current UID/PID to UID/? (races and - // wrap around are our achilles heel). Below is - // merely lipservice to catch PIDs that were still - // around when the stats were pruned to zero. - gone_szs += szsTotal; - gone_els += elsTotal; - continue; - } + format_line(output, name, size, pruned); + } + } - if (!first && (spaces > 0)) { - string.appendFormat("%*s", spaces, ""); - } - spaces = 0; + *buf = strdup(output.string()); +} - intermediate = string.format(gone ? "%d/%d?" : "%d/%d", u, p); - string.appendFormat(first ? "\n%-12s" : "%-12s", - intermediate.string()); - intermediate.clear(); - - oldLength = string.length(); - string.appendFormat("%zu/%zu", szsTotal, elsTotal); - spaces += spaces_total + oldLength - string.length(); - - if (els == elsTotal) { - if (spaces < 0) { - spaces = 0; - } - string.appendFormat("%*s=", spaces, ""); - spaces = -1; - } else if (els) { - oldLength = string.length(); - if (spaces < 0) { - spaces = 0; - } - string.appendFormat("%*s%zu/%zu", spaces, "", - pp->sizes(), els); - spaces -= string.length() - oldLength; - } - spaces += spaces_current; +namespace android { - first = !first; +uid_t pidToUid(pid_t pid) { + char buffer[512]; + snprintf(buffer, sizeof(buffer), "/proc/%u/status", pid); + FILE *fp = fopen(buffer, "r"); + if (fp) { + while (fgets(buffer, sizeof(buffer), fp)) { + int uid; + if (sscanf(buffer, "Uid: %d", &uid) == 1) { + fclose(fp); + return uid; } + } + fclose(fp); + } + return AID_LOGD; // associate this with the logger +} - if (gone_els) { - if (!first && (spaces > 0)) { - string.appendFormat("%*s", spaces, ""); - } - - intermediate = string.format("%d/?", u); - string.appendFormat(first ? "\n%-12s" : "%-12s", - intermediate.string()); - intermediate.clear(); - - spaces = spaces_total + spaces_current; - - oldLength = string.length(); - string.appendFormat("%zu/%zu", gone_szs, gone_els); - spaces -= string.length() - oldLength; +} - first = !first; +uid_t LogStatistics::pidToUid(pid_t pid) { + uid_t uid; + android::hash_t hash = android::hash_type(pid); + ssize_t index = pidTable.find(-1, hash, pid); + if (index == -1) { + uid = android::pidToUid(pid); + PidEntry initEntry(pid, uid, android::pidToName(pid)); + pidTable.add(hash, initEntry); + } else { + PidEntry &entry = pidTable.editEntryAt(index); + if (!entry.getName()) { + char *name = android::pidToName(pid); + if (name) { + entry.setName(name); } } + uid = entry.getUid(); } - - *buf = strdup(string.string()); + return uid; } -uid_t LogStatistics::pidToUid(pid_t pid) { - log_id_for_each(i) { - LidStatistics &l = id(i); - UidStatisticsCollection::iterator iu; - for (iu = l.begin(); iu != l.end(); ++iu) { - UidStatistics &u = *(*iu); - PidStatisticsCollection::iterator ip; - for (ip = u.begin(); ip != u.end(); ++ip) { - if ((*ip)->getPid() == pid) { - return u.getUid(); - } +// caller must free character string +char *LogStatistics::pidToName(pid_t pid) { + char *name; + + android::hash_t hash = android::hash_type(pid); + ssize_t index = pidTable.find(-1, hash, pid); + if (index == -1) { + name = android::pidToName(pid); + PidEntry initEntry(pid, android::pidToUid(pid), name ? strdup(name) : NULL); + pidTable.add(hash, initEntry); + } else { + PidEntry &entry = pidTable.editEntryAt(index); + const char *n = entry.getName(); + if (n) { + name = strdup(n); + } else { + name = android::pidToName(pid); + if (name) { + entry.setName(strdup(name)); } } } - return getuid(); // associate this with the logger + + return name; } diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index f6c4329..f3110d7 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -17,183 +17,153 @@ #ifndef _LOGD_LOG_STATISTICS_H__ #define _LOGD_LOG_STATISTICS_H__ +#include <memory> +#include <stdlib.h> #include <sys/types.h> #include <log/log.h> -#include <log/log_read.h> -#include <utils/List.h> +#include <utils/BasicHashtable.h> + +#include "LogBufferElement.h" #define log_id_for_each(i) \ for (log_id_t i = LOG_ID_MIN; i < LOG_ID_MAX; i = (log_id_t) (i + 1)) -class PidStatistics { - const pid_t pid; - - // Total - size_t mSizesTotal; - size_t mElementsTotal; - // Current - size_t mSizes; - size_t mElements; - - char *name; - bool mGone; - +template <typename TKey, typename TEntry> +class LogHashtable : public android::BasicHashtable<TKey, TEntry> { public: - static const pid_t gone = (pid_t) -1; - - PidStatistics(pid_t pid, char *name = NULL); - PidStatistics(const PidStatistics ©); - ~PidStatistics(); - - pid_t getPid() const { return pid; } - bool pidGone(); - char *getName() const { return name; } - void setName(char *name); - - void add(unsigned short size); - bool subtract(unsigned short size); // returns true if stats and PID gone - void addTotal(size_t size, size_t element); - - size_t sizes() const { return mSizes; } - size_t elements() const { return mElements; } - - size_t sizesTotal() const { return mSizesTotal; } - size_t elementsTotal() const { return mElementsTotal; } - - // helper - static char *pidToName(pid_t pid); + std::unique_ptr<const TEntry *[]> sort(size_t n) { + if (!n) { + std::unique_ptr<const TEntry *[]> sorted(NULL); + return sorted; + } + + const TEntry **retval = new const TEntry* [n]; + memset(retval, 0, sizeof(*retval) * n); + + ssize_t index = -1; + while ((index = android::BasicHashtable<TKey, TEntry>::next(index)) >= 0) { + const TEntry &entry = android::BasicHashtable<TKey, TEntry>::entryAt(index); + size_t s = entry.getSizes(); + ssize_t i = n - 1; + while ((!retval[i] || (s > retval[i]->getSizes())) && (--i >= 0)) + ; + if (++i < (ssize_t)n) { + size_t b = n - i - 1; + if (b) { + memmove(&retval[i+1], &retval[i], b * sizeof(retval[0])); + } + retval[i] = &entry; + } + } + std::unique_ptr<const TEntry *[]> sorted(retval); + return sorted; + } + + // Iteration handler for the sort method output + static ssize_t next(ssize_t index, std::unique_ptr<const TEntry *[]> &sorted, size_t n) { + ++index; + if (!sorted.get() || (index < 0) || (n <= (size_t)index) || !sorted[index] + || (sorted[index]->getSizes() <= (sorted[0]->getSizes() / 100))) { + return -1; + } + return index; + } + + ssize_t next(ssize_t index) { + return android::BasicHashtable<TKey, TEntry>::next(index); + } }; -typedef android::List<PidStatistics *> PidStatisticsCollection; - -class UidStatistics { +struct UidEntry { const uid_t uid; + size_t size; + size_t dropped; - PidStatisticsCollection Pids; - - void insert(PidStatisticsCollection::iterator i, PidStatistics *p) - { Pids.insert(i, p); } - void push_back(PidStatistics *p) { Pids.push_back(p); } - - size_t mSizes; - size_t mElements; - -public: - UidStatistics(uid_t uid); - ~UidStatistics(); - - PidStatisticsCollection::iterator begin() { return Pids.begin(); } - PidStatisticsCollection::iterator end() { return Pids.end(); } - PidStatisticsCollection::iterator erase(PidStatisticsCollection::iterator i) - { return Pids.erase(i); } - - uid_t getUid() { return uid; } + UidEntry(uid_t uid):uid(uid),size(0),dropped(0) { } - void add(unsigned short size, pid_t pid); - void subtract(unsigned short size, pid_t pid); - void sort(); + inline const uid_t&getKey() const { return uid; } + size_t getSizes() const { return size; } + size_t getDropped() const { return dropped; } - static const pid_t pid_all = (pid_t) -1; - - // fast track current value - size_t sizes() const { return mSizes; }; - size_t elements() const { return mElements; }; - - // statistical track - size_t sizes(pid_t pid); - size_t elements(pid_t pid); - - size_t sizesTotal(pid_t pid = pid_all); - size_t elementsTotal(pid_t pid = pid_all); - - // helper - static char *pidToName(pid_t pid) { return PidStatistics::pidToName(pid); } + inline void add(size_t s) { size += s; } + 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; } }; -typedef android::List<UidStatistics *> UidStatisticsCollection; - -class LidStatistics { - UidStatisticsCollection Uids; - -public: - LidStatistics(); - ~LidStatistics(); - - UidStatisticsCollection::iterator begin() { return Uids.begin(); } - UidStatisticsCollection::iterator end() { return Uids.end(); } - - void add(unsigned short size, uid_t uid, pid_t pid); - void subtract(unsigned short size, uid_t uid, pid_t pid); - void sort(); - - static const pid_t pid_all = (pid_t) -1; - static const uid_t uid_all = (uid_t) -1; - - size_t sizes(uid_t uid = uid_all, pid_t pid = pid_all); - size_t elements(uid_t uid = uid_all, pid_t pid = pid_all); - - size_t sizesTotal(uid_t uid = uid_all, pid_t pid = pid_all); - size_t elementsTotal(uid_t uid = uid_all, pid_t pid = pid_all); +struct PidEntry { + const pid_t pid; + 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),dropped(0) { } + PidEntry(const PidEntry &c): + pid(c.pid), + uid(c.uid), + name(c.name ? strdup(c.name) : NULL), + size(c.size), + dropped(c.dropped) { } + ~PidEntry() { free(name); } + + const pid_t&getKey() const { return pid; } + const uid_t&getUid() const { return uid; } + uid_t&setUid(uid_t u) { return uid = u; } + 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 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 class LogStatistics { - LidStatistics LogIds[LOG_ID_MAX]; - size_t mSizes[LOG_ID_MAX]; size_t mElements[LOG_ID_MAX]; + size_t mSizesTotal[LOG_ID_MAX]; + size_t mElementsTotal[LOG_ID_MAX]; + bool enable; - bool mStatistics; - bool dgramQlenStatistics; + // uid to size list + typedef LogHashtable<uid_t, UidEntry> uidTable_t; + uidTable_t uidTable[LOG_ID_MAX]; - static const unsigned short mBuckets[14]; - log_time mMinimum[sizeof(mBuckets) / sizeof(mBuckets[0])]; + // pid to uid list + typedef LogHashtable<pid_t, PidEntry> pidTable_t; + pidTable_t pidTable; public: - const log_time start; - LogStatistics(); - LidStatistics &id(log_id_t log_id) { return LogIds[log_id]; } + void enableStatistics() { enable = true; } - void enableDgramQlenStatistics() { dgramQlenStatistics = true; } - void enableStatistics() { mStatistics = true; } - static unsigned short dgramQlen(unsigned short bucket); - unsigned long long minimum(unsigned short bucket); - void recordDiff(log_time diff, unsigned short bucket); + 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()]; } - void add(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid); - void subtract(unsigned short size, log_id_t log_id, uid_t uid, pid_t pid); - void sort(); + std::unique_ptr<const UidEntry *[]> sort(size_t n, log_id i) { return uidTable[i].sort(n); } // fast track current value by id only size_t sizes(log_id_t id) const { return mSizes[id]; } size_t elements(log_id_t id) const { return mElements[id]; } - - // statistical track - static const log_id_t log_id_all = (log_id_t) -1; - static const uid_t uid_all = (uid_t) -1; - static const pid_t pid_all = (pid_t) -1; - - size_t sizes(log_id_t id, uid_t uid, pid_t pid = pid_all); - size_t elements(log_id_t id, uid_t uid, pid_t pid = pid_all); - size_t sizes() { return sizes(log_id_all, uid_all); } - size_t elements() { return elements(log_id_all, uid_all); } - - size_t sizesTotal(log_id_t id = log_id_all, - uid_t uid = uid_all, - pid_t pid = pid_all); - size_t elementsTotal(log_id_t id = log_id_all, - uid_t uid = uid_all, - pid_t pid = pid_all); + size_t sizesTotal(log_id_t id) const { return mSizesTotal[id]; } + size_t elementsTotal(log_id_t id) const { return mElementsTotal[id]; } // *strp = malloc, balance with free - void format(char **strp, uid_t uid, unsigned int logMask, log_time oldest); + void format(char **strp, uid_t uid, unsigned int logMask); // helper - static char *pidToName(pid_t pid) { return PidStatistics::pidToName(pid); } + char *pidToName(pid_t pid); uid_t pidToUid(pid_t pid); + char *uidToName(uid_t uid); }; #endif // _LOGD_LOG_STATISTICS_H__ diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index ea4e8c8..1b60b7e 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -23,12 +23,10 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER; -const struct timespec LogTimeEntry::EPOCH = { 0, 1 }; - LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - log_time start) + uint64_t start) : mRefCount(1) , mRelease(false) , mError(false) @@ -36,16 +34,16 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, , mReader(reader) , mLogMask(logMask) , mPid(pid) - , skipAhead(0) , mCount(0) , mTail(tail) , mIndex(0) , mClient(client) , mStart(start) , mNonBlock(nonBlock) - , mEnd(CLOCK_MONOTONIC) + , mEnd(LogBufferElement::getCurrentSequence()) { pthread_cond_init(&threadTriggeredCondition, NULL); + cleanSkip_Locked(); } void LogTimeEntry::startReader_Locked(void) { @@ -129,7 +127,7 @@ void *LogTimeEntry::threadStart(void *obj) { lock(); while (me->threadRunning && !me->isError_Locked()) { - log_time start = me->mStart; + uint64_t start = me->mStart; unlock(); @@ -148,6 +146,8 @@ void *LogTimeEntry::threadStart(void *obj) { break; } + me->cleanSkip_Locked(); + pthread_cond_wait(&me->threadTriggeredCondition, ×Lock); } @@ -159,17 +159,17 @@ void *LogTimeEntry::threadStart(void *obj) { } // A first pass to count the number of elements -bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { +int LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { LogTimeEntry *me = reinterpret_cast<LogTimeEntry *>(obj); LogTimeEntry::lock(); if (me->mCount == 0) { - me->mStart = element->getMonotonicTime(); + me->mStart = element->getSequence(); } if ((!me->mPid || (me->mPid == element->getPid())) - && (me->mLogMask & (1 << element->getLogId()))) { + && (me->isWatching(element->getLogId()))) { ++me->mCount; } @@ -179,24 +179,24 @@ bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { } // A second pass to send the selected elements -bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) { +int LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) { LogTimeEntry *me = reinterpret_cast<LogTimeEntry *>(obj); LogTimeEntry::lock(); - if (me->skipAhead) { - me->skipAhead--; + me->mStart = element->getSequence(); + + if (me->skipAhead[element->getLogId()]) { + me->skipAhead[element->getLogId()]--; goto skip; } - me->mStart = element->getMonotonicTime(); - // Truncate to close race between first and second pass if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) { - goto skip; + goto stop; } - if ((me->mLogMask & (1 << element->getLogId())) == 0) { + if (!me->isWatching(element->getLogId())) { goto skip; } @@ -205,7 +205,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) } if (me->isError_Locked()) { - goto skip; + goto stop; } if (!me->mTail) { @@ -223,7 +223,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) } ok: - if (!me->skipAhead) { + if (!me->skipAhead[element->getLogId()]) { LogTimeEntry::unlock(); return true; } @@ -232,4 +232,14 @@ ok: skip: LogTimeEntry::unlock(); return false; + +stop: + LogTimeEntry::unlock(); + return -1; +} + +void LogTimeEntry::cleanSkip_Locked(void) { + for (log_id_t i = LOG_ID_MIN; i < LOG_ID_MAX; i = (log_id_t) (i + 1)) { + skipAhead[i] = 0; + } } diff --git a/logd/LogTimes.h b/logd/LogTimes.h index 0bfa7a2..ae2f92b 100644 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -22,6 +22,7 @@ #include <sys/types.h> #include <sysutils/SocketClient.h> #include <utils/List.h> +#include <log/log.h> class LogReader; @@ -38,7 +39,7 @@ class LogTimeEntry { static void threadStop(void *me); const unsigned int mLogMask; const pid_t mPid; - unsigned int skipAhead; + unsigned int skipAhead[LOG_ID_MAX]; unsigned long mCount; unsigned long mTail; unsigned long mIndex; @@ -46,13 +47,12 @@ class LogTimeEntry { public: LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - log_time start); + uint64_t start); SocketClient *mClient; - static const struct timespec EPOCH; - log_time mStart; + uint64_t mStart; const bool mNonBlock; - const log_time mEnd; // only relevant if mNonBlock + const uint64_t mEnd; // only relevant if mNonBlock // Protect List manipulations static void lock(void) { pthread_mutex_lock(×Lock); } @@ -67,7 +67,8 @@ public: pthread_cond_signal(&threadTriggeredCondition); } - void triggerSkip_Locked(unsigned int skip) { skipAhead = skip; } + void triggerSkip_Locked(log_id_t id, unsigned int skip) { skipAhead[id] = skip; } + void cleanSkip_Locked(void); // Called after LogTimeEntry removed from list, lock implicitly held void release_Locked(void) { @@ -99,10 +100,10 @@ public: // No one else is holding a reference to this delete this; } - + bool isWatching(log_id_t id) { return (mLogMask & (1<<id)) != 0; } // flushTo filter callbacks - static bool FilterFirstPass(const LogBufferElement *element, void *me); - static bool FilterSecondPass(const LogBufferElement *element, void *me); + static int FilterFirstPass(const LogBufferElement *element, void *me); + static int FilterSecondPass(const LogBufferElement *element, void *me); }; typedef android::List<LogTimeEntry *> LastLogTimes; diff --git a/logd/LogWhiteBlackList.cpp b/logd/LogWhiteBlackList.cpp index e87b604..bee940d 100644 --- a/logd/LogWhiteBlackList.cpp +++ b/logd/LogWhiteBlackList.cpp @@ -39,15 +39,20 @@ int Prune::cmp(uid_t uid, pid_t pid) const { void Prune::format(char **strp) { if (mUid != uid_all) { - asprintf(strp, (mPid != pid_all) ? "%u/%u" : "%u", mUid, mPid); - } else { - // NB: mPid == pid_all can not happen if mUid == uid_all - asprintf(strp, (mPid != pid_all) ? "/%u" : "/", mPid); + if (mPid != pid_all) { + asprintf(strp, "%u/%u", mUid, mPid); + } else { + asprintf(strp, "%u", mUid); + } + } else if (mPid != pid_all) { + asprintf(strp, "/%u", mPid); + } else { // NB: mPid == pid_all can not happen if mUid == uid_all + asprintf(strp, "/"); } } PruneList::PruneList() - : mWorstUidEnabled(false) { + : mWorstUidEnabled(true) { mNaughty.clear(); mNice.clear(); } @@ -65,7 +70,7 @@ PruneList::~PruneList() { } int PruneList::init(char *str) { - mWorstUidEnabled = false; + mWorstUidEnabled = true; PruneCollection::iterator it; for (it = mNice.begin(); it != mNice.end();) { delete (*it); diff --git a/logd/LogWhiteBlackList.h b/logd/LogWhiteBlackList.h index 769d651..5f60801 100644 --- a/logd/LogWhiteBlackList.h +++ b/logd/LogWhiteBlackList.h @@ -61,7 +61,9 @@ public: int init(char *str); bool naughty(LogBufferElement *element); + bool naughty(void) { return !mNaughty.empty(); } bool nice(LogBufferElement *element); + bool nice(void) { return !mNice.empty(); } bool worstUidEnabled() const { return mWorstUidEnabled; } // *strp is malloc'd, use free to release diff --git a/logd/README.property b/logd/README.property index b7fcece..60542b2 100644 --- a/logd/README.property +++ b/logd/README.property @@ -7,12 +7,6 @@ logd.auditd.dmesg bool true selinux audit messages duplicated and logd.statistics bool depends Enable logcat -S statistics. ro.config.low_ram bool false if true, logd.statistics default false ro.build.type string if user, logd.statistics default false -logd.statistics.dgram_qlen bool false Record dgram_qlen statistics. This - represents a performance impact and - is used to determine the platform's - minimum domain socket network FIFO - size (see source for details) based - on typical load (logcat -S to view) persist.logd.size number 256K default size of the buffer for all log ids at initial startup, at runtime use: logcat -b all -G <value> 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) diff --git a/logd/libaudit.c b/logd/libaudit.c index d00d579..cf76305 100644 --- a/logd/libaudit.c +++ b/logd/libaudit.c @@ -177,7 +177,7 @@ int audit_setup(int fd, uint32_t pid) */ status.pid = pid; status.mask = AUDIT_STATUS_PID | AUDIT_STATUS_RATE_LIMIT; - status.rate_limit = 20; // audit entries per second + status.rate_limit = 5; // audit entries per second /* Let the kernel know this pid will be registering for audit events */ rc = audit_send(fd, AUDIT_SET, &status, sizeof(status)); diff --git a/logd/main.cpp b/logd/main.cpp index 54da7e3..eb29596 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -17,24 +17,37 @@ #include <dirent.h> #include <errno.h> #include <fcntl.h> +#include <poll.h> #include <sched.h> +#include <semaphore.h> +#include <signal.h> #include <stdio.h> #include <stdlib.h> #include <string.h> #include <sys/capability.h> +#include <sys/klog.h> #include <sys/prctl.h> #include <sys/stat.h> #include <sys/types.h> +#include <syslog.h> #include <unistd.h> #include <cutils/properties.h> +#include <cutils/sched_policy.h> +#include <cutils/sockets.h> +#include <private/android_filesystem_config.h> -#include "private/android_filesystem_config.h" #include "CommandListener.h" #include "LogBuffer.h" #include "LogListener.h" #include "LogAudit.h" +#define KMSG_PRIORITY(PRI) \ + '<', \ + '0' + LOG_MAKEPRI(LOG_DAEMON, LOG_PRI(PRI)) / 10, \ + '0' + LOG_MAKEPRI(LOG_DAEMON, LOG_PRI(PRI)) % 10, \ + '>' + // // The service is designed to be run by init, it does not respond well // to starting up manually. When starting up manually the sockets will @@ -68,6 +81,10 @@ static int drop_privs() { struct sched_param param; memset(¶m, 0, sizeof(param)); + if (set_sched_policy(0, SP_BACKGROUND) < 0) { + return -1; + } + if (sched_setscheduler((pid_t) 0, SCHED_BATCH, ¶m) < 0) { return -1; } @@ -121,17 +138,161 @@ static bool property_get_bool(const char *key, bool def) { return def; } -// Foreground waits for exit of the three main persistent threads that -// are started here. The three threads are created to manage UNIX -// domain client sockets for writing, reading and controlling the user -// space logger. Additional transitory per-client threads are created -// for each reader once they register. -int main() { - bool auditd = property_get_bool("logd.auditd", true); +// Remove the static, and use this variable +// globally for debugging if necessary. eg: +// write(fdDmesg, "I am here\n", 10); +static int fdDmesg = -1; + +static sem_t uidName; +static uid_t uid; +static char *name; + +static sem_t reinit; +static bool reinit_running = false; +static LogBuffer *logBuf = NULL; + +static void *reinit_thread_start(void * /*obj*/) { + prctl(PR_SET_NAME, "logd.daemon"); + set_sched_policy(0, SP_BACKGROUND); + + setgid(AID_SYSTEM); + setuid(AID_SYSTEM); + + while (reinit_running && !sem_wait(&reinit) && reinit_running) { + + // uidToName Privileged Worker + if (uid) { + name = NULL; + + FILE *fp = fopen("/data/system/packages.list", "r"); + if (fp) { + // This simple parser is sensitive to format changes in + // frameworks/base/services/core/java/com/android/server/pm/Settings.java + // A dependency note has been added to that file to correct + // this parser. + + char *buffer = NULL; + size_t len; + while (getline(&buffer, &len, fp) > 0) { + char *userId = strchr(buffer, ' '); + if (!userId) { + continue; + } + *userId = '\0'; + unsigned long value = strtoul(userId + 1, NULL, 10); + if (value != uid) { + continue; + } + name = strdup(buffer); + break; + } + free(buffer); + fclose(fp); + } + uid = 0; + sem_post(&uidName); + continue; + } - int fdDmesg = -1; - if (auditd && property_get_bool("logd.auditd.dmesg", true)) { - fdDmesg = open("/dev/kmsg", O_WRONLY); + if (fdDmesg >= 0) { + static const char reinit_message[] = { KMSG_PRIORITY(LOG_INFO), + 'l', 'o', 'g', 'd', '.', 'd', 'a', 'e', 'm', 'o', 'n', ':', + ' ', 'r', 'e', 'i', 'n', 'i', 't', '\n' }; + write(fdDmesg, reinit_message, sizeof(reinit_message)); + } + + // Anything that reads persist.<property> + if (logBuf) { + logBuf->init(); + } + } + + return NULL; +} + +char *android::uidToName(uid_t u) { + if (!u || !reinit_running) { + return NULL; + } + + // Not multi-thread safe, we know there is only one caller + uid = u; + + name = NULL; + sem_post(&reinit); + sem_wait(&uidName); + return name; +} + +// Serves as a global method to trigger reinitialization +// and as a function that can be provided to signal(). +void reinit_signal_handler(int /*signal*/) { + sem_post(&reinit); +} + +// Foreground waits for exit of the main persistent threads +// that are started here. The threads are created to manage +// UNIX domain client sockets for writing, reading and +// controlling the user space logger, and for any additional +// logging plugins like auditd and restart control. Additional +// transitory per-client threads are created for each reader. +int main(int argc, char *argv[]) { + fdDmesg = open("/dev/kmsg", O_WRONLY); + + // issue reinit command. KISS argument parsing. + if ((argc > 1) && argv[1] && !strcmp(argv[1], "--reinit")) { + int sock = TEMP_FAILURE_RETRY( + socket_local_client("logd", + ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_STREAM)); + if (sock < 0) { + return -errno; + } + static const char reinit[] = "reinit"; + ssize_t ret = TEMP_FAILURE_RETRY(write(sock, reinit, sizeof(reinit))); + if (ret < 0) { + return -errno; + } + struct pollfd p; + memset(&p, 0, sizeof(p)); + p.fd = sock; + p.events = POLLIN; + ret = TEMP_FAILURE_RETRY(poll(&p, 1, 100)); + if (ret < 0) { + return -errno; + } + if ((ret == 0) || !(p.revents & POLLIN)) { + return -ETIME; + } + static const char success[] = "success"; + char buffer[sizeof(success) - 1]; + memset(buffer, 0, sizeof(buffer)); + ret = TEMP_FAILURE_RETRY(read(sock, buffer, sizeof(buffer))); + if (ret < 0) { + return -errno; + } + return strncmp(buffer, success, sizeof(success) - 1) != 0; + } + + // Reinit Thread + sem_init(&reinit, 0, 0); + sem_init(&uidName, 0, 0); + pthread_attr_t attr; + if (!pthread_attr_init(&attr)) { + struct sched_param param; + + memset(¶m, 0, sizeof(param)); + pthread_attr_setschedparam(&attr, ¶m); + pthread_attr_setschedpolicy(&attr, SCHED_BATCH); + if (!pthread_attr_setdetachstate(&attr, + PTHREAD_CREATE_DETACHED)) { + pthread_t thread; + reinit_running = true; + if (pthread_create(&thread, &attr, reinit_thread_start, NULL)) { + reinit_running = false; + } + } + pthread_attr_destroy(&attr); } if (drop_privs() != 0) { @@ -147,11 +308,10 @@ int main() { // LogBuffer is the object which is responsible for holding all // log entries. - LogBuffer *logBuf = new LogBuffer(times); + logBuf = new LogBuffer(times); + + signal(SIGHUP, reinit_signal_handler); - if (property_get_bool("logd.statistics.dgram_qlen", false)) { - logBuf->enableDgramQlenStatistics(); - } { char property[PROPERTY_VALUE_MAX]; property_get("ro.build.type", property, ""); @@ -192,16 +352,36 @@ int main() { // initiated log messages. New log entries are added to LogBuffer // and LogReader is notified to send updates to connected clients. + bool auditd = property_get_bool("logd.auditd", true); + if (auditd) { + bool dmesg = property_get_bool("logd.auditd.dmesg", true); + // failure is an option ... messages are in dmesg (required by standard) - LogAudit *al = new LogAudit(logBuf, reader, fdDmesg); + LogAudit *al = new LogAudit(logBuf, reader, dmesg ? fdDmesg : -1); + + int len = klogctl(KLOG_SIZE_BUFFER, NULL, 0); + if (len > 0) { + len++; + char buf[len]; + + int rc = klogctl(KLOG_READ_ALL, buf, len); + + if (rc >= 0) { + buf[len - 1] = '\0'; + + for (char *ptr, *tok = buf; (tok = strtok_r(tok, "\r\n", &ptr)); tok = NULL) { + al->log(tok); + } + } + } + if (al->startListener()) { delete al; - close(fdDmesg); } } - pause(); + TEMP_FAILURE_RETRY(pause()); + exit(0); } - diff --git a/logd/tests/Android.mk b/logd/tests/Android.mk index f851288..85ca4ac 100644 --- a/logd/tests/Android.mk +++ b/logd/tests/Android.mk @@ -46,7 +46,6 @@ test_src_files := \ include $(CLEAR_VARS) LOCAL_MODULE := $(test_module_prefix)unit-tests LOCAL_MODULE_TAGS := $(test_tags) -LOCAL_ADDITIONAL_DEPENDENCIES := $(LOCAL_PATH)/Android.mk LOCAL_CFLAGS += $(test_c_flags) LOCAL_SHARED_LIBRARIES := libcutils LOCAL_SRC_FILES := $(test_src_files) diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index 4bea4be..46bd9c0 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -192,164 +192,6 @@ TEST(logd, statistics) { EXPECT_TRUE(NULL != events_logs); #endif - // Parse timing stats - - cp = strstr(cp, "Minimum time between log events per dgram_qlen:"); - - if (cp) { - while (*cp && (*cp != '\n')) { - ++cp; - } - if (*cp == '\n') { - ++cp; - } - - char *list_of_spans = cp; - EXPECT_NE('\0', *list_of_spans); - - unsigned short number_of_buckets = 0; - unsigned short *dgram_qlen = NULL; - unsigned short bucket = 0; - while (*cp && (*cp != '\n')) { - bucket = 0; - while (isdigit(*cp)) { - bucket = bucket * 10 + *cp - '0'; - ++cp; - } - while (*cp == ' ') { - ++cp; - } - if (!bucket) { - break; - } - unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1]; - EXPECT_TRUE(new_dgram_qlen != NULL); - if (dgram_qlen) { - memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets); - delete [] dgram_qlen; - } - - dgram_qlen = new_dgram_qlen; - dgram_qlen[number_of_buckets++] = bucket; - } - - char *end_of_spans = cp; - EXPECT_NE('\0', *end_of_spans); - - EXPECT_LT(5, number_of_buckets); - - unsigned long long *times = new unsigned long long [number_of_buckets]; - ASSERT_TRUE(times != NULL); - - memset(times, 0, sizeof(*times) * number_of_buckets); - - while (*cp == '\n') { - ++cp; - } - - unsigned short number_of_values = 0; - unsigned long long value; - while (*cp && (*cp != '\n')) { - EXPECT_GE(number_of_buckets, number_of_values); - - value = 0; - while (isdigit(*cp)) { - value = value * 10ULL + *cp - '0'; - ++cp; - } - - switch(*cp) { - case ' ': - case '\n': - value *= 1000ULL; - /* FALLTHRU */ - case 'm': - value *= 1000ULL; - /* FALLTHRU */ - case 'u': - value *= 1000ULL; - /* FALLTHRU */ - case 'n': - default: - break; - } - while (*++cp == ' '); - - if (!value) { - break; - } - - times[number_of_values] = value; - ++number_of_values; - } - -#ifdef TARGET_USES_LOGD - EXPECT_EQ(number_of_values, number_of_buckets); -#endif - - FILE *fp; - ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r"))); - - unsigned max_dgram_qlen = 0; - fscanf(fp, "%u", &max_dgram_qlen); - - fclose(fp); - - // Find launch point - unsigned short launch = 0; - unsigned long long total = 0; - do { - total += times[launch]; - } while (((++launch < number_of_buckets) - && ((total / launch) >= (times[launch] / 8ULL))) - || (launch == 1)); // too soon - - bool failure = number_of_buckets <= launch; - if (!failure) { - unsigned short l = launch; - if (l >= number_of_buckets) { - l = number_of_buckets - 1; - } - failure = max_dgram_qlen < dgram_qlen[l]; - } - - // We can get failure if at any time liblog_benchmarks has been run - // because designed to overload /proc/sys/net/unix/max_dgram_qlen even - // at excessive values like 20000. It does so to measure the raw processing - // performance of logd. - if (failure) { - cp = find_benchmark_spam(cp); - } - - if (cp) { - // Fake a failure, but without the failure code - if (number_of_buckets <= launch) { - printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n", - number_of_buckets, launch); - } - if (launch >= number_of_buckets) { - launch = number_of_buckets - 1; - } - if (max_dgram_qlen < dgram_qlen[launch]) { - printf ("Expected: max_dgram_qlen >= dgram_qlen[%d]," - " actual: %u vs %u\n", - launch, max_dgram_qlen, dgram_qlen[launch]); - } - } else -#ifndef TARGET_USES_LOGD - if (total) -#endif - { - EXPECT_GT(number_of_buckets, launch); - if (launch >= number_of_buckets) { - launch = number_of_buckets - 1; - } - EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]); - } - - delete [] dgram_qlen; - delete [] times; - } delete [] buf; } @@ -417,7 +259,11 @@ static void dump_log_msg(const char *prefix, if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) { fprintf(stderr, "\""); while (*cp) { - fprintf(stderr, (*cp != '\n') ? "%c" : "\\n", *cp); + if (*cp != '\n') { + fprintf(stderr, "%c", *cp); + } else { + fprintf(stderr, "\\n"); + } ++cp; --len; } |