diff options
Diffstat (limited to 'logd/LogBuffer.cpp')
| -rw-r--r-- | logd/LogBuffer.cpp | 1225 |
1 files changed, 0 insertions, 1225 deletions
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp deleted file mode 100644 index 1cf20617f2..0000000000 --- a/logd/LogBuffer.cpp +++ /dev/null @@ -1,1225 +0,0 @@ -/* - * Copyright (C) 2012-2014 The Android Open Source Project - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -// for manual checking of stale entries during LogBuffer::erase() -//#define DEBUG_CHECK_FOR_STALE_ENTRIES - -#include <ctype.h> -#include <endian.h> -#include <errno.h> -#include <stdio.h> -#include <string.h> -#include <sys/cdefs.h> -#include <sys/user.h> -#include <time.h> -#include <unistd.h> - -#include <unordered_map> - -#include <cutils/properties.h> -#include <private/android_logger.h> - -#include "LogBuffer.h" -#include "LogKlog.h" -#include "LogReader.h" -#include "LogUtils.h" - -#ifndef __predict_false -#define __predict_false(exp) __builtin_expect((exp) != 0, 0) -#endif - -// Default -#define log_buffer_size(id) mMaxSize[id] - -const log_time LogBuffer::pruneMargin(3, 0); - -void LogBuffer::init() { - log_id_for_each(i) { - mLastSet[i] = false; - mLast[i] = mLogElements.begin(); - - if (setSize(i, __android_logger_get_buffer_size(i))) { - setSize(i, LOG_BUFFER_MIN_SIZE); - } - } - bool lastMonotonic = monotonic; - monotonic = android_log_clockid() == CLOCK_MONOTONIC; - if (lastMonotonic != monotonic) { - // - // Fixup all timestamps, may not be 100% accurate, but better than - // throwing what we have away when we get 'surprised' by a change. - // In-place element fixup so no need to check reader-lock. Entries - // should already be in timestamp order, but we could end up with a - // few out-of-order entries if new monotonics come in before we - // are notified of the reinit change in status. A Typical example would - // be: - // --------- beginning of system - // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data - // --------- beginning of kernel - // 0.000000 0 0 I : Initializing cgroup subsys - // as the act of mounting /data would trigger persist.logd.timestamp to - // be corrected. 1/30 corner case YMMV. - // - rdlock(); - LogBufferElementCollection::iterator it = mLogElements.begin(); - while ((it != mLogElements.end())) { - LogBufferElement* e = *it; - if (monotonic) { - if (!android::isMonotonic(e->mRealTime)) { - LogKlog::convertRealToMonotonic(e->mRealTime); - if ((e->mRealTime.tv_nsec % 1000) == 0) { - e->mRealTime.tv_nsec++; - } - } - } else { - if (android::isMonotonic(e->mRealTime)) { - LogKlog::convertMonotonicToReal(e->mRealTime); - if ((e->mRealTime.tv_nsec % 1000) == 0) { - e->mRealTime.tv_nsec++; - } - } - } - ++it; - } - unlock(); - } - - // We may have been triggered by a SIGHUP. Release any sleeping reader - // threads to dump their current content. - // - // NB: this is _not_ performed in the context of a SIGHUP, it is - // performed during startup, and in context of reinit administrative thread - LogTimeEntry::wrlock(); - - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogTimeEntry* entry = times->get(); - entry->triggerReader_Locked(); - times++; - } - - LogTimeEntry::unlock(); -} - -LogBuffer::LogBuffer(LastLogTimes* times) - : monotonic(android_log_clockid() == CLOCK_MONOTONIC), mTimes(*times) { - pthread_rwlock_init(&mLogElementsLock, nullptr); - - log_id_for_each(i) { - lastLoggedElements[i] = nullptr; - droppedElements[i] = nullptr; - } - - init(); -} - -LogBuffer::~LogBuffer() { - log_id_for_each(i) { - delete lastLoggedElements[i]; - delete droppedElements[i]; - } -} - -enum match_type { DIFFERENT, SAME, SAME_LIBLOG }; - -static enum match_type identical(LogBufferElement* elem, - LogBufferElement* last) { - // is it mostly identical? - // if (!elem) return DIFFERENT; - ssize_t lenl = elem->getMsgLen(); - if (lenl <= 0) return DIFFERENT; // value if this represents a chatty elem - // if (!last) return DIFFERENT; - ssize_t lenr = last->getMsgLen(); - if (lenr <= 0) return DIFFERENT; // value if this represents a chatty elem - // if (elem->getLogId() != last->getLogId()) return DIFFERENT; - if (elem->getUid() != last->getUid()) return DIFFERENT; - if (elem->getPid() != last->getPid()) return DIFFERENT; - if (elem->getTid() != last->getTid()) return DIFFERENT; - - // last is more than a minute old, stop squashing identical messages - if (elem->getRealTime().nsec() > - (last->getRealTime().nsec() + 60 * NS_PER_SEC)) - return DIFFERENT; - - // Identical message - const char* msgl = elem->getMsg(); - const char* msgr = last->getMsg(); - if (lenl == lenr) { - if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME; - // liblog tagged messages (content gets summed) - if ((elem->getLogId() == LOG_ID_EVENTS) && - (lenl == sizeof(android_log_event_int_t)) && - !fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_int_t) - - sizeof(int32_t)) && - (elem->getTag() == LIBLOG_LOG_TAG)) { - return SAME_LIBLOG; - } - } - - // audit message (except sequence number) identical? - if (last->isBinary() && - (lenl > static_cast<ssize_t>(sizeof(android_log_event_string_t))) && - (lenr > static_cast<ssize_t>(sizeof(android_log_event_string_t)))) { - if (fastcmp<memcmp>(msgl, msgr, sizeof(android_log_event_string_t) - - sizeof(int32_t))) { - return DIFFERENT; - } - msgl += sizeof(android_log_event_string_t); - lenl -= sizeof(android_log_event_string_t); - msgr += sizeof(android_log_event_string_t); - lenr -= sizeof(android_log_event_string_t); - } - static const char avc[] = "): avc: "; - const char* avcl = android::strnstr(msgl, lenl, avc); - if (!avcl) return DIFFERENT; - lenl -= avcl - msgl; - const char* avcr = android::strnstr(msgr, lenr, avc); - if (!avcr) return DIFFERENT; - lenr -= avcr - msgr; - if (lenl != lenr) return DIFFERENT; - if (fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), - lenl - strlen(avc))) { - return DIFFERENT; - } - return SAME; -} - -int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, - pid_t tid, const char* msg, uint16_t len) { - if (log_id >= LOG_ID_MAX) { - return -EINVAL; - } - - // Slip the time by 1 nsec if the incoming lands on xxxxxx000 ns. - // This prevents any chance that an outside source can request an - // exact entry with time specified in ms or us precision. - if ((realtime.tv_nsec % 1000) == 0) ++realtime.tv_nsec; - - LogBufferElement* elem = new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len); - - // b/137093665: don't coalesce security messages. - if (log_id == LOG_ID_SECURITY) { - wrlock(); - log(elem); - unlock(); - - return len; - } - - int prio = ANDROID_LOG_INFO; - const char* tag = nullptr; - size_t tag_len = 0; - if (log_id == LOG_ID_EVENTS || log_id == LOG_ID_STATS) { - tag = tagToName(elem->getTag()); - if (tag) { - tag_len = strlen(tag); - } - } else { - prio = *msg; - tag = msg + 1; - tag_len = strnlen(tag, len - 1); - } - if (!__android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE)) { - // Log traffic received to total - wrlock(); - stats.addTotal(elem); - unlock(); - delete elem; - return -EACCES; - } - - wrlock(); - LogBufferElement* currentLast = lastLoggedElements[log_id]; - if (currentLast) { - LogBufferElement* dropped = droppedElements[log_id]; - uint16_t count = dropped ? dropped->getDropped() : 0; - // - // State Init - // incoming: - // dropped = nullptr - // currentLast = nullptr; - // elem = incoming message - // outgoing: - // dropped = nullptr -> State 0 - // currentLast = copy of elem - // log elem - // State 0 - // incoming: - // count = 0 - // dropped = nullptr - // currentLast = copy of last message - // elem = incoming message - // outgoing: if match != DIFFERENT - // dropped = copy of first identical message -> State 1 - // currentLast = reference to elem - // break: if match == DIFFERENT - // dropped = nullptr -> State 0 - // delete copy of last message (incoming currentLast) - // currentLast = copy of elem - // log elem - // State 1 - // incoming: - // count = 0 - // dropped = copy of first identical message - // currentLast = reference to last held-back incoming - // message - // elem = incoming message - // outgoing: if match == SAME - // delete copy of first identical message (dropped) - // dropped = reference to last held-back incoming - // message set to chatty count of 1 -> State 2 - // currentLast = reference to elem - // outgoing: if match == SAME_LIBLOG - // dropped = copy of first identical message -> State 1 - // take sum of currentLast and elem - // if sum overflows: - // log currentLast - // currentLast = reference to elem - // else - // delete currentLast - // currentLast = reference to elem, sum liblog. - // break: if match == DIFFERENT - // delete dropped - // dropped = nullptr -> State 0 - // log reference to last held-back (currentLast) - // currentLast = copy of elem - // log elem - // State 2 - // incoming: - // count = chatty count - // dropped = chatty message holding count - // currentLast = reference to last held-back incoming - // message. - // dropped = chatty message holding count - // elem = incoming message - // outgoing: if match != DIFFERENT - // delete chatty message holding count - // dropped = reference to last held-back incoming - // message, set to chatty count + 1 - // currentLast = reference to elem - // break: if match == DIFFERENT - // log dropped (chatty message) - // dropped = nullptr -> State 0 - // log reference to last held-back (currentLast) - // currentLast = copy of elem - // log elem - // - enum match_type match = identical(elem, currentLast); - if (match != DIFFERENT) { - if (dropped) { - // Sum up liblog tag messages? - if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) { - android_log_event_int_t* event = - reinterpret_cast<android_log_event_int_t*>( - const_cast<char*>(currentLast->getMsg())); - // - // To unit test, differentiate with something like: - // event->header.tag = htole32(CHATTY_LOG_TAG); - // here, then instead of delete currentLast below, - // log(currentLast) to see the incremental sums form. - // - uint32_t swab = event->payload.data; - unsigned long long total = htole32(swab); - event = reinterpret_cast<android_log_event_int_t*>( - const_cast<char*>(elem->getMsg())); - swab = event->payload.data; - - lastLoggedElements[LOG_ID_EVENTS] = elem; - total += htole32(swab); - // check for overflow - if (total >= UINT32_MAX) { - log(currentLast); - unlock(); - return len; - } - stats.addTotal(currentLast); - delete currentLast; - swab = total; - event->payload.data = htole32(swab); - unlock(); - return len; - } - if (count == USHRT_MAX) { - log(dropped); - count = 1; - } else { - delete dropped; - ++count; - } - } - if (count) { - stats.addTotal(currentLast); - currentLast->setDropped(count); - } - droppedElements[log_id] = currentLast; - lastLoggedElements[log_id] = elem; - unlock(); - return len; - } - if (dropped) { // State 1 or 2 - if (count) { // State 2 - log(dropped); // report chatty - } else { // State 1 - delete dropped; - } - droppedElements[log_id] = nullptr; - log(currentLast); // report last message in the series - } else { // State 0 - delete currentLast; - } - } - lastLoggedElements[log_id] = new LogBufferElement(*elem); - - log(elem); - unlock(); - - return len; -} - -// assumes LogBuffer::wrlock() held, owns elem, look after garbage collection -void LogBuffer::log(LogBufferElement* elem) { - // cap on how far back we will sort in-place, otherwise append - static uint32_t too_far_back = 5; // five seconds - // Insert elements in time sorted order if possible - // NB: if end is region locked, place element at end of list - LogBufferElementCollection::iterator it = mLogElements.end(); - LogBufferElementCollection::iterator last = it; - if (__predict_true(it != mLogElements.begin())) --it; - if (__predict_false(it == mLogElements.begin()) || - __predict_true((*it)->getRealTime() <= elem->getRealTime()) || - __predict_false((((*it)->getRealTime().tv_sec - too_far_back) > - elem->getRealTime().tv_sec) && - (elem->getLogId() != LOG_ID_KERNEL) && - ((*it)->getLogId() != LOG_ID_KERNEL))) { - mLogElements.push_back(elem); - } else { - log_time end(log_time::EPOCH); - bool end_set = false; - bool end_always = false; - - LogTimeEntry::rdlock(); - - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogTimeEntry* entry = times->get(); - if (!entry->mNonBlock) { - end_always = true; - break; - } - // it passing mEnd is blocked by the following checks. - if (!end_set || (end <= entry->mEnd)) { - end = entry->mEnd; - end_set = true; - } - times++; - } - - if (end_always || (end_set && (end > (*it)->getRealTime()))) { - mLogElements.push_back(elem); - } else { - // should be short as timestamps are localized near end() - do { - last = it; - if (__predict_false(it == mLogElements.begin())) { - break; - } - --it; - } while (((*it)->getRealTime() > elem->getRealTime()) && - (!end_set || (end <= (*it)->getRealTime()))); - mLogElements.insert(last, elem); - } - LogTimeEntry::unlock(); - } - - stats.add(elem); - maybePrune(elem->getLogId()); -} - -// Prune at most 10% of the log entries or maxPrune, whichever is less. -// -// LogBuffer::wrlock() must be held when this function is called. -void LogBuffer::maybePrune(log_id_t id) { - size_t sizes = stats.sizes(id); - unsigned long maxSize = log_buffer_size(id); - if (sizes > maxSize) { - size_t sizeOver = sizes - ((maxSize * 9) / 10); - size_t elements = stats.realElements(id); - size_t minElements = elements / 100; - if (minElements < minPrune) { - minElements = minPrune; - } - unsigned long pruneRows = elements * sizeOver / sizes; - if (pruneRows < minElements) { - pruneRows = minElements; - } - if (pruneRows > maxPrune) { - pruneRows = maxPrune; - } - prune(id, pruneRows); - } -} - -LogBufferElementCollection::iterator LogBuffer::erase( - LogBufferElementCollection::iterator it, bool coalesce) { - LogBufferElement* element = *it; - log_id_t id = element->getLogId(); - - // Remove iterator references in the various lists that will become stale - // after the element is erased from the main logging list. - - { // start of scope for found iterator - int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) - ? element->getTag() - : element->getUid(); - LogBufferIteratorMap::iterator found = mLastWorst[id].find(key); - if ((found != mLastWorst[id].end()) && (it == found->second)) { - mLastWorst[id].erase(found); - } - } - - { // start of scope for pid found iterator - // element->getUid() may not be AID_SYSTEM for next-best-watermark. - // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and - // long term code stability, find() check should be fast for those ids. - LogBufferPidIteratorMap::iterator found = - mLastWorstPidOfSystem[id].find(element->getPid()); - if ((found != mLastWorstPidOfSystem[id].end()) && - (it == found->second)) { - mLastWorstPidOfSystem[id].erase(found); - } - } - - bool setLast[LOG_ID_MAX]; - bool doSetLast = false; - log_id_for_each(i) { - doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]); - } -#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES - LogBufferElementCollection::iterator bad = it; - int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) - ? element->getTag() - : element->getUid(); -#endif - it = mLogElements.erase(it); - if (doSetLast) { - log_id_for_each(i) { - if (setLast[i]) { - if (__predict_false(it == mLogElements.end())) { // impossible - mLastSet[i] = false; - mLast[i] = mLogElements.begin(); - } else { - mLast[i] = it; // push down the road as next-best-watermark - } - } - } - } -#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES - log_id_for_each(i) { - for (auto b : mLastWorst[i]) { - if (bad == b.second) { - android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i, - b.first, key); - } - } - for (auto b : mLastWorstPidOfSystem[i]) { - if (bad == b.second) { - android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i, - b.first); - } - } - if (mLastSet[i] && (bad == mLast[i])) { - android::prdebug("stale mLast[%d]\n", i); - mLastSet[i] = false; - mLast[i] = mLogElements.begin(); - } - } -#endif - if (coalesce) { - stats.erase(element); - } else { - stats.subtract(element); - } - delete element; - - 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 { - uint32_t uid; - uint16_t pid; - uint16_t tid; - } __packed; - uint64_t value; - } __packed; - - public: - LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) - : uid(uid), pid(pid), tid(tid) { - } - explicit LogBufferElementKey(uint64_t key) : value(key) { - } - - uint64_t getKey() { - return value; - } -}; - -class LogBufferElementLast { - typedef std::unordered_map<uint64_t, LogBufferElement*> LogBufferElementMap; - LogBufferElementMap map; - - public: - bool coalesce(LogBufferElement* element, uint16_t dropped) { - LogBufferElementKey key(element->getUid(), element->getPid(), - element->getTid()); - LogBufferElementMap::iterator it = map.find(key.getKey()); - if (it != map.end()) { - LogBufferElement* found = it->second; - uint16_t moreDropped = found->getDropped(); - if ((dropped + moreDropped) > USHRT_MAX) { - map.erase(it); - } else { - found->setDropped(dropped + moreDropped); - return true; - } - } - return false; - } - - void add(LogBufferElement* element) { - LogBufferElementKey key(element->getUid(), element->getPid(), - element->getTid()); - map[key.getKey()] = element; - } - - inline void clear() { - map.clear(); - } - - void clear(LogBufferElement* element) { - log_time current = - element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0); - for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) { - LogBufferElement* mapElement = it->second; - if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) && - (current > mapElement->getRealTime())) { - it = map.erase(it); - } else { - ++it; - } - } - } -}; - -// Determine if watermark is within pruneMargin + 1s from the end of the list, -// the caller will use this result to set an internal busy flag indicating -// the prune operation could not be completed because a reader is blocking -// the request. -bool LogBuffer::isBusy(log_time watermark) { - LogBufferElementCollection::iterator ei = mLogElements.end(); - --ei; - return watermark < ((*ei)->getRealTime() - pruneMargin - log_time(1, 0)); -} - -// If the selected reader is blocking our pruning progress, decide on -// what kind of mitigation is necessary to unblock the situation. -void LogBuffer::kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows) { - if (stats.sizes(id) > (2 * log_buffer_size(id))) { // +100% - // A misbehaving or slow reader has its connection - // dropped if we hit too much memory pressure. - android::prdebug("Kicking blocked reader, pid %d, from LogBuffer::kickMe()\n", - me->mClient->getPid()); - me->release_Locked(); - } else if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) { - // Allow a blocked WRAP timeout reader to - // trigger and start reporting the log data. - me->triggerReader_Locked(); - } else { - // tell slow reader to skip entries to catch up - android::prdebug( - "Skipping %lu entries from slow reader, pid %d, from LogBuffer::kickMe()\n", - pruneRows, me->mClient->getPid()); - me->triggerSkip_Locked(id, pruneRows); - } -} - -// prune "pruneRows" of type "id" from the buffer. -// -// This garbage collection task is used to expire log entries. It is called to -// remove all logs (clear), all UID logs (unprivileged clear), or every -// 256 or 10% of the total logs (whichever is less) to prune the logs. -// -// First there is a prep phase where we discover the reader region lock that -// acts as a backstop to any pruning activity to stop there and go no further. -// -// There are three major pruning loops that follow. All expire from the oldest -// entries. Since there are multiple log buffers, the Android logging facility -// will appear to drop entries 'in the middle' when looking at multiple log -// sources and buffers. This effect is slightly more prominent when we prune -// the worst offender by logging source. Thus the logs slowly loose content -// and value as you move back in time. This is preferred since chatty sources -// invariably move the logs value down faster as less chatty sources would be -// expired in the noise. -// -// The first loop performs blacklisting and worst offender pruning. Falling -// through when there are no notable worst offenders and have not hit the -// region lock preventing further worst offender pruning. This loop also looks -// after managing the chatty log entries and merging to help provide -// statistical basis for blame. The chatty entries are not a notification of -// how much logs you may have, but instead represent how much logs you would -// have had in a virtual log buffer that is extended to cover all the in-memory -// logs without loss. They last much longer than the represented pruned logs -// since they get multiplied by the gains in the non-chatty log sources. -// -// The second loop get complicated because an algorithm of watermarks and -// history is maintained to reduce the order and keep processing time -// down to a minimum at scale. These algorithms can be costly in the face -// of larger log buffers, or severly limited processing time granted to a -// background task at lowest priority. -// -// This second loop does straight-up expiration from the end of the logs -// (again, remember for the specified log buffer id) but does some whitelist -// preservation. Thus whitelist is a Hail Mary low priority, blacklists and -// spam filtration all take priority. This second loop also checks if a region -// lock is causing us to buffer too much in the logs to help the reader(s), -// and will tell the slowest reader thread to skip log entries, and if -// persistent and hits a further threshold, kill the reader thread. -// -// The third thread is optional, and only gets hit if there was a whitelist -// and more needs to be pruned against the backstop of the region lock. -// -// LogBuffer::wrlock() must be held when this function is called. -// -bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { - LogTimeEntry* oldest = nullptr; - bool busy = false; - bool clearAll = pruneRows == ULONG_MAX; - - LogTimeEntry::rdlock(); - - // Region locked? - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogTimeEntry* entry = times->get(); - if (entry->isWatching(id) && - (!oldest || (oldest->mStart > entry->mStart) || - ((oldest->mStart == entry->mStart) && - (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) { - oldest = entry; - } - times++; - } - log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max); - if (oldest) watermark = oldest->mStart - pruneMargin; - - LogBufferElementCollection::iterator it; - - if (__predict_false(caller_uid != AID_ROOT)) { // unlikely - // Only here if clear all request from non system source, so chatty - // filter logistics is not required. - it = mLastSet[id] ? mLast[id] : mLogElements.begin(); - while (it != mLogElements.end()) { - LogBufferElement* element = *it; - - if ((element->getLogId() != id) || - (element->getUid() != caller_uid)) { - ++it; - continue; - } - - if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { - mLast[id] = it; - mLastSet[id] = true; - } - - if (oldest && (watermark <= element->getRealTime())) { - busy = isBusy(watermark); - if (busy) kickMe(oldest, id, pruneRows); - break; - } - - it = erase(it); - if (--pruneRows == 0) { - break; - } - } - LogTimeEntry::unlock(); - return busy; - } - - // prune by worst offenders; by blacklist, UID, and by PID of system UID - bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty(); - while (!clearAll && (pruneRows > 0)) { - // recalculate the worst offender on every batched pass - int worst = -1; // not valid for getUid() or getKey() - size_t worst_sizes = 0; - size_t second_worst_sizes = 0; - pid_t worstPid = 0; // POSIX guarantees PID != 0 - - if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) { - // Calculate threshold as 12.5% of available storage - size_t threshold = log_buffer_size(id) / 8; - - if ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) { - stats.sortTags(AID_ROOT, (pid_t)0, 2, id) - .findWorst(worst, worst_sizes, second_worst_sizes, - threshold); - // per-pid filter for AID_SYSTEM sources is too complex - } else { - stats.sort(AID_ROOT, (pid_t)0, 2, id) - .findWorst(worst, worst_sizes, second_worst_sizes, - threshold); - - if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) { - stats.sortPids(worst, (pid_t)0, 2, id) - .findWorst(worstPid, worst_sizes, second_worst_sizes); - } - } - } - - // skip if we have neither worst nor naughty filters - if ((worst == -1) && !hasBlacklist) { - break; - } - - bool kick = false; - bool leading = true; - it = mLastSet[id] ? mLast[id] : mLogElements.begin(); - // Perform at least one mandatory garbage collection cycle in following - // - clear leading chatty tags - // - coalesce chatty tags - // - check age-out of preserved logs - bool gc = pruneRows <= 1; - if (!gc && (worst != -1)) { - { // begin scope for worst found iterator - LogBufferIteratorMap::iterator found = - mLastWorst[id].find(worst); - if ((found != mLastWorst[id].end()) && - (found->second != mLogElements.end())) { - leading = false; - it = found->second; - } - } - if (worstPid) { // begin scope for pid worst found iterator - // FYI: worstPid only set if !LOG_ID_EVENTS and - // !LOG_ID_SECURITY, not going to make that assumption ... - LogBufferPidIteratorMap::iterator found = - mLastWorstPidOfSystem[id].find(worstPid); - if ((found != mLastWorstPidOfSystem[id].end()) && - (found->second != mLogElements.end())) { - leading = false; - it = found->second; - } - } - } - static const timespec too_old = { EXPIRE_HOUR_THRESHOLD * 60 * 60, 0 }; - LogBufferElementCollection::iterator lastt; - lastt = mLogElements.end(); - --lastt; - LogBufferElementLast last; - while (it != mLogElements.end()) { - LogBufferElement* element = *it; - - if (oldest && (watermark <= element->getRealTime())) { - busy = isBusy(watermark); - // Do not let chatty eliding trigger any reader mitigation - break; - } - - if (element->getLogId() != id) { - ++it; - continue; - } - // below this point element->getLogId() == id - - if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) { - mLast[id] = it; - mLastSet[id] = true; - } - - uint16_t dropped = element->getDropped(); - - // remove any leading drops - if (leading && dropped) { - it = erase(it); - continue; - } - - if (dropped && last.coalesce(element, dropped)) { - it = erase(it, true); - continue; - } - - int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) - ? element->getTag() - : element->getUid(); - - if (hasBlacklist && mPrune.naughty(element)) { - last.clear(element); - it = erase(it); - if (dropped) { - continue; - } - - pruneRows--; - if (pruneRows == 0) { - break; - } - - if (key == worst) { - kick = true; - if (worst_sizes < second_worst_sizes) { - break; - } - worst_sizes -= element->getMsgLen(); - } - continue; - } - - if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old)) || - (element->getRealTime() > (*lastt)->getRealTime())) { - break; - } - - if (dropped) { - last.add(element); - if (worstPid && - ((!gc && (element->getPid() == worstPid)) || - (mLastWorstPidOfSystem[id].find(element->getPid()) == - mLastWorstPidOfSystem[id].end()))) { - // element->getUid() may not be AID_SYSTEM, next best - // watermark if current one empty. id is not LOG_ID_EVENTS - // or LOG_ID_SECURITY because of worstPid check. - mLastWorstPidOfSystem[id][element->getPid()] = it; - } - if ((!gc && !worstPid && (key == worst)) || - (mLastWorst[id].find(key) == mLastWorst[id].end())) { - mLastWorst[id][key] = it; - } - ++it; - continue; - } - - if ((key != worst) || - (worstPid && (element->getPid() != worstPid))) { - leading = false; - last.clear(element); - ++it; - continue; - } - // key == worst below here - // If worstPid set, then element->getPid() == worstPid below here - - pruneRows--; - if (pruneRows == 0) { - break; - } - - kick = true; - - uint16_t len = element->getMsgLen(); - - // do not create any leading drops - if (leading) { - it = erase(it); - } else { - stats.drop(element); - element->setDropped(1); - if (last.coalesce(element, 1)) { - it = erase(it, true); - } else { - last.add(element); - if (worstPid && - (!gc || (mLastWorstPidOfSystem[id].find(worstPid) == - mLastWorstPidOfSystem[id].end()))) { - // element->getUid() may not be AID_SYSTEM, next best - // watermark if current one empty. id is not - // LOG_ID_EVENTS or LOG_ID_SECURITY because of worstPid. - mLastWorstPidOfSystem[id][worstPid] = it; - } - if ((!gc && !worstPid) || - (mLastWorst[id].find(worst) == mLastWorst[id].end())) { - mLastWorst[id][worst] = it; - } - ++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 - } - } - - bool whitelist = false; - bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll; - it = mLastSet[id] ? mLast[id] : mLogElements.begin(); - while ((pruneRows > 0) && (it != mLogElements.end())) { - LogBufferElement* element = *it; - - if (element->getLogId() != id) { - it++; - continue; - } - - if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { - mLast[id] = it; - mLastSet[id] = true; - } - - if (oldest && (watermark <= element->getRealTime())) { - busy = isBusy(watermark); - if (!whitelist && busy) kickMe(oldest, id, pruneRows); - break; - } - - if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) { - // 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 = mLastSet[id] ? mLast[id] : mLogElements.begin(); - while ((it != mLogElements.end()) && (pruneRows > 0)) { - LogBufferElement* element = *it; - - if (element->getLogId() != id) { - ++it; - continue; - } - - if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) { - mLast[id] = it; - mLastSet[id] = true; - } - - if (oldest && (watermark <= element->getRealTime())) { - busy = isBusy(watermark); - if (busy) kickMe(oldest, id, pruneRows); - break; - } - - it = erase(it); - pruneRows--; - } - } - - LogTimeEntry::unlock(); - - return (pruneRows > 0) && busy; -} - -// clear all rows of type "id" from the buffer. -bool LogBuffer::clear(log_id_t id, uid_t uid) { - bool busy = true; - // If it takes more than 4 tries (seconds) to clear, then kill reader(s) - for (int retry = 4;;) { - if (retry == 1) { // last pass - // Check if it is still busy after the sleep, we say prune - // one entry, not another clear run, so we are looking for - // the quick side effect of the return value to tell us if - // we have a _blocked_ reader. - wrlock(); - busy = prune(id, 1, uid); - unlock(); - // It is still busy, blocked reader(s), lets kill them all! - // otherwise, lets be a good citizen and preserve the slow - // readers and let the clear run (below) deal with determining - // if we are still blocked and return an error code to caller. - if (busy) { - LogTimeEntry::wrlock(); - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogTimeEntry* entry = times->get(); - // Killer punch - if (entry->isWatching(id)) { - android::prdebug( - "Kicking blocked reader, pid %d, from LogBuffer::clear()\n", - entry->mClient->getPid()); - entry->release_Locked(); - } - times++; - } - LogTimeEntry::unlock(); - } - } - wrlock(); - busy = prune(id, ULONG_MAX, uid); - unlock(); - if (!busy || !--retry) { - break; - } - sleep(1); // Let reader(s) catch up after notification - } - return busy; -} - -// get the used space associated with "id". -unsigned long LogBuffer::getSizeUsed(log_id_t id) { - rdlock(); - size_t retval = stats.sizes(id); - unlock(); - return retval; -} - -// set the total space allocated to "id" -int LogBuffer::setSize(log_id_t id, unsigned long size) { - // Reasonable limits ... - if (!__android_logger_valid_buffer_size(size)) { - return -1; - } - wrlock(); - log_buffer_size(id) = size; - unlock(); - return 0; -} - -// get the total space allocated to "id" -unsigned long LogBuffer::getSize(log_id_t id) { - rdlock(); - size_t retval = log_buffer_size(id); - unlock(); - return retval; -} - -log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, - pid_t* lastTid, bool privileged, bool security, - int (*filter)(const LogBufferElement* element, - void* arg), - void* arg) { - LogBufferElementCollection::iterator it; - uid_t uid = reader->getUid(); - - rdlock(); - - if (start == log_time::EPOCH) { - // client wants to start from the beginning - it = mLogElements.begin(); - } else { - // Cap to 300 iterations we look back for out-of-order entries. - size_t count = 300; - - // Client wants to start from some specified time. Chances are - // we are better off starting from the end of the time sorted list. - LogBufferElementCollection::iterator last; - for (last = it = mLogElements.end(); it != mLogElements.begin(); - /* do nothing */) { - --it; - LogBufferElement* element = *it; - if (element->getRealTime() > start) { - last = it; - } else if (element->getRealTime() == start) { - last = ++it; - break; - } else if (!--count) { - break; - } - } - it = last; - } - - log_time curr = start; - - LogBufferElement* lastElement = nullptr; // iterator corruption paranoia - static const size_t maxSkip = 4194304; // maximum entries to skip - size_t skip = maxSkip; - for (; it != mLogElements.end(); ++it) { - LogBufferElement* element = *it; - - if (!--skip) { - android::prdebug("reader.per: too many elements skipped"); - break; - } - if (element == lastElement) { - android::prdebug("reader.per: identical elements"); - break; - } - lastElement = element; - - if (!privileged && (element->getUid() != uid)) { - continue; - } - - if (!security && (element->getLogId() == LOG_ID_SECURITY)) { - continue; - } - - // NB: calling out to another object with wrlock() held (safe) - if (filter) { - int ret = (*filter)(element, arg); - if (ret == false) { - continue; - } - if (ret != true) { - break; - } - } - - bool sameTid = false; - if (lastTid) { - sameTid = lastTid[element->getLogId()] == element->getTid(); - // Dropped (chatty) immediately following a valid log from the - // same source in the same log buffer indicates we have a - // multiple identical squash. chatty that differs source - // is due to spam filter. chatty to chatty of different - // source is also due to spam filter. - lastTid[element->getLogId()] = - (element->getDropped() && !sameTid) ? 0 : element->getTid(); - } - - unlock(); - - // range locking in LastLogTimes looks after us - curr = element->flushTo(reader, this, sameTid); - - if (curr == element->FLUSH_ERROR) { - return curr; - } - - skip = maxSkip; - rdlock(); - } - unlock(); - - return curr; -} - -std::string LogBuffer::formatStatistics(uid_t uid, pid_t pid, - unsigned int logMask) { - wrlock(); - - std::string ret = stats.format(uid, pid, logMask); - - unlock(); - - return ret; -} |