/* * 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 #include #include #include #include #include #include #include #include #include #include #include #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(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(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(sizeof(android_log_event_string_t))) && (lenr > static_cast(sizeof(android_log_event_string_t)))) { if (fastcmp(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(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); if (log_id != LOG_ID_SECURITY) { 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( const_cast(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( const_cast(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 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. 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 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)) { 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, privileged, 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; }