| /* | |
| * 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); | |
| 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<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. | |
| 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; | |
| } |