ACPR/android_system_core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Merge changes If6e29418,I6d90838e,Ie488f8ac

Browse source 
* changes:
  logd: create SimpleLogBuffer and implement ChattyLogBuffer in terms of it
  logd: separate Chatty only vs generic LogBufferTests
  logd: move current sequence from LogBufferElement to LogBuffer
This commit is contained in:
Tom Cherry 2020-05-26 15:19:44 +00:00 • committed by Gerrit Code Review
commit f8f95a41f4
14 changed files with 802 additions and 613 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
logd/Android.bp
View file

@ -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",
],

363
logd/ChattyLogBuffer.cpp
View file

@ -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<const android_event_header_t*>(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, &current_last);
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]->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<int32_t>::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<uint16_t>::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<FlushToResult(const LogBufferElement* element)>& 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;
}

41
logd/ChattyLogBuffer.h
View file

@ -35,13 +35,12 @@
#include "LogTags.h"
#include "LogWhiteBlackList.h"
#include "LogWriter.h"
#include "SimpleLogBuffer.h"
#include "rwlock.h"
typedef std::list<LogBufferElement> 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<uid_t, LogBufferElementCollection::iterator> LogBufferIteratorMap;
LogBufferIteratorMap mLastWorst[LOG_ID_MAX] GUARDED_BY(lock_);
@ -49,48 +48,20 @@ class ChattyLogBuffer : public LogBuffer {
typedef std::unordered_map<pid_t, LogBufferElementCollection::iterator> 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<FlushToResult(const LogBufferElement* element)>& 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<LogBufferElementCollection::iterator> oldest_[LOG_ID_MAX];
RwLock lock_;
// This always contains a copy of the last message logged, for deduplication.
std::optional<LogBufferElement> last_logged_elements_[LOG_ID_MAX] GUARDED_BY(lock_);

202
logd/ChattyLogBufferTest.cpp Normal file
View file

@ -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<LogMessage> 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<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
std::vector<LogMessage> 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<LogMessage> log_messages = {
make_message(sec++, "test_tag", "normal"),
};
size_t expired_per_chatty_message = std::numeric_limits<uint16_t>::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<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
std::vector<LogMessage> 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<char*>(&liblog_event), sizeof(liblog_event)),
false};
};
// LIBLOG_LOG_TAG
std::vector<LogMessage> 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<int32_t>::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<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
std::vector<LogMessage> 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<int32_t>::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"));

2
logd/LogBuffer.h
View file

@ -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;
};

6
logd/LogBufferElement.cpp
View file

@ -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),

8
logd/LogBufferElement.h
View file

@ -16,7 +16,6 @@
#pragma once
#include <stdatomic.h>
#include <stdint.h>
#include <stdlib.h>
#include <sys/types.h>
@ -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;
}

264
logd/LogBufferTest.cpp
View file

@ -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 <unistd.h>
@ -25,14 +25,8 @@
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <gtest/gtest.h>
#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<std::string> CompareLoggerEntries(const logger_entry& expected,
const logger_entry& result, bool ignore_len) {
static std::vector<std::string> CompareLoggerEntries(const logger_entry& expected,
const logger_entry& result, bool ignore_len) {
std::vector<std::string> errors;
if (!ignore_len && expected.len != result.len) {
errors.emplace_back(
@ -106,7 +93,7 @@ std::vector<std::string> 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<LogMessage>& expected,
EXPECT_EQ(0U, num_errors);
}
class TestWriter : public LogWriter {
public:
TestWriter(std::vector<LogMessage>* 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<LogMessage>* 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<LogMessage>* 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<LogMessage>* messages) {
for (auto& [entry, message, _] : *messages) {
entry.hdr_size = sizeof(logger_entry);
entry.len = message.size();
}
}
void LogMessages(const std::vector<LogMessage>& messages) {
for (auto& [entry, message, _] : messages) {
log_buffer_->Log(static_cast<log_id_t>(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<LogBuffer> log_buffer_;
};
TEST_F(LogBufferTest, smoke) {
TEST_P(LogBufferTest, smoke) {
std::vector<LogMessage> 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<LogMessage> 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<LogMessage> 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<LogMessage> 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<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
std::vector<LogMessage> 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<LogMessage> log_messages = {
make_message(sec++, "test_tag", "normal"),
};
size_t expired_per_chatty_message = std::numeric_limits<uint16_t>::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<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
std::vector<LogMessage> 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<char*>(&liblog_event), sizeof(liblog_event)),
false};
};
// LIBLOG_LOG_TAG
std::vector<LogMessage> 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<int32_t>::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<LogMessage> read_log_messages;
std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, nullptr));
log_buffer_->FlushTo(test_writer.get(), 1, nullptr, nullptr);
std::vector<LogMessage> 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<int32_t>::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(LogBufferTests, LogBufferTest, testing::Values("chatty", "simple"));

89
logd/LogBufferTest.h Normal file
View file

@ -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 <string>
#include <vector>
#include <gtest/gtest.h>
#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<LogMessage>& expected,
const std::vector<LogMessage>& result);
// Sets hdr_size and len parameters appropriately.
void FixupMessages(std::vector<LogMessage>* messages);
class TestWriter : public LogWriter {
public:
TestWriter(std::vector<LogMessage>* 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<LogMessage>* msgs_;
bool* released_;
};
class LogBufferTest : public testing::TestWithParam<std::string> {
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<LogMessage>& messages) {
for (auto& [entry, message, _] : messages) {
log_buffer_->Log(static_cast<log_id_t>(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<LogBuffer> log_buffer_;
};

2
logd/LogReader.cpp
View file

@ -200,7 +200,7 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
if (nonBlock) {
return false;
}
sequence = LogBufferElement::getCurrentSequence();
sequence = log_buffer_->sequence();
}
}

6
logd/LogTags.h
View file

@ -14,13 +14,13 @@
* limitations under the License.
*/
#ifndef _LOGD_LOG_TAGS_H__
#define _LOGD_LOG_TAGS_H__
#pragma once
#include <string>
#include <unordered_map>
#include <unordered_set>
#include <private/android_filesystem_config.h>
#include <utils/RWLock.h>
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__

337
logd/SimpleLogBuffer.cpp Normal file
View file

@ -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<LogBufferElement>::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<const android_event_header_t*>(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<FlushToResult(const LogBufferElement* element)>& filter) {
auto shared_lock = SharedLock{lock_};
std::list<LogBufferElement>::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<LogBufferElement>::iterator SimpleLogBuffer::Erase(
std::list<LogBufferElement>::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);
}
}

82
logd/SimpleLogBuffer.h Normal file
View file

@ -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 <atomic>
#include <list>
#include <mutex>
#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<FlushToResult(const LogBufferElement* element)>& 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<LogBufferElement>::iterator GetOldest(log_id_t log_id) REQUIRES(lock_);
std::list<LogBufferElement>::iterator Erase(std::list<LogBufferElement>::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<LogBufferElement>& 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<uint64_t> sequence_ = 1;
unsigned long max_size_[LOG_ID_MAX] GUARDED_BY(lock_);
std::list<LogBufferElement> 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<std::list<LogBufferElement>::iterator> oldest_[LOG_ID_MAX] GUARDED_BY(lock_);
};

11
logd/main.cpp
View file

@ -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.