diff --git a/logd/Android.bp b/logd/Android.bp index 5e591d9a0..1f6ab3467 100644 --- a/logd/Android.bp +++ b/logd/Android.bp @@ -54,6 +54,7 @@ cc_library_static { "LogStatistics.cpp", "LogWhiteBlackList.cpp", "LogTags.cpp", + "SimpleLogBuffer.cpp", ], logtags: ["event.logtags"], @@ -128,6 +129,7 @@ cc_defaults { ] + event_flag, srcs: [ + "ChattyLogBufferTest.cpp", "logd_test.cpp", "LogBufferTest.cpp", ], diff --git a/logd/ChattyLogBuffer.cpp b/logd/ChattyLogBuffer.cpp index fd2c23691..0ba602596 100644 --- a/logd/ChattyLogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -40,47 +40,15 @@ #define __predict_false(exp) __builtin_expect((exp) != 0, 0) #endif -// Default -#define log_buffer_size(id) mMaxSize[id] - -void ChattyLogBuffer::Init() { - log_id_for_each(i) { - if (SetSize(i, __android_logger_get_buffer_size(i))) { - SetSize(i, LOG_BUFFER_MIN_SIZE); - } - } - // Release any sleeping reader threads to dump their current content. - auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; - for (const auto& reader_thread : reader_list_->reader_threads()) { - reader_thread->triggerReader_Locked(); - } -} - ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, LogStatistics* stats) - : reader_list_(reader_list), tags_(tags), prune_(prune), stats_(stats) { - Init(); -} + : SimpleLogBuffer(reader_list, tags, stats), prune_(prune) {} ChattyLogBuffer::~ChattyLogBuffer() {} -LogBufferElementCollection::iterator ChattyLogBuffer::GetOldest(log_id_t log_id) { - auto it = mLogElements.begin(); - if (oldest_[log_id]) { - it = *oldest_[log_id]; - } - while (it != mLogElements.end() && it->getLogId() != log_id) { - it++; - } - if (it != mLogElements.end()) { - oldest_[log_id] = it; - } - return it; -} - enum match_type { DIFFERENT, SAME, SAME_LIBLOG }; -static enum match_type identical(LogBufferElement* elem, LogBufferElement* last) { +static enum match_type Identical(LogBufferElement* elem, LogBufferElement* last) { // is it mostly identical? // if (!elem) return DIFFERENT; ssize_t lenl = elem->getMsgLen(); @@ -135,88 +103,44 @@ static enum match_type identical(LogBufferElement* elem, LogBufferElement* last) return SAME; } -bool ChattyLogBuffer::ShouldLog(log_id_t log_id, const char* msg, uint16_t len) { - if (log_id == LOG_ID_SECURITY) { - return true; - } - - 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) { - if (len < sizeof(android_event_header_t)) { - return false; - } - int32_t numeric_tag = reinterpret_cast(msg)->tag; - tag = tags_->tagToName(numeric_tag); - if (tag) { - tag_len = strlen(tag); - } - } else { - prio = *msg; - tag = msg + 1; - tag_len = strnlen(tag, len - 1); - } - return __android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE); -} - -int ChattyLogBuffer::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; - } - - if (!ShouldLog(log_id, msg, len)) { - // Log traffic received to total - stats_->AddTotal(log_id, len); - return -EACCES; - } - - // 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(log_id, realtime, uid, pid, tid, msg, len); - +void ChattyLogBuffer::LogInternal(LogBufferElement&& elem) { // b/137093665: don't coalesce security messages. - if (log_id == LOG_ID_SECURITY) { - auto lock = std::lock_guard{lock_}; - Log(std::move(elem)); - return len; + if (elem.getLogId() == LOG_ID_SECURITY) { + SimpleLogBuffer::LogInternal(std::move(elem)); + return; } + int log_id = elem.getLogId(); - auto lock = std::lock_guard{lock_}; // 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); - Log(std::move(elem)); - return len; + SimpleLogBuffer::LogInternal(std::move(elem)); + return; } LogBufferElement& current_last = *last_logged_elements_[log_id]; - enum match_type match = identical(&elem, ¤t_last); + enum match_type match = Identical(&elem, ¤t_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]->getDropped() > 0) { - Log(std::move(*duplicate_elements_[log_id])); + SimpleLogBuffer::LogInternal(std::move(*duplicate_elements_[log_id])); } duplicate_elements_[log_id].reset(); // Log the saved copy of the last identical message seen. - Log(std::move(current_last)); + SimpleLogBuffer::LogInternal(std::move(current_last)); } last_logged_elements_[log_id].emplace(elem); - Log(std::move(elem)); - return len; + 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 len; + return; } // 3+ identical LIBLOG event messages: coalesce them into last_logged_elements_. @@ -230,47 +154,31 @@ int ChattyLogBuffer::Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pi int64_t total = current_last_count + elem_count; if (total > std::numeric_limits::max()) { - Log(std::move(current_last)); + SimpleLogBuffer::LogInternal(std::move(current_last)); last_logged_elements_[log_id].emplace(std::move(elem)); - return len; + return; } - stats_->AddTotal(current_last.getLogId(), current_last.getMsgLen()); + stats()->AddTotal(current_last.getLogId(), current_last.getMsgLen()); elem_event->payload.data = total; last_logged_elements_[log_id].emplace(std::move(elem)); - return len; + return; } // 3+ identical messages (not LIBLOG) messages: increase the drop count. uint16_t dropped_count = duplicate_elements_[log_id]->getDropped(); if (dropped_count == std::numeric_limits::max()) { - Log(std::move(*duplicate_elements_[log_id])); + 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.getLogId(), current_last.getMsgLen()); + stats()->AddTotal(current_last.getLogId(), current_last.getMsgLen()); // 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)); - return len; } -void ChattyLogBuffer::Log(LogBufferElement&& elem) { - log_id_t log_id = elem.getLogId(); - mLogElements.push_back(std::move(elem)); - stats_->Add(&mLogElements.back()); - maybePrune(log_id); - reader_list_->NotifyNewLog(1 << log_id); -} - -void ChattyLogBuffer::maybePrune(log_id_t id) { - unsigned long prune_rows; - if (stats_->ShouldPrune(id, log_buffer_size(id), &prune_rows)) { - prune(id, prune_rows); - } -} - -LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementCollection::iterator it, +LogBufferElementCollection::iterator ChattyLogBuffer::Erase(LogBufferElementCollection::iterator it, bool coalesce) { LogBufferElement& element = *it; log_id_t id = element.getLogId(); @@ -297,9 +205,6 @@ LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementColl } } - bool setLast[LOG_ID_MAX]; - bool doSetLast = false; - log_id_for_each(i) { doSetLast |= setLast[i] = oldest_[i] && it == *oldest_[i]; } #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES LogBufferElementCollection::iterator bad = it; int key = @@ -307,25 +212,13 @@ LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementColl #endif if (coalesce) { - stats_->Erase(&element); + stats()->Erase(&element); } else { - stats_->Subtract(&element); + stats()->Subtract(&element); } - it = mLogElements.erase(it); + it = SimpleLogBuffer::Erase(it); - if (doSetLast) { - log_id_for_each(i) { - if (setLast[i]) { - if (__predict_false(it == mLogElements.end())) { - oldest_[i] = std::nullopt; - } else { - oldest_[i] = it; // Store the next iterator even if it does not correspond to - // the same log_id, as a starting point for GetOldest(). - } - } - } - } #ifdef DEBUG_CHECK_FOR_STALE_ENTRIES log_id_for_each(i) { for (auto b : mLastWorst[i]) { @@ -393,27 +286,6 @@ class LogBufferElementLast { } }; -// If the selected reader is blocking our pruning progress, decide on -// what kind of mitigation is necessary to unblock the situation. -void ChattyLogBuffer::kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows) { - if (stats_->Sizes(id) > (2 * log_buffer_size(id))) { // +100% - // A misbehaving or slow reader has its connection - // dropped if we hit too much memory pressure. - android::prdebug("Kicking blocked reader, %s, from ChattyLogBuffer::kickMe()\n", - me->name().c_str()); - me->release_Locked(); - } else if (me->deadline().time_since_epoch().count() != 0) { - // Allow a blocked WRAP deadline reader to trigger and start reporting the log data. - me->triggerReader_Locked(); - } else { - // tell slow reader to skip entries to catch up - android::prdebug( - "Skipping %lu entries from slow reader, %s, from ChattyLogBuffer::kickMe()\n", - pruneRows, me->name().c_str()); - 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 @@ -459,15 +331,15 @@ void ChattyLogBuffer::kickMe(LogReaderThread* me, log_id_t id, unsigned long pru // 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. // -bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { +bool ChattyLogBuffer::Prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { LogReaderThread* oldest = nullptr; bool busy = false; bool clearAll = pruneRows == ULONG_MAX; - auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; + auto reader_threads_lock = std::lock_guard{reader_list()->reader_threads_lock()}; // Region locked? - for (const auto& reader_thread : reader_list_->reader_threads()) { + for (const auto& reader_thread : reader_list()->reader_threads()) { if (!reader_thread->IsWatching(id)) { continue; } @@ -484,7 +356,7 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u // Only here if clear all request from non system source, so chatty // filter logistics is not required. it = GetOldest(id); - while (it != mLogElements.end()) { + while (it != logs().end()) { LogBufferElement& element = *it; if (element.getLogId() != id || element.getUid() != caller_uid) { @@ -494,11 +366,11 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (oldest && oldest->start() <= element.getSequence()) { busy = true; - kickMe(oldest, id, pruneRows); + KickReader(oldest, id, pruneRows); break; } - it = erase(it); + it = Erase(it); if (--pruneRows == 0) { break; } @@ -517,16 +389,16 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (worstUidEnabledForLogid(id) && prune_->worstUidEnabled()) { // Calculate threshold as 12.5% of available storage - size_t threshold = log_buffer_size(id) / 8; + 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); + 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); + stats()->WorstTwoUids(id, threshold, &worst, &worst_sizes, &second_worst_sizes); if (worst == AID_SYSTEM && prune_->worstPidOfSystemEnabled()) { - stats_->WorstTwoSystemPids(id, worst_sizes, &worstPid, &second_worst_sizes); + stats()->WorstTwoSystemPids(id, worst_sizes, &worstPid, &second_worst_sizes); } } } @@ -547,7 +419,7 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u 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()) { + if (found != mLastWorst[id].end() && found->second != logs().end()) { leading = false; it = found->second; } @@ -556,8 +428,7 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u // 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()) { + if (found != mLastWorstPidOfSystem[id].end() && found->second != logs().end()) { leading = false; it = found->second; } @@ -568,10 +439,10 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u } static const log_time too_old{EXPIRE_HOUR_THRESHOLD * 60 * 60, 0}; LogBufferElementCollection::iterator lastt; - lastt = mLogElements.end(); + lastt = logs().end(); --lastt; LogBufferElementLast last; - while (it != mLogElements.end()) { + while (it != logs().end()) { LogBufferElement& element = *it; if (oldest && oldest->start() <= element.getSequence()) { @@ -590,12 +461,12 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u // remove any leading drops if (leading && dropped) { - it = erase(it); + it = Erase(it); continue; } if (dropped && last.coalesce(&element, dropped)) { - it = erase(it, true); + it = Erase(it, true); continue; } @@ -604,7 +475,7 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (hasBlacklist && prune_->naughty(&element)) { last.clear(&element); - it = erase(it); + it = Erase(it); if (dropped) { continue; } @@ -667,12 +538,12 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u // do not create any leading drops if (leading) { - it = erase(it); + it = Erase(it); } else { - stats_->Drop(&element); + stats()->Drop(&element); element.setDropped(1); if (last.coalesce(&element, 1)) { - it = erase(it, true); + it = Erase(it, true); } else { last.add(&element); if (worstPid && (!gc || mLastWorstPidOfSystem[id].find(worstPid) == @@ -703,7 +574,7 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u bool whitelist = false; bool hasWhitelist = (id != LOG_ID_SECURITY) && prune_->nice() && !clearAll; it = GetOldest(id); - while ((pruneRows > 0) && (it != mLogElements.end())) { + while ((pruneRows > 0) && (it != logs().end())) { LogBufferElement& element = *it; if (element.getLogId() != id) { @@ -713,7 +584,7 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (oldest && oldest->start() <= element.getSequence()) { busy = true; - if (!whitelist) kickMe(oldest, id, pruneRows); + if (!whitelist) KickReader(oldest, id, pruneRows); break; } @@ -724,14 +595,14 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u continue; } - it = erase(it); + it = Erase(it); pruneRows--; } // Do not save the whitelist if we are reader range limited if (whitelist && (pruneRows > 0)) { it = GetOldest(id); - while ((it != mLogElements.end()) && (pruneRows > 0)) { + while ((it != logs().end()) && (pruneRows > 0)) { LogBufferElement& element = *it; if (element.getLogId() != id) { @@ -741,146 +612,14 @@ bool ChattyLogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_u if (oldest && oldest->start() <= element.getSequence()) { busy = true; - kickMe(oldest, id, pruneRows); + KickReader(oldest, id, pruneRows); break; } - it = erase(it); + it = Erase(it); pruneRows--; } } return (pruneRows > 0) && busy; } - -// clear all rows of type "id" from the buffer. -bool ChattyLogBuffer::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. - { - auto lock = std::lock_guard{lock_}; - busy = prune(id, 1, uid); - } - // 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) { - auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; - for (const auto& reader_thread : reader_list_->reader_threads()) { - if (reader_thread->IsWatching(id)) { - android::prdebug( - "Kicking blocked reader, %s, from ChattyLogBuffer::clear()\n", - reader_thread->name().c_str()); - reader_thread->release_Locked(); - } - } - } - } - { - auto lock = std::lock_guard{lock_}; - busy = prune(id, ULONG_MAX, uid); - } - if (!busy || !--retry) { - break; - } - sleep(1); // Let reader(s) catch up after notification - } - return busy; -} - -// set the total space allocated to "id" -int ChattyLogBuffer::SetSize(log_id_t id, unsigned long size) { - // Reasonable limits ... - if (!__android_logger_valid_buffer_size(size)) { - return -1; - } - auto lock = std::lock_guard{lock_}; - log_buffer_size(id) = size; - return 0; -} - -// get the total space allocated to "id" -unsigned long ChattyLogBuffer::GetSize(log_id_t id) { - auto shared_lock = SharedLock{lock_}; - size_t retval = log_buffer_size(id); - return retval; -} - -uint64_t ChattyLogBuffer::FlushTo( - LogWriter* writer, uint64_t start, pid_t* lastTid, - const std::function& filter) { - LogBufferElementCollection::iterator it; - uid_t uid = writer->uid(); - - auto shared_lock = SharedLock{lock_}; - - if (start <= 1) { - // client wants to start from the beginning - it = mLogElements.begin(); - } else { - // Client wants to start from some specified time. Chances are - // we are better off starting from the end of the time sorted list. - for (it = mLogElements.end(); it != mLogElements.begin(); - /* do nothing */) { - --it; - if (it->getSequence() <= start) { - it++; - break; - } - } - } - - uint64_t curr = start; - - for (; it != mLogElements.end(); ++it) { - LogBufferElement& element = *it; - - if (!writer->privileged() && element.getUid() != uid) { - continue; - } - - if (!writer->can_read_security_logs() && element.getLogId() == LOG_ID_SECURITY) { - continue; - } - - // NB: calling out to another object with wrlock() held (safe) - if (filter) { - FlushToResult ret = filter(&element); - if (ret == FlushToResult::kSkip) { - continue; - } - if (ret == FlushToResult::kStop) { - 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(); - } - - shared_lock.unlock(); - - curr = element.getSequence(); - // range locking in LastLogTimes looks after us - if (!element.FlushTo(writer, stats_, sameTid)) { - return FLUSH_ERROR; - } - - shared_lock.lock_shared(); - } - return curr; -} diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h index 08c4bffe4..6f6027213 100644 --- a/logd/ChattyLogBuffer.h +++ b/logd/ChattyLogBuffer.h @@ -35,13 +35,12 @@ #include "LogTags.h" #include "LogWhiteBlackList.h" #include "LogWriter.h" +#include "SimpleLogBuffer.h" #include "rwlock.h" typedef std::list LogBufferElementCollection; -class ChattyLogBuffer : public LogBuffer { - LogBufferElementCollection mLogElements GUARDED_BY(lock_); - +class ChattyLogBuffer : public SimpleLogBuffer { // watermark of any worst/chatty uid processing typedef std::unordered_map LogBufferIteratorMap; LogBufferIteratorMap mLastWorst[LOG_ID_MAX] GUARDED_BY(lock_); @@ -49,48 +48,20 @@ class ChattyLogBuffer : public LogBuffer { typedef std::unordered_map LogBufferPidIteratorMap; LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX] GUARDED_BY(lock_); - unsigned long mMaxSize[LOG_ID_MAX] GUARDED_BY(lock_); - public: ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, LogStatistics* stats); ~ChattyLogBuffer(); - void Init() override; - int Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char* msg, - uint16_t len) override; - uint64_t FlushTo( - LogWriter* writer, uint64_t start, pid_t* lastTid, - const std::function& filter) override; - - bool Clear(log_id_t id, uid_t uid = AID_ROOT) override; - unsigned long GetSize(log_id_t id) override; - int SetSize(log_id_t id, unsigned long size) override; + protected: + bool Prune(log_id_t id, unsigned long pruneRows, uid_t uid) REQUIRES(lock_) override; + void LogInternal(LogBufferElement&& elem) REQUIRES(lock_) override; private: - void maybePrune(log_id_t id) REQUIRES(lock_); - void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows) REQUIRES_SHARED(lock_); - - bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT) REQUIRES(lock_); - LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it, + LogBufferElementCollection::iterator Erase(LogBufferElementCollection::iterator it, bool coalesce = false) REQUIRES(lock_); - bool ShouldLog(log_id_t log_id, const char* msg, uint16_t len); - void Log(LogBufferElement&& elem) REQUIRES(lock_); - // Returns an iterator to the oldest element for a given log type, or mLogElements.end() if - // there are no logs for the given log type. Requires mLogElementsLock to be held. - LogBufferElementCollection::iterator GetOldest(log_id_t log_id) REQUIRES(lock_); - - LogReaderList* reader_list_; - LogTags* tags_; PruneList* prune_; - LogStatistics* stats_; - - // Keeps track of the iterator to the oldest log message of a given log type, as an - // optimization when pruning logs. Use GetOldest() to retrieve. - std::optional oldest_[LOG_ID_MAX]; - - RwLock lock_; // This always contains a copy of the last message logged, for deduplication. std::optional last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_); diff --git a/logd/ChattyLogBufferTest.cpp b/logd/ChattyLogBufferTest.cpp new file mode 100644 index 000000000..2e0c9470a --- /dev/null +++ b/logd/ChattyLogBufferTest.cpp @@ -0,0 +1,202 @@ +/* + * Copyright (C) 2020 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. + */ + +#include "LogBufferTest.h" + +class ChattyLogBufferTest : public LogBufferTest {}; + +TEST_P(ChattyLogBufferTest, deduplication_simple) { + auto make_message = [&](uint32_t sec, const char* tag, const char* msg, + bool regex = false) -> LogMessage { + logger_entry entry = { + .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0}; + std::string message; + message.push_back(ANDROID_LOG_INFO); + message.append(tag); + message.push_back('\0'); + message.append(msg); + message.push_back('\0'); + return {entry, message, regex}; + }; + + // clang-format off + std::vector log_messages = { + make_message(0, "test_tag", "duplicate"), + make_message(1, "test_tag", "duplicate"), + make_message(2, "test_tag", "not_same"), + make_message(3, "test_tag", "duplicate"), + make_message(4, "test_tag", "duplicate"), + make_message(5, "test_tag", "not_same"), + make_message(6, "test_tag", "duplicate"), + make_message(7, "test_tag", "duplicate"), + make_message(8, "test_tag", "duplicate"), + make_message(9, "test_tag", "not_same"), + make_message(10, "test_tag", "duplicate"), + make_message(11, "test_tag", "duplicate"), + make_message(12, "test_tag", "duplicate"), + make_message(13, "test_tag", "duplicate"), + make_message(14, "test_tag", "duplicate"), + make_message(15, "test_tag", "duplicate"), + make_message(16, "test_tag", "not_same"), + make_message(100, "test_tag", "duplicate"), + make_message(200, "test_tag", "duplicate"), + make_message(300, "test_tag", "duplicate"), + }; + // clang-format on + FixupMessages(&log_messages); + LogMessages(log_messages); + + std::vector read_log_messages; + std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); + log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); + + std::vector expected_log_messages = { + make_message(0, "test_tag", "duplicate"), + make_message(1, "test_tag", "duplicate"), + make_message(2, "test_tag", "not_same"), + make_message(3, "test_tag", "duplicate"), + make_message(4, "test_tag", "duplicate"), + make_message(5, "test_tag", "not_same"), + // 3 duplicate logs together print the first, a 1 count chatty message, then the last. + make_message(6, "test_tag", "duplicate"), + make_message(7, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ expire 1 line", true), + make_message(8, "test_tag", "duplicate"), + make_message(9, "test_tag", "not_same"), + // 6 duplicate logs together print the first, a 4 count chatty message, then the last. + make_message(10, "test_tag", "duplicate"), + make_message(14, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ expire 4 lines", true), + make_message(15, "test_tag", "duplicate"), + make_message(16, "test_tag", "not_same"), + // duplicate logs > 1 minute apart are not deduplicated. + make_message(100, "test_tag", "duplicate"), + make_message(200, "test_tag", "duplicate"), + make_message(300, "test_tag", "duplicate"), + }; + FixupMessages(&expected_log_messages); + CompareLogMessages(expected_log_messages, read_log_messages); +}; + +TEST_P(ChattyLogBufferTest, deduplication_overflow) { + auto make_message = [&](uint32_t sec, const char* tag, const char* msg, + bool regex = false) -> LogMessage { + logger_entry entry = { + .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0}; + std::string message; + message.push_back(ANDROID_LOG_INFO); + message.append(tag); + message.push_back('\0'); + message.append(msg); + message.push_back('\0'); + return {entry, message, regex}; + }; + + uint32_t sec = 0; + std::vector log_messages = { + make_message(sec++, "test_tag", "normal"), + }; + size_t expired_per_chatty_message = std::numeric_limits::max(); + for (size_t i = 0; i < expired_per_chatty_message + 3; ++i) { + log_messages.emplace_back(make_message(sec++, "test_tag", "duplicate")); + } + log_messages.emplace_back(make_message(sec++, "test_tag", "normal")); + FixupMessages(&log_messages); + LogMessages(log_messages); + + std::vector read_log_messages; + std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); + log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); + + std::vector expected_log_messages = { + make_message(0, "test_tag", "normal"), + make_message(1, "test_tag", "duplicate"), + make_message(expired_per_chatty_message + 1, "chatty", + "uid=0\\([^\\)]+\\) [^ ]+ expire 65535 lines", true), + make_message(expired_per_chatty_message + 2, "chatty", + "uid=0\\([^\\)]+\\) [^ ]+ expire 1 line", true), + make_message(expired_per_chatty_message + 3, "test_tag", "duplicate"), + make_message(expired_per_chatty_message + 4, "test_tag", "normal"), + }; + FixupMessages(&expected_log_messages); + CompareLogMessages(expected_log_messages, read_log_messages); +} + +TEST_P(ChattyLogBufferTest, deduplication_liblog) { + auto make_message = [&](uint32_t sec, int32_t tag, int32_t count) -> LogMessage { + logger_entry entry = { + .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_EVENTS, .uid = 0}; + android_log_event_int_t liblog_event = { + .header.tag = tag, .payload.type = EVENT_TYPE_INT, .payload.data = count}; + return {entry, std::string(reinterpret_cast(&liblog_event), sizeof(liblog_event)), + false}; + }; + + // LIBLOG_LOG_TAG + std::vector log_messages = { + make_message(0, 1234, 1), + make_message(1, LIBLOG_LOG_TAG, 3), + make_message(2, 1234, 2), + make_message(3, LIBLOG_LOG_TAG, 3), + make_message(4, LIBLOG_LOG_TAG, 4), + make_message(5, 1234, 223), + make_message(6, LIBLOG_LOG_TAG, 2), + make_message(7, LIBLOG_LOG_TAG, 3), + make_message(8, LIBLOG_LOG_TAG, 4), + make_message(9, 1234, 227), + make_message(10, LIBLOG_LOG_TAG, 1), + make_message(11, LIBLOG_LOG_TAG, 3), + make_message(12, LIBLOG_LOG_TAG, 2), + make_message(13, LIBLOG_LOG_TAG, 3), + make_message(14, LIBLOG_LOG_TAG, 5), + make_message(15, 1234, 227), + make_message(16, LIBLOG_LOG_TAG, 2), + make_message(17, LIBLOG_LOG_TAG, std::numeric_limits::max()), + make_message(18, LIBLOG_LOG_TAG, 3), + make_message(19, LIBLOG_LOG_TAG, 5), + make_message(20, 1234, 227), + }; + FixupMessages(&log_messages); + LogMessages(log_messages); + + std::vector read_log_messages; + std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); + log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); + + std::vector expected_log_messages = { + make_message(0, 1234, 1), + make_message(1, LIBLOG_LOG_TAG, 3), + make_message(2, 1234, 2), + make_message(3, LIBLOG_LOG_TAG, 3), + make_message(4, LIBLOG_LOG_TAG, 4), + make_message(5, 1234, 223), + // More than 2 liblog events (3 here), sum their value into the third message. + make_message(6, LIBLOG_LOG_TAG, 2), + make_message(8, LIBLOG_LOG_TAG, 7), + make_message(9, 1234, 227), + // More than 2 liblog events (5 here), sum their value into the third message. + make_message(10, LIBLOG_LOG_TAG, 1), + make_message(14, LIBLOG_LOG_TAG, 13), + make_message(15, 1234, 227), + // int32_t max is the max for a chatty message, beyond that we must use new messages. + make_message(16, LIBLOG_LOG_TAG, 2), + make_message(17, LIBLOG_LOG_TAG, std::numeric_limits::max()), + make_message(19, LIBLOG_LOG_TAG, 8), + make_message(20, 1234, 227), + }; + FixupMessages(&expected_log_messages); + CompareLogMessages(expected_log_messages, read_log_messages); +}; + +INSTANTIATE_TEST_CASE_P(ChattyLogBufferTests, ChattyLogBufferTest, testing::Values("chatty")); \ No newline at end of file diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 6274051ec..7f1e1284e 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -53,4 +53,6 @@ class LogBuffer { virtual bool Clear(log_id_t id, uid_t uid) = 0; virtual unsigned long GetSize(log_id_t id) = 0; virtual int SetSize(log_id_t id, unsigned long size) = 0; + + virtual uint64_t sequence() const = 0; }; \ No newline at end of file diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index 3bcf11deb..c6dbda86d 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -30,14 +30,12 @@ #include "LogStatistics.h" #include "LogUtils.h" -atomic_int_fast64_t LogBufferElement::sequence(1); - LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, - pid_t tid, const char* msg, uint16_t len) + pid_t tid, uint64_t sequence, const char* msg, uint16_t len) : mUid(uid), mPid(pid), mTid(tid), - mSequence(sequence.fetch_add(1, memory_order_relaxed)), + mSequence(sequence), mRealTime(realtime), mMsgLen(len), mLogId(log_id), diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index a777970d4..35252f9c9 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -16,7 +16,6 @@ #pragma once -#include #include #include #include @@ -51,14 +50,12 @@ class __attribute__((packed)) LogBufferElement { const uint8_t mLogId; bool mDropped; - static atomic_int_fast64_t sequence; - // assumption: mDropped == true size_t populateDroppedMessage(char*& buffer, LogStatistics* parent, bool lastSame); public: - LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, - pid_t tid, const char* msg, uint16_t len); + LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, + uint64_t sequence, const char* msg, uint16_t len); LogBufferElement(const LogBufferElement& elem); LogBufferElement(LogBufferElement&& elem); ~LogBufferElement(); @@ -91,7 +88,6 @@ class __attribute__((packed)) LogBufferElement { return mDropped ? nullptr : mMsg; } uint64_t getSequence() const { return mSequence; } - static uint64_t getCurrentSequence() { return sequence.load(memory_order_relaxed); } log_time getRealTime(void) const { return mRealTime; } diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp index b52ce8f63..334d57b60 100644 --- a/logd/LogBufferTest.cpp +++ b/logd/LogBufferTest.cpp @@ -1,5 +1,5 @@ /* - * Copyright (C) 2014 The Android Open Source Project + * Copyright (C) 2020 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. @@ -14,7 +14,7 @@ * limitations under the License. */ -#include "LogBuffer.h" +#include "LogBufferTest.h" #include @@ -25,14 +25,8 @@ #include #include -#include -#include "ChattyLogBuffer.h" -#include "LogReaderList.h" #include "LogReaderThread.h" -#include "LogStatistics.h" -#include "LogTags.h" -#include "LogWhiteBlackList.h" #include "LogWriter.h" using android::base::Join; @@ -61,15 +55,8 @@ char* android::uidToName(uid_t) { return nullptr; } -struct LogMessage { - logger_entry entry; - std::string message; - bool regex_compare = false; // Only set for expected messages, when true 'message' should be - // interpretted as a regex. -}; - -std::vector CompareLoggerEntries(const logger_entry& expected, - const logger_entry& result, bool ignore_len) { +static std::vector CompareLoggerEntries(const logger_entry& expected, + const logger_entry& result, bool ignore_len) { std::vector errors; if (!ignore_len && expected.len != result.len) { errors.emplace_back( @@ -106,7 +93,7 @@ std::vector CompareLoggerEntries(const logger_entry& expected, return errors; } -std::string MakePrintable(std::string in) { +static std::string MakePrintable(std::string in) { if (in.size() > 80) { in = in.substr(0, 80) + "..."; } @@ -121,7 +108,7 @@ std::string MakePrintable(std::string in) { return result; } -std::string CompareMessages(const std::string& expected, const std::string& result) { +static std::string CompareMessages(const std::string& expected, const std::string& result) { if (expected == result) { return {}; } @@ -145,7 +132,7 @@ std::string CompareMessages(const std::string& expected, const std::string& resu result_short.c_str()); } -std::string CompareRegexMessages(const std::string& expected, const std::string& result) { +static std::string CompareRegexMessages(const std::string& expected, const std::string& result) { auto expected_pieces = Split(expected, std::string("\0", 1)); auto result_pieces = Split(result, std::string("\0", 1)); @@ -197,54 +184,14 @@ void CompareLogMessages(const std::vector& expected, EXPECT_EQ(0U, num_errors); } -class TestWriter : public LogWriter { - public: - TestWriter(std::vector* msgs, bool* released) - : LogWriter(0, true, true), msgs_(msgs), released_(released) {} - bool Write(const logger_entry& entry, const char* message) override { - msgs_->emplace_back(LogMessage{entry, std::string(message, entry.len), false}); - return true; +void FixupMessages(std::vector* messages) { + for (auto& [entry, message, _] : *messages) { + entry.hdr_size = sizeof(logger_entry); + entry.len = message.size(); } +} - void Release() { - if (released_) *released_ = true; - } - - std::string name() const override { return "test_writer"; } - - private: - std::vector* msgs_; - bool* released_; -}; - -class LogBufferTest : public testing::Test { - protected: - void SetUp() override { - log_buffer_.reset(new ChattyLogBuffer(&reader_list_, &tags_, &prune_, &stats_)); - } - - void FixupMessages(std::vector* messages) { - for (auto& [entry, message, _] : *messages) { - entry.hdr_size = sizeof(logger_entry); - entry.len = message.size(); - } - } - - void LogMessages(const std::vector& messages) { - for (auto& [entry, message, _] : messages) { - log_buffer_->Log(static_cast(entry.lid), log_time(entry.sec, entry.nsec), - entry.uid, entry.pid, entry.tid, message.c_str(), message.size()); - } - } - - LogReaderList reader_list_; - LogTags tags_; - PruneList prune_; - LogStatistics stats_{false}; - std::unique_ptr log_buffer_; -}; - -TEST_F(LogBufferTest, smoke) { +TEST_P(LogBufferTest, smoke) { std::vector log_messages = { {{ .pid = 1, @@ -266,7 +213,7 @@ TEST_F(LogBufferTest, smoke) { CompareLogMessages(log_messages, read_log_messages); } -TEST_F(LogBufferTest, smoke_with_reader_thread) { +TEST_P(LogBufferTest, smoke_with_reader_thread) { std::vector log_messages = { {{.pid = 1, .tid = 2, .sec = 10000, .nsec = 20001, .lid = LOG_ID_MAIN, .uid = 0}, "first"}, @@ -358,7 +305,7 @@ LogMessage GenerateRandomLogMessage(uint32_t sec) { return {entry, message}; } -TEST_F(LogBufferTest, random_messages) { +TEST_P(LogBufferTest, random_messages) { srand(1); std::vector log_messages; for (size_t i = 0; i < 1000; ++i) { @@ -388,183 +335,4 @@ TEST_F(LogBufferTest, random_messages) { CompareLogMessages(log_messages, read_log_messages); } -TEST_F(LogBufferTest, deduplication_simple) { - auto make_message = [&](uint32_t sec, const char* tag, const char* msg, - bool regex = false) -> LogMessage { - logger_entry entry = { - .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0}; - std::string message; - message.push_back(ANDROID_LOG_INFO); - message.append(tag); - message.push_back('\0'); - message.append(msg); - message.push_back('\0'); - return {entry, message, regex}; - }; - - // clang-format off - std::vector log_messages = { - make_message(0, "test_tag", "duplicate"), - make_message(1, "test_tag", "duplicate"), - make_message(2, "test_tag", "not_same"), - make_message(3, "test_tag", "duplicate"), - make_message(4, "test_tag", "duplicate"), - make_message(5, "test_tag", "not_same"), - make_message(6, "test_tag", "duplicate"), - make_message(7, "test_tag", "duplicate"), - make_message(8, "test_tag", "duplicate"), - make_message(9, "test_tag", "not_same"), - make_message(10, "test_tag", "duplicate"), - make_message(11, "test_tag", "duplicate"), - make_message(12, "test_tag", "duplicate"), - make_message(13, "test_tag", "duplicate"), - make_message(14, "test_tag", "duplicate"), - make_message(15, "test_tag", "duplicate"), - make_message(16, "test_tag", "not_same"), - make_message(100, "test_tag", "duplicate"), - make_message(200, "test_tag", "duplicate"), - make_message(300, "test_tag", "duplicate"), - }; - // clang-format on - FixupMessages(&log_messages); - LogMessages(log_messages); - - std::vector read_log_messages; - std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); - log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); - - std::vector expected_log_messages = { - make_message(0, "test_tag", "duplicate"), - make_message(1, "test_tag", "duplicate"), - make_message(2, "test_tag", "not_same"), - make_message(3, "test_tag", "duplicate"), - make_message(4, "test_tag", "duplicate"), - make_message(5, "test_tag", "not_same"), - // 3 duplicate logs together print the first, a 1 count chatty message, then the last. - make_message(6, "test_tag", "duplicate"), - make_message(7, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ expire 1 line", true), - make_message(8, "test_tag", "duplicate"), - make_message(9, "test_tag", "not_same"), - // 6 duplicate logs together print the first, a 4 count chatty message, then the last. - make_message(10, "test_tag", "duplicate"), - make_message(14, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ expire 4 lines", true), - make_message(15, "test_tag", "duplicate"), - make_message(16, "test_tag", "not_same"), - // duplicate logs > 1 minute apart are not deduplicated. - make_message(100, "test_tag", "duplicate"), - make_message(200, "test_tag", "duplicate"), - make_message(300, "test_tag", "duplicate"), - }; - FixupMessages(&expected_log_messages); - CompareLogMessages(expected_log_messages, read_log_messages); -}; - -TEST_F(LogBufferTest, deduplication_overflow) { - auto make_message = [&](uint32_t sec, const char* tag, const char* msg, - bool regex = false) -> LogMessage { - logger_entry entry = { - .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0}; - std::string message; - message.push_back(ANDROID_LOG_INFO); - message.append(tag); - message.push_back('\0'); - message.append(msg); - message.push_back('\0'); - return {entry, message, regex}; - }; - - uint32_t sec = 0; - std::vector log_messages = { - make_message(sec++, "test_tag", "normal"), - }; - size_t expired_per_chatty_message = std::numeric_limits::max(); - for (size_t i = 0; i < expired_per_chatty_message + 3; ++i) { - log_messages.emplace_back(make_message(sec++, "test_tag", "duplicate")); - } - log_messages.emplace_back(make_message(sec++, "test_tag", "normal")); - FixupMessages(&log_messages); - LogMessages(log_messages); - - std::vector read_log_messages; - std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); - log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); - - std::vector expected_log_messages = { - make_message(0, "test_tag", "normal"), - make_message(1, "test_tag", "duplicate"), - make_message(expired_per_chatty_message + 1, "chatty", - "uid=0\\([^\\)]+\\) [^ ]+ expire 65535 lines", true), - make_message(expired_per_chatty_message + 2, "chatty", - "uid=0\\([^\\)]+\\) [^ ]+ expire 1 line", true), - make_message(expired_per_chatty_message + 3, "test_tag", "duplicate"), - make_message(expired_per_chatty_message + 4, "test_tag", "normal"), - }; - FixupMessages(&expected_log_messages); - CompareLogMessages(expected_log_messages, read_log_messages); -} - -TEST_F(LogBufferTest, deduplication_liblog) { - auto make_message = [&](uint32_t sec, int32_t tag, int32_t count) -> LogMessage { - logger_entry entry = { - .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_EVENTS, .uid = 0}; - android_log_event_int_t liblog_event = { - .header.tag = tag, .payload.type = EVENT_TYPE_INT, .payload.data = count}; - return {entry, std::string(reinterpret_cast(&liblog_event), sizeof(liblog_event)), - false}; - }; - - // LIBLOG_LOG_TAG - std::vector log_messages = { - make_message(0, 1234, 1), - make_message(1, LIBLOG_LOG_TAG, 3), - make_message(2, 1234, 2), - make_message(3, LIBLOG_LOG_TAG, 3), - make_message(4, LIBLOG_LOG_TAG, 4), - make_message(5, 1234, 223), - make_message(6, LIBLOG_LOG_TAG, 2), - make_message(7, LIBLOG_LOG_TAG, 3), - make_message(8, LIBLOG_LOG_TAG, 4), - make_message(9, 1234, 227), - make_message(10, LIBLOG_LOG_TAG, 1), - make_message(11, LIBLOG_LOG_TAG, 3), - make_message(12, LIBLOG_LOG_TAG, 2), - make_message(13, LIBLOG_LOG_TAG, 3), - make_message(14, LIBLOG_LOG_TAG, 5), - make_message(15, 1234, 227), - make_message(16, LIBLOG_LOG_TAG, 2), - make_message(17, LIBLOG_LOG_TAG, std::numeric_limits::max()), - make_message(18, LIBLOG_LOG_TAG, 3), - make_message(19, LIBLOG_LOG_TAG, 5), - make_message(20, 1234, 227), - }; - FixupMessages(&log_messages); - LogMessages(log_messages); - - std::vector read_log_messages; - std::unique_ptr test_writer(new TestWriter(&read_log_messages, nullptr)); - log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr); - - std::vector expected_log_messages = { - make_message(0, 1234, 1), - make_message(1, LIBLOG_LOG_TAG, 3), - make_message(2, 1234, 2), - make_message(3, LIBLOG_LOG_TAG, 3), - make_message(4, LIBLOG_LOG_TAG, 4), - make_message(5, 1234, 223), - // More than 2 liblog events (3 here), sum their value into the third message. - make_message(6, LIBLOG_LOG_TAG, 2), - make_message(8, LIBLOG_LOG_TAG, 7), - make_message(9, 1234, 227), - // More than 2 liblog events (5 here), sum their value into the third message. - make_message(10, LIBLOG_LOG_TAG, 1), - make_message(14, LIBLOG_LOG_TAG, 13), - make_message(15, 1234, 227), - // int32_t max is the max for a chatty message, beyond that we must use new messages. - make_message(16, LIBLOG_LOG_TAG, 2), - make_message(17, LIBLOG_LOG_TAG, std::numeric_limits::max()), - make_message(19, LIBLOG_LOG_TAG, 8), - make_message(20, 1234, 227), - }; - FixupMessages(&expected_log_messages); - CompareLogMessages(expected_log_messages, read_log_messages); -}; \ No newline at end of file +INSTANTIATE_TEST_CASE_P(LogBufferTests, LogBufferTest, testing::Values("chatty", "simple")); diff --git a/logd/LogBufferTest.h b/logd/LogBufferTest.h new file mode 100644 index 000000000..1659f1270 --- /dev/null +++ b/logd/LogBufferTest.h @@ -0,0 +1,89 @@ +/* + * Copyright (C) 2020 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. + */ + +#pragma once + +#include +#include + +#include + +#include "ChattyLogBuffer.h" +#include "LogReaderList.h" +#include "LogStatistics.h" +#include "LogTags.h" +#include "LogWhiteBlackList.h" +#include "SimpleLogBuffer.h" + +struct LogMessage { + logger_entry entry; + std::string message; + bool regex_compare = false; // Only set for expected messages, when true 'message' should be + // interpretted as a regex. +}; + +// Compares the ordered list of expected and result, causing a test failure with appropriate +// information on failure. +void CompareLogMessages(const std::vector& expected, + const std::vector& result); +// Sets hdr_size and len parameters appropriately. +void FixupMessages(std::vector* messages); + +class TestWriter : public LogWriter { + public: + TestWriter(std::vector* msgs, bool* released) + : LogWriter(0, true, true), msgs_(msgs), released_(released) {} + bool Write(const logger_entry& entry, const char* message) override { + msgs_->emplace_back(LogMessage{entry, std::string(message, entry.len), false}); + return true; + } + + void Release() { + if (released_) *released_ = true; + } + + std::string name() const override { return "test_writer"; } + + private: + std::vector* msgs_; + bool* released_; +}; + +class LogBufferTest : public testing::TestWithParam { + protected: + void SetUp() override { + if (GetParam() == "chatty") { + log_buffer_.reset(new ChattyLogBuffer(&reader_list_, &tags_, &prune_, &stats_)); + } else if (GetParam() == "simple") { + log_buffer_.reset(new SimpleLogBuffer(&reader_list_, &tags_, &stats_)); + } else { + FAIL() << "Unknown buffer type selected for test"; + } + } + + void LogMessages(const std::vector& messages) { + for (auto& [entry, message, _] : messages) { + log_buffer_->Log(static_cast(entry.lid), log_time(entry.sec, entry.nsec), + entry.uid, entry.pid, entry.tid, message.c_str(), message.size()); + } + } + + LogReaderList reader_list_; + LogTags tags_; + PruneList prune_; + LogStatistics stats_{false}; + std::unique_ptr log_buffer_; +}; diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 89562a414..234ddc75b 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -200,7 +200,7 @@ bool LogReader::onDataAvailable(SocketClient* cli) { if (nonBlock) { return false; } - sequence = LogBufferElement::getCurrentSequence(); + sequence = log_buffer_->sequence(); } } diff --git a/logd/LogTags.h b/logd/LogTags.h index e4d165a7c..cce700c26 100644 --- a/logd/LogTags.h +++ b/logd/LogTags.h @@ -14,13 +14,13 @@ * limitations under the License. */ -#ifndef _LOGD_LOG_TAGS_H__ -#define _LOGD_LOG_TAGS_H__ +#pragma once #include #include #include +#include #include class LogTags { @@ -120,5 +120,3 @@ class LogTags { std::string formatGetEventTag(uid_t uid, const char* name, const char* format); }; - -#endif // _LOGD_LOG_TAGS_H__ diff --git a/logd/SimpleLogBuffer.cpp b/logd/SimpleLogBuffer.cpp new file mode 100644 index 000000000..1c834281d --- /dev/null +++ b/logd/SimpleLogBuffer.cpp @@ -0,0 +1,337 @@ +/* + * Copyright (C) 2020 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. + */ + +#include "SimpleLogBuffer.h" + +#include "LogBufferElement.h" + +SimpleLogBuffer::SimpleLogBuffer(LogReaderList* reader_list, LogTags* tags, LogStatistics* stats) + : reader_list_(reader_list), tags_(tags), stats_(stats) { + Init(); +} + +SimpleLogBuffer::~SimpleLogBuffer() {} + +void SimpleLogBuffer::Init() { + log_id_for_each(i) { + if (SetSize(i, __android_logger_get_buffer_size(i))) { + SetSize(i, LOG_BUFFER_MIN_SIZE); + } + } + + // Release any sleeping reader threads to dump their current content. + auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; + for (const auto& reader_thread : reader_list_->reader_threads()) { + reader_thread->triggerReader_Locked(); + } +} + +std::list::iterator SimpleLogBuffer::GetOldest(log_id_t log_id) { + auto it = logs().begin(); + if (oldest_[log_id]) { + it = *oldest_[log_id]; + } + while (it != logs().end() && it->getLogId() != log_id) { + it++; + } + if (it != logs().end()) { + oldest_[log_id] = it; + } + return it; +} + +bool SimpleLogBuffer::ShouldLog(log_id_t log_id, const char* msg, uint16_t len) { + if (log_id == LOG_ID_SECURITY) { + return true; + } + + 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) { + if (len < sizeof(android_event_header_t)) { + return false; + } + int32_t numeric_tag = reinterpret_cast(msg)->tag; + tag = tags_->tagToName(numeric_tag); + if (tag) { + tag_len = strlen(tag); + } + } else { + prio = *msg; + tag = msg + 1; + tag_len = strnlen(tag, len - 1); + } + return __android_log_is_loggable_len(prio, tag, tag_len, ANDROID_LOG_VERBOSE); +} + +int SimpleLogBuffer::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; + } + + if (!ShouldLog(log_id, msg, len)) { + // Log traffic received to total + stats_->AddTotal(log_id, len); + return -EACCES; + } + + // 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; + + auto lock = std::lock_guard{lock_}; + auto sequence = sequence_.fetch_add(1, std::memory_order_relaxed); + LogInternal(LogBufferElement(log_id, realtime, uid, pid, tid, sequence, msg, len)); + return len; +} + +void SimpleLogBuffer::LogInternal(LogBufferElement&& elem) { + log_id_t log_id = elem.getLogId(); + + logs_.emplace_back(std::move(elem)); + stats_->Add(&logs_.back()); + MaybePrune(log_id); + reader_list_->NotifyNewLog(1 << log_id); +} + +uint64_t SimpleLogBuffer::FlushTo( + LogWriter* writer, uint64_t start, pid_t* last_tid, + const std::function& filter) { + auto shared_lock = SharedLock{lock_}; + + std::list::iterator it; + if (start <= 1) { + // client wants to start from the beginning + it = logs_.begin(); + } else { + // Client wants to start from some specified time. Chances are + // we are better off starting from the end of the time sorted list. + for (it = logs_.end(); it != logs_.begin(); + /* do nothing */) { + --it; + if (it->getSequence() <= start) { + it++; + break; + } + } + } + + uint64_t curr = start; + + for (; it != logs_.end(); ++it) { + LogBufferElement& element = *it; + + if (!writer->privileged() && element.getUid() != writer->uid()) { + continue; + } + + if (!writer->can_read_security_logs() && element.getLogId() == LOG_ID_SECURITY) { + continue; + } + + if (filter) { + FlushToResult ret = filter(&element); + if (ret == FlushToResult::kSkip) { + continue; + } + if (ret == FlushToResult::kStop) { + break; + } + } + + bool same_tid = false; + if (last_tid) { + same_tid = last_tid[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. + last_tid[element.getLogId()] = + (element.getDropped() && !same_tid) ? 0 : element.getTid(); + } + + shared_lock.unlock(); + + // We never prune logs equal to or newer than any LogReaderThreads' `start` value, so the + // `element` pointer is safe here without the lock + curr = element.getSequence(); + if (!element.FlushTo(writer, stats_, same_tid)) { + return FLUSH_ERROR; + } + + shared_lock.lock_shared(); + } + + return curr; +} + +// clear all rows of type "id" from the buffer. +bool SimpleLogBuffer::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. + { + auto lock = std::lock_guard{lock_}; + busy = Prune(id, 1, uid); + } + // 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) { + auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; + for (const auto& reader_thread : reader_list_->reader_threads()) { + if (reader_thread->IsWatching(id)) { + android::prdebug("Kicking blocked reader, %s, from LogBuffer::clear()\n", + reader_thread->name().c_str()); + reader_thread->release_Locked(); + } + } + } + } + { + auto lock = std::lock_guard{lock_}; + busy = Prune(id, ULONG_MAX, uid); + } + + if (!busy || !--retry) { + break; + } + sleep(1); // Let reader(s) catch up after notification + } + return busy; +} + +// get the total space allocated to "id" +unsigned long SimpleLogBuffer::GetSize(log_id_t id) { + auto lock = SharedLock{lock_}; + size_t retval = max_size_[id]; + return retval; +} + +// set the total space allocated to "id" +int SimpleLogBuffer::SetSize(log_id_t id, unsigned long size) { + // Reasonable limits ... + if (!__android_logger_valid_buffer_size(size)) { + return -1; + } + + auto lock = std::lock_guard{lock_}; + max_size_[id] = size; + return 0; +} + +void SimpleLogBuffer::MaybePrune(log_id_t id) { + unsigned long prune_rows; + if (stats_->ShouldPrune(id, max_size_[id], &prune_rows)) { + Prune(id, prune_rows, 0); + } +} + +bool SimpleLogBuffer::Prune(log_id_t id, unsigned long prune_rows, uid_t caller_uid) { + auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; + + // Don't prune logs that are newer than the point at which any reader threads are reading from. + LogReaderThread* oldest = nullptr; + 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(); + } + } + + auto it = GetOldest(id); + + while (it != logs_.end()) { + LogBufferElement& element = *it; + + if (element.getLogId() != id) { + ++it; + continue; + } + + if (caller_uid != 0 && element.getUid() != caller_uid) { + ++it; + continue; + } + + if (oldest && oldest->start() <= element.getSequence()) { + KickReader(oldest, id, prune_rows); + return true; + } + + stats_->Subtract(&element); + it = Erase(it); + if (--prune_rows == 0) { + return false; + } + } + return false; +} + +std::list::iterator SimpleLogBuffer::Erase( + std::list::iterator it) { + bool oldest_is_it[LOG_ID_MAX]; + log_id_for_each(i) { oldest_is_it[i] = oldest_[i] && it == *oldest_[i]; } + + it = logs_.erase(it); + + log_id_for_each(i) { + if (oldest_is_it[i]) { + if (__predict_false(it == logs().end())) { + oldest_[i] = std::nullopt; + } else { + oldest_[i] = it; // Store the next iterator even if it does not correspond to + // the same log_id, as a starting point for GetOldest(). + } + } + } + + return it; +} + +// If the selected reader is blocking our pruning progress, decide on +// what kind of mitigation is necessary to unblock the situation. +void SimpleLogBuffer::KickReader(LogReaderThread* reader, log_id_t id, unsigned long prune_rows) { + if (stats_->Sizes(id) > (2 * max_size_[id])) { // +100% + // A misbehaving or slow reader has its connection + // dropped if we hit too much memory pressure. + android::prdebug("Kicking blocked reader, %s, from LogBuffer::kickMe()\n", + reader->name().c_str()); + reader->release_Locked(); + } else if (reader->deadline().time_since_epoch().count() != 0) { + // Allow a blocked WRAP deadline reader to trigger and start reporting the log data. + reader->triggerReader_Locked(); + } else { + // tell slow reader to skip entries to catch up + android::prdebug("Skipping %lu entries from slow reader, %s, from LogBuffer::kickMe()\n", + prune_rows, reader->name().c_str()); + reader->triggerSkip_Locked(id, prune_rows); + } +} diff --git a/logd/SimpleLogBuffer.h b/logd/SimpleLogBuffer.h new file mode 100644 index 000000000..9a2d01ab5 --- /dev/null +++ b/logd/SimpleLogBuffer.h @@ -0,0 +1,82 @@ +/* + * Copyright (C) 2020 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. + */ + +#pragma once + +#include +#include +#include + +#include "LogBuffer.h" +#include "LogBufferElement.h" +#include "LogReaderList.h" +#include "LogStatistics.h" +#include "LogTags.h" +#include "rwlock.h" + +class SimpleLogBuffer : public LogBuffer { + public: + SimpleLogBuffer(LogReaderList* reader_list, LogTags* tags, LogStatistics* stats); + ~SimpleLogBuffer(); + void Init() override; + + int Log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char* msg, + uint16_t len) override; + uint64_t FlushTo( + LogWriter* writer, uint64_t start, pid_t* lastTid, + const std::function& filter) override; + + bool Clear(log_id_t id, uid_t uid) override; + unsigned long GetSize(log_id_t id) override; + int SetSize(log_id_t id, unsigned long size) override; + + uint64_t sequence() const override { return sequence_.load(std::memory_order_relaxed); } + + protected: + virtual bool Prune(log_id_t id, unsigned long prune_rows, uid_t uid) REQUIRES(lock_); + virtual void LogInternal(LogBufferElement&& elem) REQUIRES(lock_); + + // Returns an iterator to the oldest element for a given log type, or logs_.end() if + // there are no logs for the given log type. Requires logs_lock_ to be held. + std::list::iterator GetOldest(log_id_t log_id) REQUIRES(lock_); + std::list::iterator Erase(std::list::iterator it) + REQUIRES(lock_); + void KickReader(LogReaderThread* reader, log_id_t id, unsigned long prune_rows) + REQUIRES_SHARED(lock_); + + LogStatistics* stats() { return stats_; } + LogReaderList* reader_list() { return reader_list_; } + unsigned long max_size(log_id_t id) REQUIRES_SHARED(lock_) { return max_size_[id]; } + std::list& logs() { return logs_; } + + RwLock lock_; + + private: + bool ShouldLog(log_id_t log_id, const char* msg, uint16_t len); + void MaybePrune(log_id_t id) REQUIRES(lock_); + + LogReaderList* reader_list_; + LogTags* tags_; + LogStatistics* stats_; + + std::atomic sequence_ = 1; + + unsigned long max_size_[LOG_ID_MAX] GUARDED_BY(lock_); + std::list logs_ GUARDED_BY(lock_); + // Keeps track of the iterator to the oldest log message of a given log type, as an + // optimization when pruning logs. Use GetOldest() to retrieve. + std::optional::iterator> oldest_[LOG_ID_MAX] GUARDED_BY(lock_); +}; diff --git a/logd/main.cpp b/logd/main.cpp index 1deca7261..c2b5a1d5b 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -56,6 +56,7 @@ #include "LogStatistics.h" #include "LogTags.h" #include "LogUtils.h" +#include "SimpleLogBuffer.h" #define KMSG_PRIORITY(PRI) \ '<', '0' + LOG_MAKEPRI(LOG_DAEMON, LOG_PRI(PRI)) / 10, \ @@ -287,9 +288,13 @@ int main(int argc, char* argv[]) { // entries. LogReaderList reader_list; - // LogBuffer is the object which is responsible for holding all - // log entries. - LogBuffer* logBuf = new ChattyLogBuffer(&reader_list, &log_tags, &prune_list, &log_statistics); + // LogBuffer is the object which is responsible for holding all log entries. + LogBuffer* logBuf; + if (true) { + logBuf = new ChattyLogBuffer(&reader_list, &log_tags, &prune_list, &log_statistics); + } else { + logBuf = new SimpleLogBuffer(&reader_list, &log_tags, &log_statistics); + } // LogReader listens on /dev/socket/logdr. When a client // connects, log entries in the LogBuffer are written to the client.