logd/ChattyLogBuffer.cpp - platform/system/logging - Git at Google

 /*
  * 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 ChattyLogBuffer::erase()
 //#define DEBUG_CHECK_FOR_STALE_ENTRIES

 #include "ChattyLogBuffer.h"

 #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 <limits>
 #include <unordered_map>
 #include <utility>

 #include <private/android_logger.h>

 #include "LogUtils.h"

 #ifndef __predict_false
 #define __predict_false(exp) __builtin_expect((exp) != 0, 0)
 #endif

 ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune,
                                  LogStatistics* stats)
     : SimpleLogBuffer(reader_list, tags, stats), prune_(prune) {}

 ChattyLogBuffer::~ChattyLogBuffer() {}

 enum match_type { DIFFERENT, SAME, SAME_LIBLOG };

 static enum match_type Identical(const LogBufferElement& elem, const LogBufferElement& last) {
     ssize_t lenl = elem.msg_len();
     if (lenl <= 0) return DIFFERENT;  // value if this represents a chatty elem
     ssize_t lenr = last.msg_len();
     if (lenr <= 0) return DIFFERENT;  // value if this represents a chatty elem
     if (elem.uid() != last.uid()) return DIFFERENT;
     if (elem.pid() != last.pid()) return DIFFERENT;
     if (elem.tid() != last.tid()) return DIFFERENT;

     // last is more than a minute old, stop squashing identical messages
     if (elem.realtime().nsec() > (last.realtime().nsec() + 60 * NS_PER_SEC)) return DIFFERENT;

     // Identical message
     const char* msgl = elem.msg();
     const char* msgr = last.msg();
     if (lenl == lenr) {
         if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME;
         // liblog tagged messages (content gets summed)
         if (elem.log_id() == 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 (IsBinary(last.log_id()) &&
         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;
 }

 void ChattyLogBuffer::LogInternal(LogBufferElement&& elem) {
     // b/137093665: don't coalesce security messages.
     if (elem.log_id() == LOG_ID_SECURITY) {
         SimpleLogBuffer::LogInternal(std::move(elem));
         return;
     }
     int log_id = elem.log_id();

     // Initialize last_logged_elements_ to a copy of elem if logging the first element for a log_id.
     if (!last_logged_elements_[log_id]) {
         last_logged_elements_[log_id].emplace(elem);
         SimpleLogBuffer::LogInternal(std::move(elem));
         return;
     }

     LogBufferElement& current_last = *last_logged_elements_[log_id];
     enum match_type match = Identical(elem, current_last);

     if (match == DIFFERENT) {
         if (duplicate_elements_[log_id]) {
             // If we previously had 3+ identical messages, log the chatty message.
             if (duplicate_elements_[log_id]->dropped_count() > 0) {
                 SimpleLogBuffer::LogInternal(std::move(*duplicate_elements_[log_id]));
             }
             duplicate_elements_[log_id].reset();
             // Log the saved copy of the last identical message seen.
             SimpleLogBuffer::LogInternal(std::move(current_last));
         }
         last_logged_elements_[log_id].emplace(elem);
         SimpleLogBuffer::LogInternal(std::move(elem));
         return;
     }

     // 2 identical message: set duplicate_elements_ appropriately.
     if (!duplicate_elements_[log_id]) {
         duplicate_elements_[log_id].emplace(std::move(current_last));
         last_logged_elements_[log_id].emplace(std::move(elem));
         return;
     }

     // 3+ identical LIBLOG event messages: coalesce them into last_logged_elements_.
     if (match == SAME_LIBLOG) {
         const android_log_event_int_t* current_last_event =
                 reinterpret_cast<const android_log_event_int_t*>(current_last.msg());
         int64_t current_last_count = current_last_event->payload.data;
         android_log_event_int_t* elem_event =
                 reinterpret_cast<android_log_event_int_t*>(const_cast<char*>(elem.msg()));
         int64_t elem_count = elem_event->payload.data;

         int64_t total = current_last_count + elem_count;
         if (total > std::numeric_limits<int32_t>::max()) {
             SimpleLogBuffer::LogInternal(std::move(current_last));
             last_logged_elements_[log_id].emplace(std::move(elem));
             return;
         }
         stats()->AddTotal(current_last.log_id(), current_last.msg_len());
         elem_event->payload.data = total;
         last_logged_elements_[log_id].emplace(std::move(elem));
         return;
     }

     // 3+ identical messages (not LIBLOG) messages: increase the drop count.
     uint16_t dropped_count = duplicate_elements_[log_id]->dropped_count();
     if (dropped_count == std::numeric_limits<uint16_t>::max()) {
         SimpleLogBuffer::LogInternal(std::move(*duplicate_elements_[log_id]));
         dropped_count = 0;
     }
     // We're dropping the current_last log so add its stats to the total.
     stats()->AddTotal(current_last.log_id(), current_last.msg_len());
     // Use current_last for tracking the dropped count to always use the latest timestamp.
     current_last.SetDropped(dropped_count + 1);
     duplicate_elements_[log_id].emplace(std::move(current_last));
     last_logged_elements_[log_id].emplace(std::move(elem));
 }

 LogBufferElementCollection::iterator ChattyLogBuffer::Erase(LogBufferElementCollection::iterator it,
                                                             bool coalesce) {
     LogBufferElement& element = *it;
     log_id_t id = element.log_id();

     // 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.uid();
         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->uid() 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.pid());
         if (found != mLastWorstPidOfSystem[id].end() && it == found->second) {
             mLastWorstPidOfSystem[id].erase(found);
         }
     }

 #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
     LogBufferElementCollection::iterator bad = it;
     int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->GetTag() : element->uid();
 #endif

     if (coalesce) {
         stats()->Erase(element.ToLogStatisticsElement());
     } else {
         stats()->Subtract(element.ToLogStatisticsElement());
     }

     it = SimpleLogBuffer::Erase(it);

 #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
     log_id_for_each(i) {
         for (auto b : mLastWorst[i]) {
             if (bad == b.second) {
                 LOG(ERROR) << StringPrintf("stale mLastWorst[%d] key=%d mykey=%d", i, b.first, key);
             }
         }
         for (auto b : mLastWorstPidOfSystem[i]) {
             if (bad == b.second) {
                 LOG(ERROR) << StringPrintf("stale mLastWorstPidOfSystem[%d] pid=%d", i, b.first);
             }
         }
     }
 #endif
     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 LogBufferElementLast {
     typedef std::unordered_map<uint64_t, LogBufferElement*> LogBufferElementMap;
     LogBufferElementMap map;

   public:
     bool coalesce(LogBufferElement* element, uint16_t dropped) {
         uint64_t key = LogBufferElementKey(element->uid(), element->pid(), element->tid());
         LogBufferElementMap::iterator it = map.find(key);
         if (it != map.end()) {
             LogBufferElement* found = it->second;
             uint16_t moreDropped = found->dropped_count();
             if ((dropped + moreDropped) > USHRT_MAX) {
                 map.erase(it);
             } else {
                 found->SetDropped(dropped + moreDropped);
                 return true;
             }
         }
         return false;
     }

     void add(LogBufferElement* element) {
         uint64_t key = LogBufferElementKey(element->uid(), element->pid(), element->tid());
         map[key] = element;
     }

     void clear() { map.clear(); }

     void clear(LogBufferElement* element) {
         uint64_t current = element->realtime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC);
         for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
             LogBufferElement* mapElement = it->second;
             if (mapElement->dropped_count() >= EXPIRE_THRESHOLD &&
                 current > mapElement->realtime().nsec()) {
                 it = map.erase(it);
             } else {
                 ++it;
             }
         }
     }

   private:
     uint64_t LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) {
         return uint64_t(uid) << 32 | uint64_t(pid) << 16 | uint64_t(tid);
     }
 };

 // 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 pass prunes elements that match 3 possible rules:
 // 1) A high priority prune rule, for example ~100/20, which indicates elements from UID 100 and PID
 //    20 should be pruned in this first pass.
 // 2) The default chatty pruning rule, ~!.  This rule sums the total size spent on log messages for
 //    each UID this log buffer.  If the highest sum consumes more than 12.5% of the log buffer, then
 //    these elements from that UID are pruned.
 // 3) The default AID_SYSTEM pruning rule, ~1000/!.  This rule is a special case to 2), if
 //    AID_SYSTEM is the top consumer of the log buffer, then this rule sums the total size spent on
 //    log messages for each PID in AID_SYSTEM in this log buffer and prunes elements from the PID
 //    with the highest sum.
 // This pass reevaluates the sums for rules 2) and 3) for every log message pruned. It creates
 // 'chatty' entries for the elements that it prunes and merges related chatty entries together. It
 // completes when one of three conditions have been met:
 // 1) The requested element count has been pruned.
 // 2) There are no elements that match any of these rules.
 // 3) A reader is referencing the oldest element that would match these rules.
 //
 // The second pass prunes elements starting from the beginning of the log.  It skips elements that
 // match any low priority prune rules.  It completes when one of three conditions have been met:
 // 1) The requested element count has been pruned.
 // 2) All elements except those mwatching low priority prune rules have been pruned.
 // 3) A reader is referencing the oldest element that would match these rules.
 //
 // The final pass only happens if there are any low priority prune rules and if the first two passes
 // were unable to prune the requested number of elements.  It prunes elements all starting from the
 // beginning of the log, regardless of if they match any low priority prune rules.
 //
 // If the requested number of logs was unable to be pruned, KickReader() is called to mitigate the
 // situation before the next call to Prune() and the function returns false.  Otherwise, if the
 // requested number of logs or all logs present in the buffer are pruned, in the case of Clear(),
 // it returns true.
 bool ChattyLogBuffer::Prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
     LogReaderThread* oldest = nullptr;
     bool clearAll = pruneRows == ULONG_MAX;

     // Region locked?
     for (const auto& reader_thread : reader_list()->reader_threads()) {
         if (!reader_thread->IsWatching(id)) {
             continue;
         }
         if (!oldest || oldest->start() > reader_thread->start() ||
             (oldest->start() == reader_thread->start() &&
              reader_thread->deadline().time_since_epoch().count() != 0)) {
             oldest = reader_thread.get();
         }
     }

     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 = GetOldest(id);
         while (it != logs().end()) {
             LogBufferElement& element = *it;

             if (element.log_id() != id || element.uid() != caller_uid) {
                 ++it;
                 continue;
             }

             if (oldest && oldest->start() <= element.sequence()) {
                 KickReader(oldest, id, pruneRows);
                 return false;
             }

             it = Erase(it);
             if (--pruneRows == 0) {
                 return true;
             }
         }
         return true;
     }

     // First prune pass.
     bool check_high_priority = id != LOG_ID_SECURITY && prune_->HasHighPriorityPruneRules();
     while (!clearAll && (pruneRows > 0)) {
         // recalculate the worst offender on every batched pass
         int worst = -1;  // not valid for uid() or getKey()
         size_t worst_sizes = 0;
         size_t second_worst_sizes = 0;
         pid_t worstPid = 0;  // POSIX guarantees PID != 0

         if (worstUidEnabledForLogid(id) && prune_->worst_uid_enabled()) {
             // Calculate threshold as 12.5% of available storage
             size_t threshold = max_size(id) / 8;

             if (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) {
                 stats()->WorstTwoTags(threshold, &worst, &worst_sizes, &second_worst_sizes);
                 // per-pid filter for AID_SYSTEM sources is too complex
             } else {
                 stats()->WorstTwoUids(id, threshold, &worst, &worst_sizes, &second_worst_sizes);

                 if (worst == AID_SYSTEM && prune_->worst_pid_of_system_enabled()) {
                     stats()->WorstTwoSystemPids(id, worst_sizes, &worstPid, &second_worst_sizes);
                 }
             }
         }

         // skip if we have neither a worst UID or high priority prune rules
         if (worst == -1 && !check_high_priority) {
             break;
         }

         bool kick = false;
         bool leading = true;  // true if starting from the oldest log entry, false if starting from
                               // a specific chatty entry.
         // 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 != logs().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 != logs().end()) {
                     leading = false;
                     it = found->second;
                 }
             }
         }
         if (leading) {
             it = GetOldest(id);
         }
         static const log_time too_old{EXPIRE_HOUR_THRESHOLD * 60 * 60, 0};
         LogBufferElementCollection::iterator lastt;
         lastt = logs().end();
         --lastt;
         LogBufferElementLast last;
         while (it != logs().end()) {
             LogBufferElement& element = *it;

             if (oldest && oldest->start() <= element.sequence()) {
                 // Do not let chatty eliding trigger any reader mitigation
                 break;
             }

             if (element.log_id() != id) {
                 ++it;
                 continue;
             }
             // below this point element->log_id() == id

             uint16_t dropped = element.dropped_count();

             // 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.uid();

             if (check_high_priority && prune_->IsHighPriority(&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.msg_len();
                 }
                 continue;
             }

             if (element.realtime() < (lastt->realtime() - too_old) ||
                 element.realtime() > lastt->realtime()) {
                 break;
             }

             if (dropped) {
                 last.add(&element);
                 if (worstPid && ((!gc && element.pid() == worstPid) ||
                                  mLastWorstPidOfSystem[id].find(element.pid()) ==
                                          mLastWorstPidOfSystem[id].end())) {
                     // element->uid() 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.pid()] = it;
                 }
                 if ((!gc && !worstPid && (key == worst)) ||
                     (mLastWorst[id].find(key) == mLastWorst[id].end())) {
                     mLastWorst[id][key] = it;
                 }
                 ++it;
                 continue;
             }

             if (key != worst || (worstPid && element.pid() != worstPid)) {
                 leading = false;
                 last.clear(&element);
                 ++it;
                 continue;
             }
             // key == worst below here
             // If worstPid set, then element->pid() == worstPid below here

             pruneRows--;
             if (pruneRows == 0) {
                 break;
             }

             kick = true;

             uint16_t len = element.msg_len();

             // do not create any leading drops
             if (leading) {
                 it = Erase(it);
             } else {
                 stats()->Drop(element.ToLogStatisticsElement());
                 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->uid() 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 || !prune_->worst_uid_enabled()) {
             break;  // the following loop will ask bad clients to skip/drop
         }
     }

     // Second prune pass.
     bool skipped_low_priority_prune = false;
     bool check_low_priority =
             id != LOG_ID_SECURITY && prune_->HasLowPriorityPruneRules() && !clearAll;
     it = GetOldest(id);
     while (pruneRows > 0 && it != logs().end()) {
         LogBufferElement& element = *it;

         if (element.log_id() != id) {
             it++;
             continue;
         }

         if (oldest && oldest->start() <= element.sequence()) {
             if (!skipped_low_priority_prune) KickReader(oldest, id, pruneRows);
             break;
         }

         if (check_low_priority && !element.dropped_count() && prune_->IsLowPriority(&element)) {
             skipped_low_priority_prune = true;
             it++;
             continue;
         }

         it = Erase(it);
         pruneRows--;
     }

     // Third prune pass.
     if (skipped_low_priority_prune && pruneRows > 0) {
         it = GetOldest(id);
         while (it != logs().end() && pruneRows > 0) {
             LogBufferElement& element = *it;

             if (element.log_id() != id) {
                 ++it;
                 continue;
             }

             if (oldest && oldest->start() <= element.sequence()) {
                 KickReader(oldest, id, pruneRows);
                 break;
             }

             it = Erase(it);
             pruneRows--;
         }
     }

     return pruneRows == 0 || it == logs().end();
 }
	/*
	* 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 ChattyLogBuffer::erase()
	//#define DEBUG_CHECK_FOR_STALE_ENTRIES

	#include "ChattyLogBuffer.h"

	#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 <limits>
	#include <unordered_map>
	#include <utility>

	#include <private/android_logger.h>

	#include "LogUtils.h"

	#ifndef __predict_false
	#define __predict_false(exp) __builtin_expect((exp) != 0, 0)
	#endif

	ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune,
	LogStatistics* stats)
	: SimpleLogBuffer(reader_list, tags, stats), prune_(prune) {}

	ChattyLogBuffer::~ChattyLogBuffer() {}

	enum match_type { DIFFERENT, SAME, SAME_LIBLOG };

	static enum match_type Identical(const LogBufferElement& elem, const LogBufferElement& last) {
	ssize_t lenl = elem.msg_len();
	if (lenl <= 0) return DIFFERENT; // value if this represents a chatty elem
	ssize_t lenr = last.msg_len();
	if (lenr <= 0) return DIFFERENT; // value if this represents a chatty elem
	if (elem.uid() != last.uid()) return DIFFERENT;
	if (elem.pid() != last.pid()) return DIFFERENT;
	if (elem.tid() != last.tid()) return DIFFERENT;

	// last is more than a minute old, stop squashing identical messages
	if (elem.realtime().nsec() > (last.realtime().nsec() + 60 * NS_PER_SEC)) return DIFFERENT;

	// Identical message
	const char* msgl = elem.msg();
	const char* msgr = last.msg();
	if (lenl == lenr) {
	if (!fastcmp<memcmp>(msgl, msgr, lenl)) return SAME;
	// liblog tagged messages (content gets summed)
	if (elem.log_id() == 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 (IsBinary(last.log_id()) &&
	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;
	}

	void ChattyLogBuffer::LogInternal(LogBufferElement&& elem) {
	// b/137093665: don't coalesce security messages.
	if (elem.log_id() == LOG_ID_SECURITY) {
	SimpleLogBuffer::LogInternal(std::move(elem));
	return;
	}
	int log_id = elem.log_id();

	// Initialize last_logged_elements_ to a copy of elem if logging the first element for a log_id.
	if (!last_logged_elements_[log_id]) {
	last_logged_elements_[log_id].emplace(elem);
	SimpleLogBuffer::LogInternal(std::move(elem));
	return;
	}

	LogBufferElement& current_last = *last_logged_elements_[log_id];
	enum match_type match = Identical(elem, current_last);

	if (match == DIFFERENT) {
	if (duplicate_elements_[log_id]) {
	// If we previously had 3+ identical messages, log the chatty message.
	if (duplicate_elements_[log_id]->dropped_count() > 0) {
	SimpleLogBuffer::LogInternal(std::move(*duplicate_elements_[log_id]));
	}
	duplicate_elements_[log_id].reset();
	// Log the saved copy of the last identical message seen.
	SimpleLogBuffer::LogInternal(std::move(current_last));
	}
	last_logged_elements_[log_id].emplace(elem);
	SimpleLogBuffer::LogInternal(std::move(elem));
	return;
	}

	// 2 identical message: set duplicate_elements_ appropriately.
	if (!duplicate_elements_[log_id]) {
	duplicate_elements_[log_id].emplace(std::move(current_last));
	last_logged_elements_[log_id].emplace(std::move(elem));
	return;
	}

	// 3+ identical LIBLOG event messages: coalesce them into last_logged_elements_.
	if (match == SAME_LIBLOG) {
	const android_log_event_int_t* current_last_event =
	reinterpret_cast<const android_log_event_int_t*>(current_last.msg());
	int64_t current_last_count = current_last_event->payload.data;
	android_log_event_int_t* elem_event =
	reinterpret_cast<android_log_event_int_t>(const_cast<char>(elem.msg()));
	int64_t elem_count = elem_event->payload.data;

	int64_t total = current_last_count + elem_count;
	if (total > std::numeric_limits<int32_t>::max()) {
	SimpleLogBuffer::LogInternal(std::move(current_last));
	last_logged_elements_[log_id].emplace(std::move(elem));
	return;
	}
	stats()->AddTotal(current_last.log_id(), current_last.msg_len());
	elem_event->payload.data = total;
	last_logged_elements_[log_id].emplace(std::move(elem));
	return;
	}

	// 3+ identical messages (not LIBLOG) messages: increase the drop count.
	uint16_t dropped_count = duplicate_elements_[log_id]->dropped_count();
	if (dropped_count == std::numeric_limits<uint16_t>::max()) {
	SimpleLogBuffer::LogInternal(std::move(*duplicate_elements_[log_id]));
	dropped_count = 0;
	}
	// We're dropping the current_last log so add its stats to the total.
	stats()->AddTotal(current_last.log_id(), current_last.msg_len());
	// Use current_last for tracking the dropped count to always use the latest timestamp.
	current_last.SetDropped(dropped_count + 1);
	duplicate_elements_[log_id].emplace(std::move(current_last));
	last_logged_elements_[log_id].emplace(std::move(elem));
	}

	LogBufferElementCollection::iterator ChattyLogBuffer::Erase(LogBufferElementCollection::iterator it,
	bool coalesce) {
	LogBufferElement& element = *it;
	log_id_t id = element.log_id();

	// 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.uid();
	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->uid() 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.pid());
	if (found != mLastWorstPidOfSystem[id].end() && it == found->second) {
	mLastWorstPidOfSystem[id].erase(found);
	}
	}

	#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
	LogBufferElementCollection::iterator bad = it;
	int key = (id == LOG_ID_EVENTS \|\| id == LOG_ID_SECURITY) ? element->GetTag() : element->uid();
	#endif

	if (coalesce) {
	stats()->Erase(element.ToLogStatisticsElement());
	} else {
	stats()->Subtract(element.ToLogStatisticsElement());
	}

	it = SimpleLogBuffer::Erase(it);

	#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES
	log_id_for_each(i) {
	for (auto b : mLastWorst[i]) {
	if (bad == b.second) {
	LOG(ERROR) << StringPrintf("stale mLastWorst[%d] key=%d mykey=%d", i, b.first, key);
	}
	}
	for (auto b : mLastWorstPidOfSystem[i]) {
	if (bad == b.second) {
	LOG(ERROR) << StringPrintf("stale mLastWorstPidOfSystem[%d] pid=%d", i, b.first);
	}
	}
	}
	#endif
	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 LogBufferElementLast {
	typedef std::unordered_map<uint64_t, LogBufferElement*> LogBufferElementMap;
	LogBufferElementMap map;

	public:
	bool coalesce(LogBufferElement* element, uint16_t dropped) {
	uint64_t key = LogBufferElementKey(element->uid(), element->pid(), element->tid());
	LogBufferElementMap::iterator it = map.find(key);
	if (it != map.end()) {
	LogBufferElement* found = it->second;
	uint16_t moreDropped = found->dropped_count();
	if ((dropped + moreDropped) > USHRT_MAX) {
	map.erase(it);
	} else {
	found->SetDropped(dropped + moreDropped);
	return true;
	}
	}
	return false;
	}

	void add(LogBufferElement* element) {
	uint64_t key = LogBufferElementKey(element->uid(), element->pid(), element->tid());
	map[key] = element;
	}

	void clear() { map.clear(); }

	void clear(LogBufferElement* element) {
	uint64_t current = element->realtime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC);
	for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
	LogBufferElement* mapElement = it->second;
	if (mapElement->dropped_count() >= EXPIRE_THRESHOLD &&
	current > mapElement->realtime().nsec()) {
	it = map.erase(it);
	} else {
	++it;
	}
	}
	}

	private:
	uint64_t LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) {
	return uint64_t(uid) << 32 \| uint64_t(pid) << 16 \| uint64_t(tid);
	}
	};

	// 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 pass prunes elements that match 3 possible rules:
	// 1) A high priority prune rule, for example ~100/20, which indicates elements from UID 100 and PID
	// 20 should be pruned in this first pass.
	// 2) The default chatty pruning rule, ~!. This rule sums the total size spent on log messages for
	// each UID this log buffer. If the highest sum consumes more than 12.5% of the log buffer, then
	// these elements from that UID are pruned.
	// 3) The default AID_SYSTEM pruning rule, ~1000/!. This rule is a special case to 2), if
	// AID_SYSTEM is the top consumer of the log buffer, then this rule sums the total size spent on
	// log messages for each PID in AID_SYSTEM in this log buffer and prunes elements from the PID
	// with the highest sum.
	// This pass reevaluates the sums for rules 2) and 3) for every log message pruned. It creates
	// 'chatty' entries for the elements that it prunes and merges related chatty entries together. It
	// completes when one of three conditions have been met:
	// 1) The requested element count has been pruned.
	// 2) There are no elements that match any of these rules.
	// 3) A reader is referencing the oldest element that would match these rules.
	//
	// The second pass prunes elements starting from the beginning of the log. It skips elements that
	// match any low priority prune rules. It completes when one of three conditions have been met:
	// 1) The requested element count has been pruned.
	// 2) All elements except those mwatching low priority prune rules have been pruned.
	// 3) A reader is referencing the oldest element that would match these rules.
	//
	// The final pass only happens if there are any low priority prune rules and if the first two passes
	// were unable to prune the requested number of elements. It prunes elements all starting from the
	// beginning of the log, regardless of if they match any low priority prune rules.
	//
	// If the requested number of logs was unable to be pruned, KickReader() is called to mitigate the
	// situation before the next call to Prune() and the function returns false. Otherwise, if the
	// requested number of logs or all logs present in the buffer are pruned, in the case of Clear(),
	// it returns true.
	bool ChattyLogBuffer::Prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
	LogReaderThread* oldest = nullptr;
	bool clearAll = pruneRows == ULONG_MAX;

	// Region locked?
	for (const auto& reader_thread : reader_list()->reader_threads()) {
	if (!reader_thread->IsWatching(id)) {
	continue;
	}
	if (!oldest \|\| oldest->start() > reader_thread->start() \|\|
	(oldest->start() == reader_thread->start() &&
	reader_thread->deadline().time_since_epoch().count() != 0)) {
	oldest = reader_thread.get();
	}
	}

	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 = GetOldest(id);
	while (it != logs().end()) {
	LogBufferElement& element = *it;

	if (element.log_id() != id \|\| element.uid() != caller_uid) {
	++it;
	continue;
	}

	if (oldest && oldest->start() <= element.sequence()) {
	KickReader(oldest, id, pruneRows);
	return false;
	}

	it = Erase(it);
	if (--pruneRows == 0) {
	return true;
	}
	}
	return true;
	}

	// First prune pass.
	bool check_high_priority = id != LOG_ID_SECURITY && prune_->HasHighPriorityPruneRules();
	while (!clearAll && (pruneRows > 0)) {
	// recalculate the worst offender on every batched pass
	int worst = -1; // not valid for uid() or getKey()
	size_t worst_sizes = 0;
	size_t second_worst_sizes = 0;
	pid_t worstPid = 0; // POSIX guarantees PID != 0

	if (worstUidEnabledForLogid(id) && prune_->worst_uid_enabled()) {
	// Calculate threshold as 12.5% of available storage
	size_t threshold = max_size(id) / 8;

	if (id == LOG_ID_EVENTS \|\| id == LOG_ID_SECURITY) {
	stats()->WorstTwoTags(threshold, &worst, &worst_sizes, &second_worst_sizes);
	// per-pid filter for AID_SYSTEM sources is too complex
	} else {
	stats()->WorstTwoUids(id, threshold, &worst, &worst_sizes, &second_worst_sizes);

	if (worst == AID_SYSTEM && prune_->worst_pid_of_system_enabled()) {
	stats()->WorstTwoSystemPids(id, worst_sizes, &worstPid, &second_worst_sizes);
	}
	}
	}

	// skip if we have neither a worst UID or high priority prune rules
	if (worst == -1 && !check_high_priority) {
	break;
	}

	bool kick = false;
	bool leading = true; // true if starting from the oldest log entry, false if starting from
	// a specific chatty entry.
	// 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 != logs().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 != logs().end()) {
	leading = false;
	it = found->second;
	}
	}
	}
	if (leading) {
	it = GetOldest(id);
	}
	static const log_time too_old{EXPIRE_HOUR_THRESHOLD * 60 * 60, 0};
	LogBufferElementCollection::iterator lastt;
	lastt = logs().end();
	--lastt;
	LogBufferElementLast last;
	while (it != logs().end()) {
	LogBufferElement& element = *it;

	if (oldest && oldest->start() <= element.sequence()) {
	// Do not let chatty eliding trigger any reader mitigation
	break;
	}

	if (element.log_id() != id) {
	++it;
	continue;
	}
	// below this point element->log_id() == id

	uint16_t dropped = element.dropped_count();

	// 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.uid();

	if (check_high_priority && prune_->IsHighPriority(&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.msg_len();
	}
	continue;
	}

	if (element.realtime() < (lastt->realtime() - too_old) \|\|
	element.realtime() > lastt->realtime()) {
	break;
	}

	if (dropped) {
	last.add(&element);
	if (worstPid && ((!gc && element.pid() == worstPid) \|\|
	mLastWorstPidOfSystem[id].find(element.pid()) ==
	mLastWorstPidOfSystem[id].end())) {
	// element->uid() 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.pid()] = it;
	}
	if ((!gc && !worstPid && (key == worst)) \|\|
	(mLastWorst[id].find(key) == mLastWorst[id].end())) {
	mLastWorst[id][key] = it;
	}
	++it;
	continue;
	}

	if (key != worst \|\| (worstPid && element.pid() != worstPid)) {
	leading = false;
	last.clear(&element);
	++it;
	continue;
	}
	// key == worst below here
	// If worstPid set, then element->pid() == worstPid below here

	pruneRows--;
	if (pruneRows == 0) {
	break;
	}

	kick = true;

	uint16_t len = element.msg_len();

	// do not create any leading drops
	if (leading) {
	it = Erase(it);
	} else {
	stats()->Drop(element.ToLogStatisticsElement());
	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->uid() 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 \|\| !prune_->worst_uid_enabled()) {
	break; // the following loop will ask bad clients to skip/drop
	}
	}

	// Second prune pass.
	bool skipped_low_priority_prune = false;
	bool check_low_priority =
	id != LOG_ID_SECURITY && prune_->HasLowPriorityPruneRules() && !clearAll;
	it = GetOldest(id);
	while (pruneRows > 0 && it != logs().end()) {
	LogBufferElement& element = *it;

	if (element.log_id() != id) {
	it++;
	continue;
	}

	if (oldest && oldest->start() <= element.sequence()) {
	if (!skipped_low_priority_prune) KickReader(oldest, id, pruneRows);
	break;
	}

	if (check_low_priority && !element.dropped_count() && prune_->IsLowPriority(&element)) {
	skipped_low_priority_prune = true;
	it++;
	continue;
	}

	it = Erase(it);
	pruneRows--;
	}

	// Third prune pass.
	if (skipped_low_priority_prune && pruneRows > 0) {
	it = GetOldest(id);
	while (it != logs().end() && pruneRows > 0) {
	LogBufferElement& element = *it;

	if (element.log_id() != id) {
	++it;
	continue;
	}

	if (oldest && oldest->start() <= element.sequence()) {
	KickReader(oldest, id, pruneRows);
	break;
	}

	it = Erase(it);
	pruneRows--;
	}
	}

	return pruneRows == 0 \|\| it == logs().end();
	}